From c52f955a98befec17221b9c457ece9daec384027 Mon Sep 17 00:00:00 2001 From: Dylan Myers Date: Thu, 6 Aug 2026 09:23:31 -0400 Subject: [PATCH] feat(o11y): lifecycle startup-latency metrics via new runtime weaver registry (PIPE-1066) Assisted-by: Claude Opus 4.8 --- cmd/blitz/main.go | 13 +++ embed/new.go | 5 +- internal/runtime/duration.go | 12 +++ internal/runtime/duration_test.go | 27 ++++++ internal/runtime/monitoring.go | 94 +++++++++++++++++++ internal/runtime/monitoring.md | 78 +++++++++++++++ internal/runtime/monitoring/metric.yaml | 44 +++++++++ .../runtime/monitoring/registry_manifest.yaml | 4 + internal/runtime/runtime.go | 23 ++++- internal/runtime/runtime_span_test.go | 5 +- internal/runtime/runtime_test.go | 82 ++++++++++++++-- internal/service/service.go | 7 +- 12 files changed, 378 insertions(+), 16 deletions(-) create mode 100644 internal/runtime/duration.go create mode 100644 internal/runtime/duration_test.go create mode 100644 internal/runtime/monitoring.go create mode 100644 internal/runtime/monitoring.md create mode 100644 internal/runtime/monitoring/metric.yaml create mode 100644 internal/runtime/monitoring/registry_manifest.yaml diff --git a/cmd/blitz/main.go b/cmd/blitz/main.go index f719fbe..61ee114 100644 --- a/cmd/blitz/main.go +++ b/cmd/blitz/main.go @@ -23,6 +23,7 @@ import ( "github.com/observiq/blitz/internal/config" "github.com/observiq/blitz/internal/dispatch" "github.com/observiq/blitz/internal/logging" + "github.com/observiq/blitz/internal/runtime" "github.com/observiq/blitz/internal/service" "github.com/observiq/blitz/internal/telemetry/logs" "github.com/observiq/blitz/internal/telemetry/metrics" @@ -91,6 +92,11 @@ func main() { } func run(cmd *cobra.Command, args []string) error { + // Mark process start so the blitz.startup.duration metric can measure the + // full standalone startup: config load, provider construction, output + // wiring, and bringing every generator up. + startTime := time.Now() + // Configure Viper to handle env overrides viper.SetConfigType("yaml") viper.SetEnvKeyReplacer(strings.NewReplacer(".", "_")) @@ -405,6 +411,13 @@ func run(cmd *cobra.Command, args []string) error { return err } + // Record process-level startup latency (best effort; a metric-build failure + // must not fail startup). Per-module and session startup are recorded by the + // runtime. + if lifecycleMetrics, merr := runtime.NewMetrics(tel.MeterProvider); merr == nil { + lifecycleMetrics.BlitzStartupDurationHistogram.Record(ctx, runtime.DurationMillis(time.Since(startTime))) + } + if tracker == nil { <-ctx.Done() } else if cfg.OnFinish == "idle" { diff --git a/embed/new.go b/embed/new.go index 4f6492c..2ff99f0 100644 --- a/embed/new.go +++ b/embed/new.go @@ -54,7 +54,10 @@ func (r *runner) Start(ctx context.Context, host Host) error { for i, m := range r.cfg.Modules { rtModules[i] = m } - rt := runtime.New(logger, rtModules, tel.TracerProvider) + rt, err := runtime.New(logger, rtModules, tel.TracerProvider, tel.MeterProvider) + if err != nil { + return err + } if err := rt.Start(ctx); err != nil { return err } diff --git a/internal/runtime/duration.go b/internal/runtime/duration.go new file mode 100644 index 0000000..9c29441 --- /dev/null +++ b/internal/runtime/duration.go @@ -0,0 +1,12 @@ +package runtime + +import "time" + +// DurationMillis converts a duration to fractional milliseconds for recording +// on the startup-latency histograms. It divides the nanosecond count as a +// float so a sub-millisecond value keeps its fractional part. time.Duration's +// Milliseconds() truncates to an integer, which would drop sub-millisecond +// samples to zero and understate the histogram sum. +func DurationMillis(d time.Duration) float64 { + return float64(d.Nanoseconds()) / 1e6 +} diff --git a/internal/runtime/duration_test.go b/internal/runtime/duration_test.go new file mode 100644 index 0000000..72346c1 --- /dev/null +++ b/internal/runtime/duration_test.go @@ -0,0 +1,27 @@ +package runtime_test + +import ( + "testing" + "time" + + "github.com/observiq/blitz/internal/runtime" + "github.com/stretchr/testify/require" +) + +func TestDurationMillis(t *testing.T) { + cases := []struct { + name string + in time.Duration + want float64 + }{ + {"whole milliseconds", 250 * time.Millisecond, 250}, + {"seconds scale", 2 * time.Second, 2000}, + {"sub-millisecond preserved", 500 * time.Microsecond, 0.5}, + {"zero", 0, 0}, + } + for _, tc := range cases { + t.Run(tc.name, func(t *testing.T) { + require.InDelta(t, tc.want, runtime.DurationMillis(tc.in), 1e-9) + }) + } +} diff --git a/internal/runtime/monitoring.go b/internal/runtime/monitoring.go new file mode 100644 index 0000000..1ad9c6d --- /dev/null +++ b/internal/runtime/monitoring.go @@ -0,0 +1,94 @@ +// DO NOT MODIFY: This code is autogenerated by "make generate-o11y". +// See templates/registry/go/metric.go.j2. + +//nolint:unused,revive +package runtime + +import ( + "context" + "errors" + + "go.opentelemetry.io/otel" + "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/metric" +) + +// Attribute name constants +const ( + attrModuleName = "module_name" +) + +// Constants for enum members + +// Wrapper types for metrics with required attributes + +// blitzModuleStartupDurationHistogramType wraps the blitz.module.startup.duration metric with type-safe required attributes +type blitzModuleStartupDurationHistogramType struct { + histogram metric.Float64Histogram +} + +// Record records a value for blitz.module.startup.duration with required attributes +func (m blitzModuleStartupDurationHistogramType) Record(ctx context.Context, value float64, moduleName string, opts ...metric.RecordOption) { + attrs := metric.WithAttributeSet(attribute.NewSet( + attribute.String(attrModuleName, moduleName), + )) + + if len(opts) == 0 { + m.histogram.Record(ctx, value, attrs) + } else { + allOpts := append([]metric.RecordOption{attrs}, opts...) + m.histogram.Record(ctx, value, allOpts...) + } +} + +// Metrics holds blitz's runtime self-telemetry instruments. Build one +// with NewMetrics from a caller-supplied MeterProvider so metrics can be routed +// to any provider (an embedding host's, or the process global). +type Metrics struct { + runtimeMeter metric.Meter + + // time to start a single module during session startup + BlitzModuleStartupDurationHistogram blitzModuleStartupDurationHistogramType + // time to start all modules in the session + BlitzSessionStartupDurationHistogram metric.Float64Histogram + // time from process start to the service running + BlitzStartupDurationHistogram metric.Float64Histogram +} + +// NewMetrics builds the runtime instruments from mp. A nil mp falls +// back to the process-global MeterProvider, preserving standalone behavior. +func NewMetrics(mp metric.MeterProvider) (*Metrics, error) { + if mp == nil { + mp = otel.GetMeterProvider() + } + m := &Metrics{} + var errs error + + m.runtimeMeter = mp.Meter("runtime") + + BlitzModuleStartupDurationHistogramRaw, err := m.runtimeMeter.Float64Histogram( + "blitz.module.startup.duration", + metric.WithDescription("time to start a single module during session startup"), + metric.WithUnit("ms"), + ) + errs = errors.Join(errs, err) + m.BlitzModuleStartupDurationHistogram = blitzModuleStartupDurationHistogramType{histogram: BlitzModuleStartupDurationHistogramRaw} + + BlitzSessionStartupDurationHistogramRaw, err := m.runtimeMeter.Float64Histogram( + "blitz.session.startup.duration", + metric.WithDescription("time to start all modules in the session"), + metric.WithUnit("ms"), + ) + errs = errors.Join(errs, err) + m.BlitzSessionStartupDurationHistogram = BlitzSessionStartupDurationHistogramRaw + + BlitzStartupDurationHistogramRaw, err := m.runtimeMeter.Float64Histogram( + "blitz.startup.duration", + metric.WithDescription("time from process start to the service running"), + metric.WithUnit("ms"), + ) + errs = errors.Join(errs, err) + m.BlitzStartupDurationHistogram = BlitzStartupDurationHistogramRaw + + return m, errs +} diff --git a/internal/runtime/monitoring.md b/internal/runtime/monitoring.md new file mode 100644 index 0000000..81342f1 --- /dev/null +++ b/internal/runtime/monitoring.md @@ -0,0 +1,78 @@ +# Runtime Metrics Reference + +## Quick Reference + +| Metric | Type | Unit | Description | +|--------|------|------|-------------| +| [`blitz.module.startup.duration`](#blitzmodulestartupduration) | Histogram | `ms` | time to start a single module during session startup | +| [`blitz.session.startup.duration`](#blitzsessionstartupduration) | Histogram | `ms` | time to start all modules in the session | +| [`blitz.startup.duration`](#blitzstartupduration) | Histogram | `ms` | time from process start to the service running | + +--- + +## Metrics Detail + +### blitz.module.startup.duration + +| Property | Value | +|----------|-------| +| **Type** | Histogram | +| **Unit** | `ms` | +| **Meter** | `runtime` | +| **Stability** | Stable | +| **Description** | time to start a single module during session startup | +| **Attributes** |`module_name` | + +**Attributes:** + +| Name | Type | Required | Values | +|------|------|----------|--------| +| `module_name` | string | ✓ | - | + +**Usage:** +```go +// Type-safe wrapper with required attributes +blitzModuleStartupDurationHistogram.Record(ctx, 1, moduleNameValue) +``` + +--- + +### blitz.session.startup.duration + +| Property | Value | +|----------|-------| +| **Type** | Histogram | +| **Unit** | `ms` | +| **Meter** | `runtime` | +| **Stability** | Stable | +| **Description** | time to start all modules in the session | + +**Usage:** +```go +blitzSessionStartupDurationHistogram.Record(ctx, 1) +``` + +--- + +### blitz.startup.duration + +| Property | Value | +|----------|-------| +| **Type** | Histogram | +| **Unit** | `ms` | +| **Meter** | `runtime` | +| **Stability** | Stable | +| **Description** | time from process start to the service running | + +**Usage:** +```go +blitzStartupDurationHistogram.Record(ctx, 1) +``` + +--- + + + +--- + +**Generated:** `make generate-o11y` | **Registry:** `runtime/monitoring/` | **Templates:** `weaver/templates/` \ No newline at end of file diff --git a/internal/runtime/monitoring/metric.yaml b/internal/runtime/monitoring/metric.yaml new file mode 100644 index 0000000..cc93e76 --- /dev/null +++ b/internal/runtime/monitoring/metric.yaml @@ -0,0 +1,44 @@ +# yaml-language-server: $schema=https://raw.githubusercontent.com/open-telemetry/weaver/refs/heads/main/schemas/semconv.schema.json +groups: +- id: runtime.module.startup.duration + type: metric + metric_name: "blitz.module.startup.duration" + stability: stable + brief: "time to start a single module during session startup" + instrument: histogram + unit: "ms" + annotations: + exported: true + histogram: + type: Float64Histogram + attributes: + - id: module_name + type: string + stability: stable + requirement_level: required + brief: "name of the module" + examples: ["apache-common", "json", "hostmetrics", "traces"] + +- id: runtime.session.startup.duration + type: metric + metric_name: "blitz.session.startup.duration" + stability: stable + brief: "time to start all modules in the session" + instrument: histogram + unit: "ms" + annotations: + exported: true + histogram: + type: Float64Histogram + +- id: runtime.startup.duration + type: metric + metric_name: "blitz.startup.duration" + stability: stable + brief: "time from process start to the service running" + instrument: histogram + unit: "ms" + annotations: + exported: true + histogram: + type: Float64Histogram diff --git a/internal/runtime/monitoring/registry_manifest.yaml b/internal/runtime/monitoring/registry_manifest.yaml new file mode 100644 index 0000000..289fa0d --- /dev/null +++ b/internal/runtime/monitoring/registry_manifest.yaml @@ -0,0 +1,4 @@ +name: runtime +description: Runtime Lifecycle Metrics +semconv_version: 0.1.0 +schema_base_url: https://github.com/observiq/blitz/schemas/runtime/ diff --git a/internal/runtime/runtime.go b/internal/runtime/runtime.go index 23f901e..18dfeb4 100644 --- a/internal/runtime/runtime.go +++ b/internal/runtime/runtime.go @@ -3,9 +3,11 @@ package runtime import ( "context" "fmt" + "time" "go.opentelemetry.io/otel" "go.opentelemetry.io/otel/attribute" + "go.opentelemetry.io/otel/metric" "go.opentelemetry.io/otel/trace" "go.uber.org/zap" ) @@ -47,6 +49,7 @@ type Runtime struct { logger *zap.Logger modules []Module tracer trace.Tracer + metrics *Metrics // sessionSpan and moduleSpans hold the open self-telemetry spans between // Start and Stop. Start and Stop are called once each and never @@ -56,27 +59,34 @@ type Runtime struct { moduleSpans []trace.Span } -// New returns a Runtime configured with the given logger, modules, and tracer -// provider. A nil tracerProvider falls back to the process global, so span -// emission is always safe. -func New(logger *zap.Logger, modules []Module, tracerProvider trace.TracerProvider) *Runtime { +// New returns a Runtime configured with the given logger, modules, tracer +// provider, and meter provider. A nil tracerProvider or meterProvider falls +// back to the process global, so emission is always safe. It returns an error +// only if the runtime's own metric instruments cannot be built. +func New(logger *zap.Logger, modules []Module, tracerProvider trace.TracerProvider, meterProvider metric.MeterProvider) (*Runtime, error) { if logger == nil { logger = zap.NewNop() } if tracerProvider == nil { tracerProvider = otel.GetTracerProvider() } + metrics, err := NewMetrics(meterProvider) + if err != nil { + return nil, fmt.Errorf("build runtime metrics: %w", err) + } return &Runtime{ logger: logger, modules: modules, tracer: tracerProvider.Tracer(tracerScope), - } + metrics: metrics, + }, nil } // Start begins every configured module. If any module's Start returns // an error, Start stops the modules already started (in reverse order) // and returns the failure. func (r *Runtime) Start(ctx context.Context) error { + sessionStart := time.Now() ctx, r.sessionSpan = r.tracer.Start(ctx, "blitz.session") r.moduleSpans = make([]trace.Span, 0, len(r.modules)) @@ -84,6 +94,7 @@ func (r *Runtime) Start(ctx context.Context) error { for _, m := range r.modules { mctx, mspan := r.tracer.Start(ctx, "blitz.generator.run", trace.WithAttributes(attribute.String("blitz.generator.name", m.Name()))) + moduleStart := time.Now() if err := m.Start(mctx); err != nil { mspan.End() // Roll back: stop modules already started, in reverse order. @@ -98,9 +109,11 @@ func (r *Runtime) Start(ctx context.Context) error { r.sessionSpan.End() return fmt.Errorf("start module %s: %w", m.Name(), err) } + r.metrics.BlitzModuleStartupDurationHistogram.Record(ctx, DurationMillis(time.Since(moduleStart)), m.Name()) started = append(started, m) r.moduleSpans = append(r.moduleSpans, mspan) } + r.metrics.BlitzSessionStartupDurationHistogram.Record(ctx, DurationMillis(time.Since(sessionStart))) return nil } diff --git a/internal/runtime/runtime_span_test.go b/internal/runtime/runtime_span_test.go index fc4ea53..338bd5f 100644 --- a/internal/runtime/runtime_span_test.go +++ b/internal/runtime/runtime_span_test.go @@ -23,10 +23,11 @@ func TestRuntime_emitsSessionAndGeneratorSpans(t *testing.T) { exp := tracetest.NewInMemoryExporter() tp := sdktrace.NewTracerProvider(sdktrace.WithSyncer(exp)) - rt := runtime.New(nil, []runtime.Module{ + rt, err := runtime.New(nil, []runtime.Module{ spanTestModule{n: "json"}, spanTestModule{n: "apache"}, - }, tp) + }, tp, nil) + require.NoError(t, err) require.NoError(t, rt.Start(context.Background())) require.NoError(t, rt.Stop(context.Background())) diff --git a/internal/runtime/runtime_test.go b/internal/runtime/runtime_test.go index 59bb803..d453352 100644 --- a/internal/runtime/runtime_test.go +++ b/internal/runtime/runtime_test.go @@ -7,9 +7,62 @@ import ( "testing" "github.com/observiq/blitz/internal/runtime" + "github.com/stretchr/testify/require" + "go.opentelemetry.io/otel/metric" + metricnoop "go.opentelemetry.io/otel/metric/noop" + sdkmetric "go.opentelemetry.io/otel/sdk/metric" + "go.opentelemetry.io/otel/sdk/metric/metricdata" "go.uber.org/zap/zaptest" ) +// failingMeter overrides the first instrument the runtime registry builds (a +// Float64Histogram) to error, so NewMetrics fails. +type failingMeter struct{ metric.Meter } + +func (failingMeter) Float64Histogram(string, ...metric.Float64HistogramOption) (metric.Float64Histogram, error) { + return nil, errors.New("instrument error") +} + +type failingMeterProvider struct{ metric.MeterProvider } + +func (failingMeterProvider) Meter(string, ...metric.MeterOption) metric.Meter { + return failingMeter{Meter: metricnoop.NewMeterProvider().Meter("test")} +} + +func TestRuntime_NewMetricsError(t *testing.T) { + _, err := runtime.New(nil, nil, nil, failingMeterProvider{}) + require.Error(t, err) + require.Contains(t, err.Error(), "build runtime metrics") +} + +// TestRuntime_recordsStartupLatency confirms the runtime records per-module and +// session startup-duration histograms through the injected MeterProvider. +func TestRuntime_recordsStartupLatency(t *testing.T) { + reader := sdkmetric.NewManualReader() + mp := sdkmetric.NewMeterProvider(sdkmetric.WithReader(reader)) + + rt, err := runtime.New(zaptest.NewLogger(t), + []runtime.Module{&recordingModule{name: "a"}, &recordingModule{name: "b"}}, nil, mp) + require.NoError(t, err) + require.NoError(t, rt.Start(context.Background())) + require.NoError(t, rt.Stop(context.Background())) + + var rm metricdata.ResourceMetrics + require.NoError(t, reader.Collect(context.Background(), &rm)) + units := map[string]string{} + found := map[string]bool{} + for _, sm := range rm.ScopeMetrics { + for _, m := range sm.Metrics { + found[m.Name] = true + units[m.Name] = m.Unit + } + } + require.True(t, found["blitz.module.startup.duration"], "module startup histogram") + require.True(t, found["blitz.session.startup.duration"], "session startup histogram") + require.Equal(t, "ms", units["blitz.module.startup.duration"], "module startup unit") + require.Equal(t, "ms", units["blitz.session.startup.duration"], "session startup unit") +} + type recordingModule struct { name string startCnt atomic.Int32 @@ -46,7 +99,10 @@ func TestRuntime_StartCallsEveryModuleInOrder(t *testing.T) { b := &recordingModule{name: "b", startCall: startOrder} c := &recordingModule{name: "c", startCall: startOrder} - rt := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, c}, nil) + rt, err := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, c}, nil, nil) + if err != nil { + t.Fatalf("New: %v", err) + } if err := rt.Start(context.Background()); err != nil { t.Fatalf("Start: %v", err) } @@ -67,8 +123,11 @@ func TestRuntime_StartRollsBackOnFailure(t *testing.T) { b := &recordingModule{name: "b", stopCall: stopOrder} failing := &recordingModule{name: "failing", startErr: errors.New("boom")} - rt := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, failing}, nil) - err := rt.Start(context.Background()) + rt, err := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, failing}, nil, nil) + if err != nil { + t.Fatalf("New: %v", err) + } + err = rt.Start(context.Background()) if err == nil { t.Fatal("expected error from Start") } @@ -95,7 +154,10 @@ func TestRuntime_StopCallsEveryModuleInReverseOrder(t *testing.T) { b := &recordingModule{name: "b", stopCall: stopOrder} c := &recordingModule{name: "c", stopCall: stopOrder} - rt := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, c}, nil) + rt, err := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, c}, nil, nil) + if err != nil { + t.Fatalf("New: %v", err) + } if err := rt.Start(context.Background()); err != nil { t.Fatalf("Start: %v", err) } @@ -114,11 +176,14 @@ func TestRuntime_StopContinuesOnError(t *testing.T) { b := &recordingModule{name: "b", stopErr: errors.New("b-stop-fail")} c := &recordingModule{name: "c"} - rt := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, c}, nil) + rt, err := runtime.New(zaptest.NewLogger(t), []runtime.Module{a, b, c}, nil, nil) + if err != nil { + t.Fatalf("New: %v", err) + } if err := rt.Start(context.Background()); err != nil { t.Fatalf("Start: %v", err) } - err := rt.Stop(context.Background()) + err = rt.Stop(context.Background()) if err == nil { t.Fatal("expected error from Stop") } @@ -130,7 +195,10 @@ func TestRuntime_StopContinuesOnError(t *testing.T) { } func TestRuntime_NewWithNilLoggerUsesNop(t *testing.T) { - rt := runtime.New(nil, nil, nil) + rt, err := runtime.New(nil, nil, nil, nil) + if err != nil { + t.Fatalf("New: %v", err) + } // Should not panic with empty modules. if err := rt.Start(context.Background()); err != nil { t.Errorf("Start with empty modules and nil logger: %v", err) diff --git a/internal/service/service.go b/internal/service/service.go index b5215e9..5373f8c 100644 --- a/internal/service/service.go +++ b/internal/service/service.go @@ -50,11 +50,16 @@ func New(logger *zap.Logger, generators []any, output output.Output, tel embed.T } } + rt, err := runtime.New(logger, modules, tel.TracerProvider, tel.MeterProvider) + if err != nil { + return nil, err + } + return &Service{ Logger: logger, Generators: generators, Output: output, - runtime: runtime.New(logger, modules, tel.TracerProvider), + runtime: rt, legacy: legacy, }, nil }