diff --git a/internal/ingest/metric_fidelity_test.go b/internal/ingest/metric_fidelity_test.go index 6d9a1cbb..004ebe5f 100644 --- a/internal/ingest/metric_fidelity_test.go +++ b/internal/ingest/metric_fidelity_test.go @@ -57,7 +57,7 @@ func TestMetricIngestKeepsKindTemporalityAndStart(t *testing.T) { t.Fatalf("point %d: %+v", i, got) } } - if err := store.CommitBatch(t.Context(), telemetry.BatchMetadata{ID: "ingest_series"}, nil, nil, captured); err != nil { + if err := store.CommitBatch(t.Context(), &telemetry.BatchMetadata{ID: "ingest_series"}, nil, nil, captured); err != nil { t.Fatal(err) } physical, err := parquet.ReadFile[struct { diff --git a/internal/ingest/server.go b/internal/ingest/server.go index ece89a90..51abc2bf 100644 --- a/internal/ingest/server.go +++ b/internal/ingest/server.go @@ -11,7 +11,6 @@ import ( "math" "strconv" "strings" - "time" collectorlogs "go.opentelemetry.io/proto/otlp/collector/logs/v1" collectormetrics "go.opentelemetry.io/proto/otlp/collector/metrics/v1" @@ -71,7 +70,6 @@ func (ts *traceService) Export(ctx context.Context, req *collectortrace.ExportTr func (s *Server) exportTraces(ctx context.Context, req *collectortrace.ExportTraceServiceRequest) (*collectortrace.ExportTraceServiceResponse, error) { cfg := s.cfg - now := time.Now().UnixNano() count := 0 for _, rs := range req.ResourceSpans { for _, ss := range rs.ScopeSpans { @@ -126,7 +124,6 @@ func (s *Server) exportTraces(ctx context.Context, req *collectortrace.ExportTra Flags: sp.Flags, ScopeName: scopeName, ScopeVersion: scopeVer, - IngestedAt: now, // Pre-extracted OTel semantic convention attributes. HTTPMethod: spanAttr(sp.Attributes, "http.method", "http.request.method"), HTTPStatusCode: spanAttrInt(sp.Attributes, "http.status_code", "http.response.status_code"), @@ -171,7 +168,6 @@ func (ls *logsService) Export(ctx context.Context, req *collectorlogs.ExportLogs func (s *Server) exportLogs(ctx context.Context, req *collectorlogs.ExportLogsServiceRequest) (*collectorlogs.ExportLogsServiceResponse, error) { cfg := s.cfg - now := time.Now().UnixNano() count := 0 for _, rl := range req.ResourceLogs { for _, sl := range rl.ScopeLogs { @@ -217,7 +213,6 @@ func (s *Server) exportLogs(ctx context.Context, req *collectorlogs.ExportLogsSe Attributes: attrs, ScopeName: scopeName, ScopeVersion: scopeVer, - IngestedAt: now, } batch.Logs = append(batch.Logs, row) } @@ -237,7 +232,6 @@ func (ms *metricsService) Export(ctx context.Context, req *collectormetrics.Expo func (s *Server) exportMetrics(ctx context.Context, req *collectormetrics.ExportMetricsServiceRequest) (*collectormetrics.ExportMetricsServiceResponse, error) { cfg := s.cfg - now := time.Now().UnixNano() count := 0 for _, rm := range req.ResourceMetrics { for _, sm := range rm.ScopeMetrics { @@ -296,7 +290,6 @@ func (s *Server) exportMetrics(ctx context.Context, req *collectormetrics.Export Resource: resources, ScopeName: scopeName, ScopeVersion: scopeVer, - IngestedAt: now, } row.SeriesID = telemetry.MetricSeriesID(row) batch.Metrics = append(batch.Metrics, row) @@ -328,7 +321,6 @@ func (s *Server) exportMetrics(ctx context.Context, req *collectormetrics.Export Resource: resources, ScopeName: scopeName, ScopeVersion: scopeVer, - IngestedAt: now, } row.SeriesID = telemetry.MetricSeriesID(row) batch.Metrics = append(batch.Metrics, row) @@ -366,7 +358,6 @@ func (s *Server) exportMetrics(ctx context.Context, req *collectormetrics.Export Resource: resources, ScopeName: scopeName, ScopeVersion: scopeVer, - IngestedAt: now, } row.SeriesID = telemetry.MetricSeriesID(row) batch.Metrics = append(batch.Metrics, row) @@ -408,7 +399,6 @@ func (s *Server) exportMetrics(ctx context.Context, req *collectormetrics.Export Resource: resources, ScopeName: scopeName, ScopeVersion: scopeVer, - IngestedAt: now, } row.SeriesID = telemetry.MetricSeriesID(row) batch.Metrics = append(batch.Metrics, row) @@ -436,7 +426,6 @@ func (s *Server) exportMetrics(ctx context.Context, req *collectormetrics.Export Resource: resources, ScopeName: scopeName, ScopeVersion: scopeVer, - IngestedAt: now, } row.SeriesID = telemetry.MetricSeriesID(row) batch.Metrics = append(batch.Metrics, row) diff --git a/internal/intelligence/annotations_test.go b/internal/intelligence/annotations_test.go index fe9f2b33..bf4bb08a 100644 --- a/internal/intelligence/annotations_test.go +++ b/internal/intelligence/annotations_test.go @@ -115,8 +115,8 @@ func TestDetectorAnnotationMapping(t *testing.T) { } defer duck.Close() at := time.Now().UTC().Truncate(time.Minute) - snapshot := IntelligenceSnapshot{GeneratedAt: at, Anomalies: []Anomaly{{ServiceName: "checkout", Type: AnomalyLatencyDegradation, ZScore: -4, DetectedAt: at, Description: "Slow"}, {ServiceName: "payment", Type: AnomalyVolumeChange, ZScore: 3, DetectedAt: at, Description: "Low volume"}}} - findings := detectorAnnotations(snapshot, "shop", 5*time.Minute) + snapshot := IntelligenceSnapshot{GeneratedAt: at, Anomalies: []Anomaly{{ServiceName: "checkout", Type: AnomalyLatencyDegradation, ZScore: -4, DetectedAt: at, WindowStart: at.Add(-5 * time.Minute), WindowEnd: at, Description: "Slow"}, {ServiceName: "payment", Type: AnomalyVolumeChange, ZScore: 3, DetectedAt: at, WindowStart: at.Add(-5 * time.Minute), WindowEnd: at, Description: "Low volume"}}} + findings := detectorAnnotations(snapshot, "shop") if err := duck.RecordAnomalies(t.Context(), findings, at); err != nil { t.Fatal(err) } diff --git a/internal/intelligence/detector.go b/internal/intelligence/detector.go index 64b6f8ed..57f8e367 100644 --- a/internal/intelligence/detector.go +++ b/internal/intelligence/detector.go @@ -1,6 +1,6 @@ // Package intelligence derives anomalies and log patterns from telemetry. // -// Every SQL string in this file goes through internal/query's validator, which +// Public log-pattern SQL goes through internal/query's validator, which // rejects "--" outright. A SQL comment in one of these statements therefore // fails the query at runtime, on a background goroutine, as a logged error // nobody is watching -- that is how latency detection stopped reporting for @@ -93,7 +93,14 @@ func (d *Detector) safeRunCheck(ctx context.Context) { // runCheck performs a single detection cycle func (d *Detector) runCheck(ctx context.Context) { - snapshot := d.GenerateSnapshot(ctx) + snapshot, err := d.GenerateSnapshot(ctx) + if err != nil { + slog.Error("generate detector snapshot failed", "error", err) + return + } + if previous := d.LatestSnapshot(); previous != nil && snapshot.GeneratedAt.Equal(previous.GeneratedAt) { + return + } d.publishSnapshot(snapshot) anomalyCount := len(snapshot.Anomalies) @@ -107,7 +114,7 @@ func (d *Detector) publishSnapshot(snapshot IntelligenceSnapshot) { d.mu.Lock() d.snapshot = &snapshot d.mu.Unlock() - batch := annotationBatch{detectorAnnotations(snapshot, d.duck.DefaultNamespace(), d.config.LookbackWindow), snapshot.GeneratedAt} + batch := annotationBatch{detectorAnnotations(snapshot, d.duck.DefaultNamespace()), snapshot.GeneratedAt} // Only the producer modifies the pending slot. Persistence can be blocked // while a newer cycle replaces the single pending batch. d.annotationMu.Lock() @@ -129,27 +136,50 @@ func (d *Detector) publishSnapshot(snapshot IntelligenceSnapshot) { const maxCarriedAnomalies = 10000 func (d *Detector) persistAnnotations(ctx context.Context, record func(context.Context, []annotations.Anomaly, time.Time) error) { - // A write can miss the write gate while ingest catches up on a backlog. Its - // findings are kept and written with the next batch, so a short spike seen - // during the backlog is not lost; the store merges overlapping episodes. - var carried []annotations.Anomaly + // Keep failed findings with their evaluated intervals, even when the + // watermark stalls and no new batch arrives to trigger another write. + var carried annotationBatch + var retry *time.Timer + var retryC <-chan time.Time + delay := time.Second + defer func() { + if retry != nil { + retry.Stop() + } + }() for { if ctx.Err() != nil { return } + var batch annotationBatch select { case <-ctx.Done(): return - case batch := <-d.annotationBatches: - findings := append(carried, batch.findings...) - carried = nil - if err := record(ctx, findings, batch.at); err != nil && ctx.Err() == nil { - slog.Error("persist detector annotations", "error", err, "carried", len(findings)) - if len(findings) > maxCarriedAnomalies { - findings = findings[len(findings)-maxCarriedAnomalies:] - } - carried = findings + case batch = <-d.annotationBatches: + batch.findings = append(carried.findings, batch.findings...) + case <-retryC: + batch = carried + } + if retry != nil { + retry.Stop() + } + retryC = nil + if err := record(ctx, batch.findings, batch.at); err != nil && ctx.Err() == nil { + slog.Error("persist detector annotations", "error", err, "carried", len(batch.findings)) + if len(batch.findings) > maxCarriedAnomalies { + batch.findings = batch.findings[len(batch.findings)-maxCarriedAnomalies:] } + carried = batch + if retry == nil { + retry = time.NewTimer(delay) + } else { + retry.Reset(delay) + } + retryC = retry.C + delay = min(2*delay, 30*time.Second) + } else { + carried = annotationBatch{} + delay = time.Second } } } @@ -162,12 +192,22 @@ func (d *Detector) LatestSnapshot() *IntelligenceSnapshot { } // GenerateSnapshot generates a complete intelligence snapshot -func (d *Detector) GenerateSnapshot(ctx context.Context) IntelligenceSnapshot { +func (d *Detector) GenerateSnapshot(ctx context.Context) (IntelligenceSnapshot, error) { + completed, err := d.duck.CompletedServiceRollupMinute(ctx) + if err != nil { + return IntelligenceSnapshot{}, fmt.Errorf("read detector service watermark: %w", err) + } + if previous := d.LatestSnapshot(); previous != nil && !completed.After(previous.evaluatedThrough) { + return *previous, nil + } now := time.Now() lookback := now.Add(-d.config.LookbackWindow) // Detect anomalies - anomalies := d.detectAnomalies(ctx, lookback, now) + anomalies, err := d.detectAnomalies(ctx, completed.Add(-d.config.LookbackWindow), completed) + if err != nil { + return IntelligenceSnapshot{}, err + } // Detect log patterns patterns := d.detectLogPatterns(ctx, lookback, now) @@ -179,33 +219,46 @@ func (d *Detector) GenerateSnapshot(ctx context.Context) IntelligenceSnapshot { insights := d.generateInsights(anomalies, patterns) return IntelligenceSnapshot{ - GeneratedAt: now, - Timeframe: fmt.Sprintf("last_%dm", int(d.config.LookbackWindow.Minutes())), - Insights: insights, - Patterns: patterns, - Anomalies: anomalies, - Summary: d.generateSummary(healthScore, anomalies, patterns), - HealthScore: healthScore, - } + evaluatedThrough: completed, + GeneratedAt: now, + Timeframe: fmt.Sprintf("last_%dm", int(d.config.LookbackWindow.Minutes())), + Insights: insights, + Patterns: patterns, + Anomalies: anomalies, + Summary: d.generateSummary(healthScore, anomalies, patterns), + HealthScore: healthScore, + }, nil } -// detectAnomalies detects statistical anomalies in metrics -func (d *Detector) detectAnomalies(ctx context.Context, start, end time.Time) []Anomaly { +// detectAnomalies evaluates exactly [start, end) from completed rollup minutes. +func (d *Detector) detectAnomalies(ctx context.Context, start, end time.Time) ([]Anomaly, error) { + if end.IsZero() { + return nil, nil + } var anomalies []Anomaly // 1. Error rate anomalies by service - errorAnomalies := d.detectErrorRateAnomalies(ctx, start, end) + errorAnomalies, err := d.detectErrorRateAnomalies(ctx, start, end) + if err != nil { + return nil, err + } anomalies = append(anomalies, errorAnomalies...) // 2. Latency anomalies by service - latencyAnomalies := d.detectLatencyAnomalies(ctx, start, end) + latencyAnomalies, err := d.detectLatencyAnomalies(ctx, start, end) + if err != nil { + return nil, err + } anomalies = append(anomalies, latencyAnomalies...) // 3. Volume anomalies - volumeAnomalies := d.detectVolumeAnomalies(ctx, start, end) + volumeAnomalies, err := d.detectVolumeAnomalies(ctx, start, end) + if err != nil { + return nil, err + } anomalies = append(anomalies, volumeAnomalies...) - return anomalies + return anomalies, nil } // minErrorRateStddev floors the error-rate z-score denominator at one @@ -240,11 +293,11 @@ func errorRateAnomalySQL(startNano, endNano int64, scope string) string { FROM ( SELECT service as service_name, - (COUNT(*) FILTER (WHERE status IN ('STATUS_CODE_ERROR', 'ERROR'))::DOUBLE / COUNT(*)::DOUBLE) AS bucket_rate - FROM spans - WHERE start_unix_nano >= %d AND start_unix_nano < %d + (SUM(error_rate * spans) / SUM(spans)) AS bucket_rate + FROM service_rollup + WHERE bucket >= make_timestamp_ns(%d) AND bucket < make_timestamp_ns(%d) AND spans > 0 %s - GROUP BY service, time_bucket(INTERVAL '5 minutes', start_time::TIMESTAMP_NS) + GROUP BY service, time_bucket(INTERVAL '5 minutes', bucket) ) buckets GROUP BY service_name ), @@ -256,11 +309,11 @@ func errorRateAnomalySQL(startNano, endNano int64, scope string) string { FROM ( SELECT service as service_name, - (COUNT(*) FILTER (WHERE status IN ('STATUS_CODE_ERROR', 'ERROR'))::DOUBLE / COUNT(*)::DOUBLE) AS bucket_rate - FROM spans - WHERE start_unix_nano >= %d AND start_unix_nano < %d + (SUM(error_rate * spans) / SUM(spans)) AS bucket_rate + FROM service_rollup + WHERE bucket >= make_timestamp_ns(%d) AND bucket < make_timestamp_ns(%d) AND spans > 0 %s - GROUP BY service, time_bucket(INTERVAL '5 minutes', start_time::TIMESTAMP_NS) + GROUP BY service, time_bucket(INTERVAL '5 minutes', bucket) ) buckets GROUP BY service_name ) @@ -279,7 +332,7 @@ func errorRateAnomalySQL(startNano, endNano int64, scope string) string { } // detectErrorRateAnomalies detects error rate spikes -func (d *Detector) detectErrorRateAnomalies(ctx context.Context, start, end time.Time) []Anomaly { +func (d *Detector) detectErrorRateAnomalies(ctx context.Context, start, end time.Time) ([]Anomaly, error) { startNano := start.UnixNano() endNano := end.UnixNano() namespace := d.duck.DefaultNamespace() @@ -288,20 +341,17 @@ func (d *Detector) detectErrorRateAnomalies(ctx context.Context, start, end time // Compare current error rate to baseline (previous period) sql := errorRateAnomalySQL(startNano, endNano, scope) - resp := d.duck.ExecuteSQL(ctx, query.SQLRequest{Query: sql}) - if resp.Error != "" { - if !isNoDataError(resp.Error) { - slog.Error("error rate detection failed", "error", resp.Error) - } - return nil + rows, err := d.readServiceAnomalies(ctx, sql) + if err != nil { + return nil, fmt.Errorf("error rate detection: %w", err) } var anomalies []Anomaly - for _, row := range resp.Results { - serviceName, _ := row["service_name"].(string) - currentRate, _ := row["current_rate"].(float64) - baselineRate, _ := row["baseline_rate"].(float64) - zScore, _ := row["z_score"].(float64) + for _, row := range rows { + serviceName := row.service + currentRate := row.current + baselineRate := row.baseline + zScore := row.zScore if math.Abs(zScore) >= d.config.ErrorRateThreshold { anomalies = append(anomalies, Anomaly{ @@ -312,82 +362,39 @@ func (d *Detector) detectErrorRateAnomalies(ctx context.Context, start, end time Baseline: baselineRate * 100, ZScore: zScore, DetectedAt: time.Now(), + WindowStart: start, + WindowEnd: end, Description: fmt.Sprintf("%s error rate: %.1f%% (baseline: %.1f%%, z-score: %.2f)", serviceName, currentRate*100, baselineRate*100, zScore), }) } } - return anomalies + return anomalies, nil } // detectLatencyAnomalies detects latency degradation -func (d *Detector) detectLatencyAnomalies(ctx context.Context, start, end time.Time) []Anomaly { - // The percentile below is approx_quantile, not PERCENTILE_CONT: the exact - // form is holistic and retains every value of every group on the raw - // allocator, outside anything memory_limit bounds. This runs every 60s over - // a 15-minute window. See serviceRollupP95SQL. +func (d *Detector) detectLatencyAnomalies(ctx context.Context, start, end time.Time) ([]Anomaly, error) { + // service_rollup grades served spans (with its outbound-only fallback). + // Weight minute p95 values by spans; do not recompute raw-span quantiles. startNano := start.UnixNano() endNano := end.UnixNano() namespace := d.duck.DefaultNamespace() scope := detectorScopeClause(namespace) - sql := fmt.Sprintf(` - WITH current_period AS ( - SELECT - service as service_name, - approx_quantile(duration_ms, 0.95) AS p95_latency - FROM spans - WHERE start_unix_nano >= %d AND start_unix_nano < %d - AND kind = 'SPAN_KIND_SERVER' - %s - GROUP BY service - ), - baseline_buckets AS ( - SELECT - service as service_name, - time_bucket(INTERVAL '5 minutes', start_time::TIMESTAMP_NS) AS bucket, - approx_quantile(duration_ms, 0.95) AS p95_latency - FROM spans - WHERE start_unix_nano >= %d AND start_unix_nano < %d - AND kind = 'SPAN_KIND_SERVER' - %s - GROUP BY service, bucket - ), - baseline_period AS ( - SELECT - service_name, - AVG(p95_latency) AS avg_p95, - STDDEV(p95_latency) AS p95_stddev - FROM baseline_buckets - GROUP BY service_name - ) - SELECT - c.service_name, - c.p95_latency AS current_p95, - COALESCE(b.avg_p95, 0.0) AS baseline_p95, - CASE - WHEN b.p95_stddev > 0 THEN (c.p95_latency - b.avg_p95) / b.p95_stddev - ELSE 0.0 - END AS z_score - FROM current_period c - LEFT JOIN baseline_period b ON c.service_name = b.service_name - `, startNano, endNano, scope, startNano-endNano+startNano, startNano, scope) + sql := latencyAnomalySQL(startNano, endNano, scope) - resp := d.duck.ExecuteSQL(ctx, query.SQLRequest{Query: sql}) - if resp.Error != "" { - if !isNoDataError(resp.Error) { - slog.Error("latency detection failed", "error", resp.Error) - } - return nil + rows, err := d.readServiceAnomalies(ctx, sql) + if err != nil { + return nil, fmt.Errorf("latency detection: %w", err) } var anomalies []Anomaly - for _, row := range resp.Results { - serviceName, _ := row["service_name"].(string) - currentP95, _ := row["current_p95"].(float64) - baselineP95, _ := row["baseline_p95"].(float64) - zScore, _ := row["z_score"].(float64) + for _, row := range rows { + serviceName := row.service + currentP95 := row.current + baselineP95 := row.baseline + zScore := row.zScore if zScore >= d.config.LatencyThreshold { anomalies = append(anomalies, Anomaly{ @@ -398,13 +405,15 @@ func (d *Detector) detectLatencyAnomalies(ctx context.Context, start, end time.T Baseline: baselineP95, ZScore: zScore, DetectedAt: time.Now(), + WindowStart: start, + WindowEnd: end, Description: fmt.Sprintf("%s P95 latency: %.1fms (baseline P95: %.1fms, z-score: %.2f)", serviceName, currentP95, baselineP95, zScore), }) } } - return anomalies + return anomalies, nil } // volumeAnomalySQL compares span volume in [startNano, endNano) against the @@ -426,11 +435,11 @@ func volumeAnomalySQL(startNano, endNano int64, scope string) string { FROM ( SELECT service as service_name, - COUNT(*) AS cnt - FROM spans - WHERE start_unix_nano >= %d AND start_unix_nano < %d + SUM(spans) AS cnt + FROM service_rollup + WHERE bucket >= make_timestamp_ns(%d) AND bucket < make_timestamp_ns(%d) AND spans > 0 %s - GROUP BY service, time_bucket(INTERVAL '5 minutes', start_time::TIMESTAMP_NS) + GROUP BY service, time_bucket(INTERVAL '5 minutes', bucket) ) subq GROUP BY service_name ), @@ -442,11 +451,11 @@ func volumeAnomalySQL(startNano, endNano int64, scope string) string { FROM ( SELECT service as service_name, - COUNT(*) AS cnt - FROM spans - WHERE start_unix_nano >= %d AND start_unix_nano < %d + SUM(spans) AS cnt + FROM service_rollup + WHERE bucket >= make_timestamp_ns(%d) AND bucket < make_timestamp_ns(%d) AND spans > 0 %s - GROUP BY service, time_bucket(INTERVAL '5 minutes', start_time::TIMESTAMP_NS) + GROUP BY service, time_bucket(INTERVAL '5 minutes', bucket) ) subq GROUP BY service_name ) @@ -464,7 +473,7 @@ func volumeAnomalySQL(startNano, endNano int64, scope string) string { } // detectVolumeAnomalies detects unusual traffic volume changes -func (d *Detector) detectVolumeAnomalies(ctx context.Context, start, end time.Time) []Anomaly { +func (d *Detector) detectVolumeAnomalies(ctx context.Context, start, end time.Time) ([]Anomaly, error) { startNano := start.UnixNano() endNano := end.UnixNano() namespace := d.duck.DefaultNamespace() @@ -472,20 +481,17 @@ func (d *Detector) detectVolumeAnomalies(ctx context.Context, start, end time.Ti sql := volumeAnomalySQL(startNano, endNano, scope) - resp := d.duck.ExecuteSQL(ctx, query.SQLRequest{Query: sql}) - if resp.Error != "" { - if !isNoDataError(resp.Error) { - slog.Error("volume detection failed", "error", resp.Error) - } - return nil + rows, err := d.readServiceAnomalies(ctx, sql) + if err != nil { + return nil, fmt.Errorf("volume detection: %w", err) } var anomalies []Anomaly - for _, row := range resp.Results { - serviceName, _ := row["service_name"].(string) - currentCount, _ := row["current_count"].(float64) - baselineCount, _ := row["baseline_count"].(float64) - zScore, _ := row["z_score"].(float64) + for _, row := range rows { + serviceName := row.service + currentCount := row.current + baselineCount := row.baseline + zScore := row.zScore if math.Abs(zScore) >= d.config.VolumeThreshold { anomalies = append(anomalies, Anomaly{ @@ -496,13 +502,86 @@ func (d *Detector) detectVolumeAnomalies(ctx context.Context, start, end time.Ti Baseline: baselineCount, ZScore: zScore, DetectedAt: time.Now(), + WindowStart: start, + WindowEnd: end, Description: fmt.Sprintf("%s volume: %.0f spans (baseline: %.0f, z-score: %.2f)", serviceName, currentCount, baselineCount, zScore), }) } } - return anomalies + return anomalies, nil +} + +// latencyAnomalySQL compares span-weighted minute p95 values. Baseline +// scatter remains the standard deviation of five-minute bucket values. +func latencyAnomalySQL(startNano, endNano int64, scope string) string { + return fmt.Sprintf(` + WITH current_period AS ( + SELECT + service as service_name, + SUM(p95_ms * spans) / SUM(spans) AS p95_latency + FROM service_rollup + WHERE bucket >= make_timestamp_ns(%d) AND bucket < make_timestamp_ns(%d) AND spans > 0 + %s + GROUP BY service + ), + baseline_buckets AS ( + SELECT + service as service_name, + time_bucket(INTERVAL '5 minutes', bucket) AS baseline_bucket, + SUM(p95_ms * spans) / SUM(spans) AS p95_latency + FROM service_rollup + WHERE bucket >= make_timestamp_ns(%d) AND bucket < make_timestamp_ns(%d) AND spans > 0 + %s + GROUP BY service, baseline_bucket + ), + baseline_period AS ( + SELECT + service_name, + AVG(p95_latency) AS avg_p95, + STDDEV(p95_latency) AS p95_stddev + FROM baseline_buckets + GROUP BY service_name + ) + SELECT + c.service_name, + c.p95_latency AS current_p95, + COALESCE(b.avg_p95, 0.0) AS baseline_p95, + CASE + WHEN b.p95_stddev > 0 THEN (c.p95_latency - b.avg_p95) / b.p95_stddev + ELSE 0.0 + END AS z_score + FROM current_period c + LEFT JOIN baseline_period b ON c.service_name = b.service_name + `, startNano, endNano, scope, startNano-endNano+startNano, startNano, scope) + +} + +type serviceAnomalyRow struct { + service string + current, baseline, zScore float64 +} + +// Use the same internal read path as the product's service-rollup panels. +// These fixed statements never pass through the public SQL allowlist. +func (d *Detector) readServiceAnomalies(ctx context.Context, statement string) ([]serviceAnomalyRow, error) { + ctx, cancel := context.WithTimeout(ctx, 15*time.Second) + defer cancel() + rows, err := d.duck.QueryContext(ctx, statement) + if err != nil { + return nil, err + } + defer rows.Close() + var result []serviceAnomalyRow + for rows.Next() { + var row serviceAnomalyRow + if err := rows.Scan(&row.service, &row.current, &row.baseline, &row.zScore); err != nil { + return nil, err + } + result = append(result, row) + } + return result, rows.Err() } // detectLogPatterns groups repetitive log messages @@ -680,15 +759,14 @@ func toInt(v interface{}) int { return int(toInt64(v)) } -func detectorAnnotations(snapshot IntelligenceSnapshot, namespace string, lookback time.Duration) []annotations.Anomaly { +func detectorAnnotations(snapshot IntelligenceSnapshot, namespace string) []annotations.Anomaly { findings := make([]annotations.Anomaly, 0, len(snapshot.Anomalies)) for _, a := range snapshot.Anomalies { severity := "warn" if math.Abs(a.ZScore) >= 4 { severity = "bad" } - end := a.DetectedAt.UTC().Truncate(time.Minute) - findings = append(findings, annotations.Anomaly{Namespace: namespace, Service: a.ServiceName, Kind: string(a.Type), From: end.Add(-lookback), To: end, Title: a.Description, Severity: severity}) + findings = append(findings, annotations.Anomaly{Namespace: namespace, Service: a.ServiceName, Kind: string(a.Type), From: a.WindowStart, To: a.WindowEnd, Title: a.Description, Severity: severity}) } return findings } diff --git a/internal/intelligence/detector_recovery_test.go b/internal/intelligence/detector_recovery_test.go new file mode 100644 index 00000000..f905fbff --- /dev/null +++ b/internal/intelligence/detector_recovery_test.go @@ -0,0 +1,203 @@ +package intelligence + +import ( + "context" + "database/sql" + "database/sql/driver" + "errors" + "strings" + "testing" + "time" + + "github.com/duckdb/duckdb-go/v2" + "github.com/labstack/fanout/internal/annotations" + "github.com/labstack/fanout/internal/config" + "github.com/labstack/fanout/internal/query" + "github.com/labstack/fanout/internal/query/writegate" + telemetrystore "github.com/labstack/fanout/internal/telemetry/store" +) + +// Fail just one statement while retaining native DuckDB watermark reads and +// all preceding anomaly queries, including when the third query fails. +type detectorFailureConnector struct { + driver.Connector + fail string +} + +func (c *detectorFailureConnector) Connect(ctx context.Context) (driver.Conn, error) { + conn, err := c.Connector.Connect(ctx) + if err != nil { + return nil, err + } + return detectorFailureConn{Conn: conn, connector: c}, nil +} + +type detectorFailureConn struct { + driver.Conn + connector *detectorFailureConnector +} + +func (c detectorFailureConn) QueryContext(ctx context.Context, statement string, args []driver.NamedValue) (driver.Rows, error) { + if c.connector.fail != "" && strings.Contains(statement, c.connector.fail) { + return nil, context.DeadlineExceeded + } + return c.Conn.(driver.QueryerContext).QueryContext(ctx, statement, args) +} + +func seedDetectorRecoveryRollup(t *testing.T, db *sql.DB, end time.Time) { + t.Helper() + for i, count := range []int{100, 200, 300, 3000, 3000, 3000} { + rate, p95 := 0.0, float64(i+1)*10 + if i >= 3 { + rate, p95 = .5, 1000 + } + if _, err := db.Exec(`INSERT INTO service_rollup(namespace,bucket,service,spans,served_spans,p95_ms,error_rate) VALUES ('default',?,'api',?,?,?,?)`, end.Add(time.Duration(i-6)*5*time.Minute), count, count, p95, rate); err != nil { + t.Fatal(err) + } + } + if _, err := db.Exec(`INSERT INTO rollup_state VALUES ('service_rollup_v3',?,now())`, end.Add(30*time.Second).UnixNano()); err != nil { + t.Fatal(err) + } +} + +func TestDetectorRetriesFailedQueriesAtUnchangedWatermark(t *testing.T) { + for _, statement := range []string{"AS current_rate", "AS current_p95", "AS current_count"} { + for _, withPrevious := range []bool{false, true} { + name := statement + "/startup" + if withPrevious { + name = statement + "/previous" + } + t.Run(name, func(t *testing.T) { + native, err := duckdb.NewConnector("", nil) + if err != nil { + t.Fatal(err) + } + defer native.Close() + connector := &detectorFailureConnector{Connector: native} + db := sql.OpenDB(connector) + defer db.Close() + if err := query.CreateCacheTables(db); err != nil { + t.Fatal(err) + } + end := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Hour) + seedDetectorRecoveryRollup(t, db, end) + d := NewDetector(&query.Duck{DB: db}, DefaultDetectorConfig()) + if withPrevious { + d.publishSnapshot(IntelligenceSnapshot{GeneratedAt: time.Now().Add(-time.Minute), evaluatedThrough: end.Add(-time.Minute), HealthScore: 85}) + <-d.annotationBatches + } + previous := d.LatestSnapshot() + connector.fail = statement + if _, err := d.GenerateSnapshot(t.Context()); !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("query error was not propagated: %v", err) + } + d.runCheck(t.Context()) + if d.LatestSnapshot() != previous || len(d.annotationBatches) != 0 { + t.Fatal("failed evaluation published a snapshot or queued annotations") + } + // Recover without changing the watermark or the rollup data. + connector.fail = "" + d.runCheck(t.Context()) + got := d.LatestSnapshot() + if got == nil || got == previous || !got.evaluatedThrough.Equal(end) || len(got.Anomalies) != 3 || got.HealthScore >= 100 { + t.Fatalf("recovered snapshot: %+v", got) + } + batch := <-d.annotationBatches + if len(batch.findings) != 3 { + t.Fatalf("recovered findings: %+v", batch) + } + for _, a := range batch.findings { + if !a.From.Equal(end.Add(-15*time.Minute)) || !a.To.Equal(end) { + t.Fatalf("recovered interval: %+v", a) + } + } + d.runCheck(t.Context()) + if d.LatestSnapshot() != got || len(d.annotationBatches) != 0 { + t.Fatal("successful minute was evaluated again") + } + }) + } + } +} + +func TestDetectorRetriesPersistenceAtUnchangedWatermark(t *testing.T) { + cfg := config.Config{DataDir: t.TempDir(), DuckDBMemory: "256MB", DuckDBThreads: 2, DuckDBMaxConns: 2} + repo, err := telemetrystore.Open(cfg.TelemetryDir()) + if err != nil { + t.Fatal(err) + } + defer repo.Close() + duck, err := query.NewDuck(t.Context(), cfg, repo) + if err != nil { + t.Fatal(err) + } + defer duck.Close() + end := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Hour) + seedDetectorRecoveryRollup(t, duck.DB, end) + d := NewDetector(duck, DefaultDetectorConfig()) + d.runCheck(t.Context()) + previous := d.LatestSnapshot() + unlock := duck.WriteGate().Lock(writegate.WriteRollupService) + defer func() { + if unlock != nil { + unlock() + } + }() + ctx, cancel := context.WithCancel(t.Context()) + done := make(chan struct{}) + attempts := make(chan error, 8) + go func() { + defer close(done) + attempt := 0 + d.persistAnnotations(ctx, func(ctx context.Context, findings []annotations.Anomaly, at time.Time) error { + // Exercise a real gate timeout without waiting the full 10 seconds. + attempt++ + if attempt <= 2 { + writeCtx, cancel := context.WithTimeout(ctx, 100*time.Millisecond) + defer cancel() + ctx = writeCtx + } + err := duck.RecordAnomalies(ctx, findings, at) + attempts <- err + return err + }) + }() + defer func() { cancel(); <-done }() + waitAttempt := func() error { + t.Helper() + select { + case err := <-attempts: + return err + case <-time.After(5 * time.Second): + t.Fatal("persistence did not retry without a new batch") + return nil + } + } + // Two failed writes also exercise rescheduling after a failed timer retry. + for range 2 { + if err := waitAttempt(); !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("expected gate timeout: %v", err) + } + } + d.runCheck(t.Context()) + if d.LatestSnapshot() != previous || len(d.annotationBatches) != 0 { + t.Fatal("stalled watermark queued another batch") + } + unlock() + unlock = nil + if err := waitAttempt(); err != nil { + t.Fatalf("persistence did not recover: %v", err) + } + got, err := annotations.New(duck).Read(t.Context(), annotations.Request{From: end.Add(-time.Hour), To: end.Add(time.Hour)}) + if err != nil || len(got.Anomalies) != 3 { + t.Fatalf("persisted findings: %+v, %v", got, err) + } + for _, a := range got.Anomalies { + if !a.From.Equal(end.Add(-15*time.Minute)) || !a.To.Equal(end) { + t.Fatalf("retry changed evaluated interval: %+v", a) + } + } + if d.LatestSnapshot() != previous { + t.Fatal("persistence retry changed snapshot") + } +} diff --git a/internal/intelligence/error_rate_sql_test.go b/internal/intelligence/error_rate_sql_test.go index b324343e..95e2126c 100644 --- a/internal/intelligence/error_rate_sql_test.go +++ b/internal/intelligence/error_rate_sql_test.go @@ -12,29 +12,20 @@ import ( // error percentage, so a service's whole history is one readable slice. func errorRateFixture(t *testing.T, db *sql.DB, start time.Time, services map[string][]float64) { t.Helper() - if _, err := db.Exec(`CREATE TABLE IF NOT EXISTS spans ( - service TEXT, namespace TEXT, status TEXT, start_time TIMESTAMP, start_unix_nano BIGINT - )`); err != nil { + if _, err := db.Exec(`CREATE TABLE IF NOT EXISTS service_rollup ( + service VARCHAR, namespace VARCHAR, bucket TIMESTAMP_NS, spans BIGINT, error_rate DOUBLE + )`); err != nil { t.Fatal(err) } - const perBucket = 1000 for service, rates := range services { for bucket, rate := range rates { at := start.Add(time.Duration(bucket) * 5 * time.Minute) - errors := int(math.Round(rate * perBucket)) - for i := range perBucket { - status := "STATUS_CODE_OK" - if i < errors { - status = "STATUS_CODE_ERROR" - } - ts := at.Add(time.Duration(i) * time.Millisecond) - if _, err := db.Exec(`INSERT INTO spans VALUES (?, 'default', ?, ?, ?)`, - service, status, ts, ts.UnixNano()); err != nil { - t.Fatal(err) - } + if _, err := db.Exec(`INSERT INTO service_rollup VALUES (?,'default',?,1000,?)`, service, at, rate); err != nil { + t.Fatal(err) } } } + } func errorRateScores(t *testing.T, db *sql.DB, start, end time.Time) map[string]float64 { diff --git a/internal/intelligence/parquet_test.go b/internal/intelligence/parquet_test.go index 03df6ec7..8c15dfd4 100644 --- a/internal/intelligence/parquet_test.go +++ b/internal/intelligence/parquet_test.go @@ -1,6 +1,7 @@ package intelligence import ( + "context" "fmt" "testing" "time" @@ -12,11 +13,11 @@ import ( ) // Exercise the production Parquet timestamp type, not a mutable TIMESTAMP table. -// Detector methods return nil on SQL errors, so require an actual anomaly from -// each query rather than merely accepting an empty snapshot. +// Require an actual anomaly from each query and propagate SQL errors. INTERNAL spans +// are served work too: latency detection must use the rollup definition. func TestDetectorsReadNativeParquetTimestamps(t *testing.T) { ctx := t.Context() - cfg := config.Config{DataDir: t.TempDir(), DuckDBMemory: "256MB", DuckDBThreads: 2, DuckDBMaxConns: 1} + cfg := config.Config{DataDir: t.TempDir(), DuckDBMemory: "256MB", DuckDBThreads: 2, DuckDBMaxConns: 1, RollupInterval: time.Minute} repository, err := telemetrystore.Open(cfg.TelemetryDir()) if err != nil { t.Fatal(err) @@ -42,7 +43,7 @@ func TestDetectorsReadNativeParquetTimestamps(t *testing.T) { nanos := at.Add(time.Duration(i) * time.Second).UnixNano() batch.Spans = append(batch.Spans, telemetry.Span{ Namespace: "prod", ServiceName: "checkout", TraceID: fmt.Sprintf("trace-%d-%d", bucket, i), SpanID: "span", - Kind: "SPAN_KIND_SERVER", StatusCode: status, DurationMS: latency, + Kind: "SPAN_KIND_INTERNAL", StatusCode: status, DurationMS: latency, StartUnixNanos: nanos, EndUnixNanos: nanos + int64(latency*1e6), IngestedAt: nanos, }) } @@ -54,17 +55,48 @@ func TestDetectorsReadNativeParquetTimestamps(t *testing.T) { if err := repository.Commit(ctx, batch); err != nil { t.Fatal(err) } + rollupCtx, cancel := context.WithCancel(ctx) + done := make(chan struct{}) + go func() { defer close(done); duck.RunRollups(rollupCtx) }() + until := time.Now().Add(5 * time.Second) + for { + minute, err := duck.CompletedServiceRollupMinute(ctx) + if err != nil { + t.Fatal(err) + } + if !minute.IsZero() { + break + } + if time.Now().After(until) { + t.Fatal("service rollup did not complete") + } + time.Sleep(time.Millisecond) + } + cancel() + <-done detector := NewDetector(duck, DefaultDetectorConfig()) - for name, detect := range map[string]func() []Anomaly{ - "error rate": func() []Anomaly { return detector.detectErrorRateAnomalies(ctx, start, end) }, - "latency": func() []Anomaly { return detector.detectLatencyAnomalies(ctx, start, end) }, - "volume": func() []Anomaly { return detector.detectVolumeAnomalies(ctx, start, end) }, + for name, detect := range map[string]func() ([]Anomaly, error){ + "error rate": func() ([]Anomaly, error) { + return detector.detectErrorRateAnomalies(ctx, start.Truncate(time.Minute), end.Truncate(time.Minute)) + }, + "latency": func() ([]Anomaly, error) { + return detector.detectLatencyAnomalies(ctx, start.Truncate(time.Minute), end.Truncate(time.Minute)) + }, + "volume": func() ([]Anomaly, error) { + return detector.detectVolumeAnomalies(ctx, start.Truncate(time.Minute), end.Truncate(time.Minute)) + }, } { t.Run(name, func(t *testing.T) { - anomalies := detect() + anomalies, err := detect() + if err != nil { + t.Fatal(err) + } if len(anomalies) != 1 || anomalies[0].ServiceName != "checkout" || anomalies[0].Current <= anomalies[0].Baseline { t.Fatalf("expected checkout anomaly, got %#v", anomalies) } + if !anomalies[0].WindowStart.Equal(start.Truncate(time.Minute)) || !anomalies[0].WindowEnd.Equal(end.Truncate(time.Minute)) { + t.Fatalf("evaluated bounds: %+v", anomalies[0]) + } }) } patterns := detector.detectLogPatterns(ctx, start, end) diff --git a/internal/intelligence/rollup_detector_test.go b/internal/intelligence/rollup_detector_test.go new file mode 100644 index 00000000..febfb5c2 --- /dev/null +++ b/internal/intelligence/rollup_detector_test.go @@ -0,0 +1,197 @@ +package intelligence + +import ( + "database/sql" + "math" + "testing" + "time" + + "github.com/labstack/fanout/internal/annotations" + "github.com/labstack/fanout/internal/config" + "github.com/labstack/fanout/internal/query" + telemetrystore "github.com/labstack/fanout/internal/telemetry/store" +) + +func TestServiceDetectorsWeightMinutesBySpanCount(t *testing.T) { + db, err := sql.Open("duckdb", "") + if err != nil { + t.Fatal(err) + } + defer db.Close() + if err := query.CreateCacheTables(db); err != nil { + t.Fatal(err) + } + start := time.Date(2026, 10, 1, 12, 15, 0, 0, time.UTC) + end := start.Add(15 * time.Minute) + for bucket := 0; bucket < 6; bucket++ { + at := start.Add(time.Duration(bucket-3) * 5 * time.Minute) + for _, v := range []struct { + offset int + spans int + rate, p95 float64 + }{{0, 10, .9, 100}, {1, 90, .1, 10}} { + if _, err := db.Exec(`INSERT INTO service_rollup(namespace,bucket,service,spans,served_spans,p95_ms,error_rate) VALUES ('prod',?,'api',?,?,?,?)`, at.Add(time.Duration(v.offset)*time.Minute), v.spans, v.spans, v.p95+float64(bucket), v.rate); err != nil { + t.Fatal(err) + } + } + } + for _, test := range []struct { + name, statement string + want float64 + }{ + {"errors", errorRateAnomalySQL(start.UnixNano(), end.UnixNano(), "AND namespace='prod'"), .18}, + {"latency", latencyAnomalySQL(start.UnixNano(), end.UnixNano(), "AND namespace='prod'"), 23}, + {"volume", volumeAnomalySQL(start.UnixNano(), end.UnixNano(), "AND namespace='prod'"), 100}, + } { + var service string + var current, baseline, z float64 + if err := db.QueryRow(test.statement).Scan(&service, ¤t, &baseline, &z); err != nil { + t.Fatal(err) + } + if service != "api" || math.Abs(current-test.want) > 1e-9 { + t.Fatalf("%s current=%g want=%g", test.name, current, test.want) + } + var count int + rows, err := db.Query(test.statement) + if err != nil { + t.Fatal(err) + } + for rows.Next() { + count++ + } + rows.Close() + if count != 1 { + t.Fatalf("%s services=%d", test.name, count) + } + } + rows, err := db.Query(errorRateAnomalySQL(start.UnixNano(), end.UnixNano(), "AND namespace='elsewhere'")) + if err != nil { + t.Fatal(err) + } + defer rows.Close() + if rows.Next() { + t.Fatal("namespace scope leaked") + } +} +func TestDetectorsStopBeforeTheServiceWatermarkMinute(t *testing.T) { + db, err := sql.Open("duckdb", "") + if err != nil { + t.Fatal(err) + } + defer db.Close() + if err := query.CreateCacheTables(db); err != nil { + t.Fatal(err) + } + base := time.Date(2026, 10, 1, 12, 0, 0, 0, time.UTC) + for i, rate := range []float64{0, .5, 1} { + if _, err := db.Exec(`INSERT INTO service_rollup(namespace,bucket,service,spans,served_spans,p95_ms,error_rate) VALUES ('prod',?,'api',100,100,10,?)`, base.Add(time.Duration(i)*5*time.Minute), rate); err != nil { + t.Fatal(err) + } + } + watermark := base.Add(10*time.Minute + 30*time.Second).UnixNano() + if _, err := db.Exec(`INSERT INTO rollup_state VALUES ('service_rollup_v3',?,now())`, watermark); err != nil { + t.Fatal(err) + } + cfg := DefaultDetectorConfig() + cfg.LookbackWindow = 5 * time.Minute + detector := NewDetector(&query.Duck{DB: db}, cfg) + snapshot, err := detector.GenerateSnapshot(t.Context()) + if err != nil { + t.Fatal(err) + } + anomalies := snapshot.Anomalies + if len(anomalies) != 1 || anomalies[0].Type != AnomalyErrorRateChange || anomalies[0].Current != 50 || anomalies[0].Baseline != 0 { + t.Fatalf("incomplete minute or wrong baseline: %#v", anomalies) + } + if _, err := db.Exec(`DELETE FROM rollup_state`); err != nil { + t.Fatal(err) + } + if result, err := detector.GenerateSnapshot(t.Context()); err != nil || len(result.Anomalies) != 0 { + t.Fatalf("unbuilt rollup graded: %#v, %v", result, err) + } +} + +func TestDetectorPersistsEvaluatedWindowAndSkipsStalledMinute(t *testing.T) { + cfg := config.Config{DataDir: t.TempDir(), DuckDBMemory: "256MB", DuckDBThreads: 2, DuckDBMaxConns: 2} + repo, err := telemetrystore.Open(cfg.TelemetryDir()) + if err != nil { + t.Fatal(err) + } + defer repo.Close() + duck, err := query.NewDuck(t.Context(), cfg, repo) + if err != nil { + t.Fatal(err) + } + defer duck.Close() + end := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Hour) + start := end.Add(-15 * time.Minute) + for i := -3; i < 3; i++ { + rate := 0.0 + if i >= 0 { + rate = .5 + } + if _, err := duck.DB.Exec(`INSERT INTO service_rollup(namespace,bucket,service,spans,served_spans,p95_ms,error_rate) VALUES ('default',?,'api',100,100,10,?)`, start.Add(time.Duration(i)*5*time.Minute), rate); err != nil { + t.Fatal(err) + } + } + watermark := end.Add(30 * time.Second).UnixNano() + if _, err := duck.DB.Exec(`INSERT INTO rollup_state VALUES ('service_rollup_v3',?,now())`, watermark); err != nil { + t.Fatal(err) + } + detector := NewDetector(duck, DefaultDetectorConfig()) + detector.runCheck(t.Context()) + previous := detector.LatestSnapshot() + if previous == nil || len(previous.Anomalies) != 1 { + t.Fatalf("snapshot: %+v", previous) + } + a := previous.Anomalies[0] + if !a.WindowStart.Equal(start) || !a.WindowEnd.Equal(end) || !a.DetectedAt.After(end) { + t.Fatalf("anomaly bounds: %+v", a) + } + batch := <-detector.annotationBatches + if err := duck.RecordAnomalies(t.Context(), batch.findings, batch.at); err != nil { + t.Fatal(err) + } + read := func() []annotations.Anomaly { + t.Helper() + result, err := annotations.New(duck).Read(t.Context(), annotations.Request{From: start.Add(-time.Minute), To: end.Add(time.Hour), Namespace: ""}) + if err != nil { + t.Fatal(err) + } + return result.Anomalies + } + persisted := read() + if len(persisted) != 1 || !persisted[0].From.Equal(start) || !persisted[0].To.Equal(end) { + t.Fatalf("historical interval: %+v", persisted) + } + // A recheck would see different values; an unchanged completed minute must + // retain the exact prior snapshot and enqueue no annotation write. + if _, err := duck.DB.Exec(`UPDATE service_rollup SET error_rate=.9 WHERE bucket >= ?`, start); err != nil { + t.Fatal(err) + } + for range 2 { + detector.runCheck(t.Context()) + } + if detector.LatestSnapshot() != previous || len(detector.annotationBatches) != 0 { + t.Fatal("stalled watermark re-evaluated or queued annotations") + } + after := read() + if len(after) != 1 || !after[0].From.Equal(persisted[0].From) || !after[0].To.Equal(persisted[0].To) { + t.Fatalf("stalled interval changed: %+v", after) + } + // Crossing only seconds in the same minute still skips evaluation. + if _, err := duck.DB.Exec(`UPDATE rollup_state SET last_ingested_unix_nano=? WHERE cache_key='service_rollup_v3'`, end.Add(59*time.Second).UnixNano()); err != nil { + t.Fatal(err) + } + detector.runCheck(t.Context()) + if detector.LatestSnapshot() != previous || len(detector.annotationBatches) != 0 { + t.Fatal("incomplete minute triggered evaluation") + } + if _, err := duck.DB.Exec(`UPDATE rollup_state SET last_ingested_unix_nano=? WHERE cache_key='service_rollup_v3'`, end.Add(time.Minute).UnixNano()); err != nil { + t.Fatal(err) + } + detector.runCheck(t.Context()) + if detector.LatestSnapshot() == previous || len(detector.annotationBatches) != 1 { + t.Fatal("advanced minute did not trigger evaluation") + } +} diff --git a/internal/intelligence/types.go b/internal/intelligence/types.go index e2ec5fab..775725b5 100644 --- a/internal/intelligence/types.go +++ b/internal/intelligence/types.go @@ -31,6 +31,8 @@ type Anomaly struct { ZScore float64 `json:"z_score"` // Statistical significance DetectedAt time.Time `json:"detected_at"` // When anomaly was detected Description string `json:"description"` // Human-readable description + WindowStart time.Time `json:"-"` // Evaluated interval, inclusive + WindowEnd time.Time `json:"-"` // Evaluated interval, exclusive } // AnomalyType represents the type of anomaly detected @@ -52,13 +54,14 @@ type Insight struct { // IntelligenceSnapshot represents the current system intelligence state type IntelligenceSnapshot struct { - GeneratedAt time.Time `json:"generated_at"` - Timeframe string `json:"timeframe"` // e.g., "last_15m" - Insights []Insight `json:"insights"` - Patterns []Pattern `json:"patterns"` - Anomalies []Anomaly `json:"anomalies"` - Summary string `json:"summary"` // Overall system health summary - HealthScore float64 `json:"health_score"` // 0-100, lower is worse + evaluatedThrough time.Time + GeneratedAt time.Time `json:"generated_at"` + Timeframe string `json:"timeframe"` // e.g., "last_15m" + Insights []Insight `json:"insights"` + Patterns []Pattern `json:"patterns"` + Anomalies []Anomaly `json:"anomalies"` + Summary string `json:"summary"` // Overall system health summary + HealthScore float64 `json:"health_score"` // 0-100, lower is worse } // DetectorConfig holds configuration for the anomaly detector diff --git a/internal/intelligence/volume_sql_test.go b/internal/intelligence/volume_sql_test.go index 7c982bf4..c1729b4b 100644 --- a/internal/intelligence/volume_sql_test.go +++ b/internal/intelligence/volume_sql_test.go @@ -22,8 +22,8 @@ func TestVolumeAnomalyComparesEqualWindows(t *testing.T) { t.Fatal(err) } defer db.Close() - if _, err := db.Exec(`CREATE TABLE spans ( - service TEXT, namespace TEXT, start_time TIMESTAMP, start_unix_nano BIGINT + if _, err := db.Exec(`CREATE TABLE service_rollup ( + service TEXT, namespace TEXT, bucket TIMESTAMP_NS, spans BIGINT )`); err != nil { t.Fatal(err) } @@ -38,12 +38,8 @@ func TestVolumeAnomalyComparesEqualWindows(t *testing.T) { for bucket, count := range perBucket { at := baselineStart.Add(time.Duration(bucket) * 5 * time.Minute) for _, service := range []string{"cart", "checkout", "frontend"} { - for i := range count { - ts := at.Add(time.Duration(i) * time.Millisecond) - if _, err := db.Exec(`INSERT INTO spans VALUES (?, 'default', ?, ?)`, - service, ts, ts.UnixNano()); err != nil { - t.Fatal(err) - } + if _, err := db.Exec(`INSERT INTO service_rollup VALUES (?, 'default', ?, ?)`, service, at, count); err != nil { + t.Fatal(err) } } } @@ -94,8 +90,8 @@ func TestVolumeAnomalyStillFiresOnARealDrop(t *testing.T) { t.Fatal(err) } defer db.Close() - if _, err := db.Exec(`CREATE TABLE spans ( - service TEXT, namespace TEXT, start_time TIMESTAMP, start_unix_nano BIGINT + if _, err := db.Exec(`CREATE TABLE service_rollup ( + service TEXT, namespace TEXT, bucket TIMESTAMP_NS, spans BIGINT )`); err != nil { t.Fatal(err) } @@ -112,12 +108,8 @@ func TestVolumeAnomalyStillFiresOnARealDrop(t *testing.T) { if service == "collapsing" && inCurrentWindow { count = count / 20 } - for i := range count { - ts := at.Add(time.Duration(i) * time.Millisecond) - if _, err := db.Exec(`INSERT INTO spans VALUES (?, 'default', ?, ?)`, - service, ts, ts.UnixNano()); err != nil { - t.Fatal(err) - } + if _, err := db.Exec(`INSERT INTO service_rollup VALUES (?, 'default', ?, ?)`, service, at, count); err != nil { + t.Fatal(err) } count = perBucket[bucket] } diff --git a/internal/metrics/metrics.go b/internal/metrics/metrics.go index 25932b03..f411b98f 100644 --- a/internal/metrics/metrics.go +++ b/internal/metrics/metrics.go @@ -47,6 +47,10 @@ const ( var ( ReadCachePendingBatches = promauto.NewGauge(prometheus.GaugeOpts{Name: "fanout_read_cache_pending_batches", Help: "Active immutable batches not covered at the start of the last read-cache pass"}) + IngestBackpressureSeconds = promauto.NewCounter(prometheus.CounterOpts{ + Name: "fanout_ingest_backpressure_seconds_total", Help: "Total seconds the ingest writer waited for compaction debt to retire", + }) + // Ingest metrics IngestTotal = promauto.NewCounterVec(prometheus.CounterOpts{ Name: "fanout_ingest_rows_total", @@ -562,3 +566,24 @@ func validateTelemetryResult(result TelemetryResult) { panic("metrics: invalid Telemetry result: " + string(result)) } } + +type compactionBacklogSource struct{ count func() int } + +var compactionBacklog atomic.Pointer[compactionBacklogSource] + +// SetCompactionBacklogSource reads the exact inventory rather than a periodic +// file-stat snapshot. Closing an older repository cannot clear a newer source. +func SetCompactionBacklogSource(count func() int) func() { + source := &compactionBacklogSource{count: count} + compactionBacklog.Store(source) + return func() { compactionBacklog.CompareAndSwap(source, nil) } +} + +var _ = promauto.NewGaugeFunc(prometheus.GaugeOpts{ + Name: "fanout_compaction_backlog_batches", Help: "Live generation-0 batches, including underfilled groups and oversized terminal batches", +}, func() float64 { + if source := compactionBacklog.Load(); source != nil { + return float64(source.count()) + } + return 0 +}) diff --git a/internal/metrics/metrics_test.go b/internal/metrics/metrics_test.go index ca328ffc..f39e0162 100644 --- a/internal/metrics/metrics_test.go +++ b/internal/metrics/metrics_test.go @@ -250,3 +250,37 @@ func histogramSampleCount(t *testing.T, metricName, labelName, labelValue string } return 0 } + +func TestCompactionBacklogSourceTracksCountAndOwner(t *testing.T) { + count := 12 + releaseOld := SetCompactionBacklogSource(func() int { return count }) + releaseNew := SetCompactionBacklogSource(func() int { return count + 1 }) + defer releaseNew() + releaseOld() + families, err := prometheus.DefaultGatherer.Gather() + if err != nil { + t.Fatal(err) + } + found := false + for _, family := range families { + if family.GetName() == "fanout_compaction_backlog_batches" { + found = true + if got := family.Metric[0].GetGauge().GetValue(); got != 13 { + t.Fatalf("count=%g", got) + } + } + } + if !found { + t.Fatal("backlog gauge not exported") + } + releaseNew() + families, err = prometheus.DefaultGatherer.Gather() + if err != nil { + t.Fatal(err) + } + for _, family := range families { + if family.GetName() == "fanout_compaction_backlog_batches" && family.Metric[0].GetGauge().GetValue() != 0 { + t.Fatal("closed source retained") + } + } +} diff --git a/internal/observability/batch_reads_test.go b/internal/observability/batch_reads_test.go index 2e13d7bb..355c83c5 100644 --- a/internal/observability/batch_reads_test.go +++ b/internal/observability/batch_reads_test.go @@ -156,7 +156,7 @@ func TestCompletedTraceMatchesRawAcrossTimeLocalBatches(t *testing.T) { rng := rand.New(rand.NewPCG(11, 104729)) t0 := time.Date(2026, 10, 1, 12, 0, 0, 0, time.UTC) statuses := []string{"OK", "ERROR", "error", "UNSET", ""} - commit := func(k int, ingest time.Time) { + commit := func(k int) { t.Helper() lo := t0.Add(-40*time.Minute + time.Duration(k)*37*time.Second) batch := telemetrystore.Batch{ID: fmt.Sprintf("local%03d", k)} @@ -165,7 +165,7 @@ func TestCompletedTraceMatchesRawAcrossTimeLocalBatches(t *testing.T) { dur := time.Duration(rng.Int64N(int64(2 * time.Second))) batch.Spans = append(batch.Spans, telemetry.Span{Namespace: []string{"prod", "dev"}[rng.IntN(2)], ServiceName: []string{"api", "worker"}[rng.IntN(2)], TraceID: fmt.Sprintf("t%03d", k/2+rng.IntN(3)), SpanID: fmt.Sprintf("%s-%d", batch.ID, i), StartUnixNanos: at.UnixNano(), EndUnixNanos: at.Add(dur).UnixNano(), - DurationMS: float64(dur) / 1e6, StatusCode: statuses[rng.IntN(len(statuses))], HTTPMethod: "GET", HTTPRoute: "/a", IngestedAt: ingest.UnixNano()}) + DurationMS: float64(dur) / 1e6, StatusCode: statuses[rng.IntN(len(statuses))], HTTPMethod: "GET", HTTPRoute: "/a"}) } if err := repo.Commit(t.Context(), batch); err != nil { t.Fatal(err) @@ -209,7 +209,7 @@ func TestCompletedTraceMatchesRawAcrossTimeLocalBatches(t *testing.T) { } } for k := 0; k < 24; k++ { - commit(k, t0.Add(-2*time.Hour+time.Duration(k)*time.Second)) + commit(k) } refresh() check("cached") @@ -221,11 +221,12 @@ func TestCompletedTraceMatchesRawAcrossTimeLocalBatches(t *testing.T) { check("compacted before refresh") refresh() check("compacted") + retireThrough, _, _ := repo.PublicationBounds() for k := 24; k < 28; k++ { - commit(k, t0.Add(time.Duration(k)*time.Second)) + commit(k) } refresh() - if n, err := repo.PruneParquet(t.Context(), d, t0.Add(-time.Hour).UnixNano(), 100); err != nil || n == 0 { + if n, err := repo.PruneParquet(t.Context(), d, retireThrough+1, 100); err != nil || n == 0 { t.Fatalf("prune: %d %v", n, err) } check("pruned before refresh") diff --git a/internal/panel/metric_measure_bench_test.go b/internal/panel/metric_measure_bench_test.go index 473fa9d4..17621493 100644 --- a/internal/panel/metric_measure_bench_test.go +++ b/internal/panel/metric_measure_bench_test.go @@ -81,7 +81,7 @@ func TestMetricMeasuresExecuteAtReviewScale(t *testing.T) { points = append(points, m) } } - if err := store.CommitBatch(t.Context(), telemetry.BatchMetadata{ID: fmt.Sprintf("minute%d", minute+10)}, nil, nil, points); err != nil { + if err := store.CommitBatch(t.Context(), &telemetry.BatchMetadata{ID: fmt.Sprintf("minute%d", minute+10)}, nil, nil, points); err != nil { t.Fatal(err) } } diff --git a/internal/query/analytical_backlog_test.go b/internal/query/analytical_backlog_test.go index 7d23cfd9..1dc53684 100644 --- a/internal/query/analytical_backlog_test.go +++ b/internal/query/analytical_backlog_test.go @@ -167,7 +167,7 @@ func TestServiceRollupBacklogDrainsWithoutDroppingLateBuckets(t *testing.T) { t.Fatal(err) } tip := base.Add(11 * ingestStep).UnixNano() - // Below the live tip, but inside its publication safety lag. This + // A new commit stamp revisits an old event bucket. This // revisits an old event bucket containing service-only outbound work. late := telemetrystore.Batch{ID: "late", Spans: []telemetry.Span{{Namespace: "ns-a", ServiceName: "outbound", TraceID: "late", SpanID: "late", Kind: "SPAN_KIND_CLIENT", StartUnixNanos: base.UnixNano(), EndUnixNanos: base.Add(time.Millisecond).UnixNano(), DurationMS: 1, IngestedAt: tip - int64(time.Second)}}, Logs: []telemetry.Log{{Namespace: "ns-b", ServiceName: "gateway", EventUnixNanos: base.UnixNano(), TimeUnixNanos: base.UnixNano(), IngestedAt: tip - int64(time.Second), Body: "late"}}} if err := repo.Commit(ctx, late); err != nil { @@ -182,7 +182,8 @@ func TestServiceRollupBacklogDrainsWithoutDroppingLateBuckets(t *testing.T) { if err := d.DB.QueryRowContext(ctx, `SELECT last_ingested_unix_nano FROM rollup_state WHERE cache_key=?`, serviceRollupStateKey).Scan(&watermark); err != nil { t.Fatal(err) } - if watermark == tip { + horizon, _, _ := d.publicationBounds() + if watermark == horizon { break } } @@ -223,7 +224,7 @@ func seedAnalyticalBacklog(t *testing.T, repo *telemetrystore.Repository, base t } b.Logs = append(b.Logs, telemetry.Log{Namespace: ns, ServiceName: "gateway", EventUnixNanos: n, TimeUnixNanos: n, IngestedAt: ingest + int64(time.Duration(batch)*step), Body: "backlog"}) } - if err := repo.Commit(t.Context(), b); err != nil { + if err := commitRestoredFixture(repo, t.Context(), b); err != nil { t.Fatal(err) } } @@ -273,3 +274,52 @@ func assertBacklogMarkers(t *testing.T, d *Duck, repo *telemetrystore.Repository } } } + +// commitRestoredFixture seeds already-stamped historical inputs, as recovery +// does. Normal ingest tests use Repository.Commit and its fresh attempt stamp. +func commitRestoredFixture(repo *telemetrystore.Repository, ctx context.Context, batch telemetrystore.Batch) error { + var lo, hi int64 + include := func(n int64) { + if n > 0 && (lo == 0 || n < lo) { + lo = n + } + hi = max(hi, n) + } + for i := range batch.Spans { + row := &batch.Spans[i] + row.Namespace = telemetry.NormalizeNamespace(row.Namespace) + include(row.IngestedAt) + if row.StartUnixNanos == 0 { + row.StartUnixNanos = row.IngestedAt + } + } + for i := range batch.Logs { + row := &batch.Logs[i] + row.Namespace = telemetry.NormalizeNamespace(row.Namespace) + include(row.IngestedAt) + if row.EventUnixNanos == 0 { + row.EventUnixNanos = telemetry.FirstPositiveNanos(row.TimeUnixNanos, row.ObservedTimeNanos, row.IngestedAt) + } + } + for i := range batch.Metrics { + row := &batch.Metrics[i] + row.Namespace = telemetry.NormalizeNamespace(row.Namespace) + include(row.IngestedAt) + if row.EventUnixNanos == 0 { + row.EventUnixNanos = telemetry.FirstPositiveNanos(row.TimeUnixNanos, row.IngestedAt) + } + } + return repo.Parquet.CommitBatch(ctx, &telemetry.BatchMetadata{ID: batch.ID, MinIngestedNanos: lo, MaxIngestedNanos: hi}, batch.Spans, batch.Logs, batch.Metrics) +} +func restoredPublicationBounds(repo *telemetrystore.Repository) func() (int64, int64, int64) { + return func() (int64, int64, int64) { + var lo, hi int64 + for _, b := range repo.Parquet.BatchMetadata() { + hi = max(hi, b.MaxIngestedNanos) + if b.MinIngestedNanos > 0 && (lo == 0 || b.MinIngestedNanos < lo) { + lo = b.MinIngestedNanos + } + } + return hi, hi, lo + } +} diff --git a/internal/query/annotation_maintenance_test.go b/internal/query/annotation_maintenance_test.go index aed9eb60..132c9983 100644 --- a/internal/query/annotation_maintenance_test.go +++ b/internal/query/annotation_maintenance_test.go @@ -44,7 +44,7 @@ func TestVersionHistoryDeletesOnlyWhenNeeded(t *testing.T) { func TestVersionFailureDoesNotStarveNewBatches(t *testing.T) { _, repo := versionEngine(t) at := time.Now().UTC().Add(-time.Hour) - commitVersionLogs(t, repo, "a-old", at, 64001) + commitVersionLogs(t, repo, "a-old", at, 1) commitVersionLogs(t, repo, "b-new", at.Add(time.Minute), 1) commitVersionLogs(t, repo, "c-new", at.Add(2*time.Minute), 1) db, mock, err := sqlmock.New() @@ -53,6 +53,7 @@ func TestVersionFailureDoesNotStarveNewBatches(t *testing.T) { } defer db.Close() d := &Duck{DB: db, writeDB: db, repository: repo, versionRollupPasses: 1} + d.versionRollupFailures = map[string]versionRollupFailure{"a-old": {retrySingly: true}} mock.ExpectQuery(`SELECT batch_id FROM version_rollup_batches`).WillReturnRows(sqlmock.NewRows([]string{"batch_id"})) mock.ExpectBegin() @@ -216,7 +217,7 @@ func TestSingleDrainRegistration(t *testing.T) { } for _, decl := range file.Decls { fn, ok := decl.(*ast.FuncDecl) - if !ok || (fn.Name.Name != "rollupOnce" && fn.Name.Name != "runReadCacheLoop") { + if !ok || (fn.Name.Name != "rollupOnce" && fn.Name.Name != "runReadCacheLoop" && fn.Name.Name != "runVersionRollupLoop") { continue } count := 0 @@ -229,7 +230,7 @@ func TestSingleDrainRegistration(t *testing.T) { return true }) want := 0 - if fn.Name.Name == "runReadCacheLoop" { + if fn.Name.Name == "runVersionRollupLoop" { want = 1 } if count != want { @@ -308,41 +309,6 @@ func TestAnomalyMergePerformance(t *testing.T) { } } -func TestOversizedVersionBatch(t *testing.T) { - d, repo := versionEngine(t) - now := time.Now().UTC().UnixNano() - logs := make([]telemetry.Log, 64001) - for i := range logs { - logs[i] = telemetry.Log{ServiceName: "oversized", Resource: map[string]any{"service.version": "v1"}, EventUnixNanos: now, IngestedAt: now} - } - if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "oversized", Logs: logs}); err != nil { - t.Fatal(err) - } - var log bytes.Buffer - logger := slog.Default() - slog.SetDefault(slog.New(slog.NewTextHandler(&log, nil))) - defer slog.SetDefault(logger) - if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != 1 { - t.Fatalf("oversized pass: %d %v", n, err) - } - if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != 0 { - t.Fatalf("oversized retry: %d %v", n, err) - } - if output := log.String(); strings.Contains(output, "version rollup batch exceeds row budget") { - t.Fatalf("oversized warning spam: %s", output) - } - var count, limited int - if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup`).Scan(&count); err != nil || count != 1 { - t.Fatalf("oversized scanned=%d %v", count, err) - } - if err := d.DB.QueryRow(`SELECT last_ingested_unix_nano FROM rollup_state WHERE cache_key='version_rollup_v1_limited'`).Scan(&limited); err != nil || limited != 0 { - t.Fatalf("limited=%d %v", limited, err) - } - if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup_batches WHERE batch_id='oversized'`).Scan(&count); err != nil || count != 1 { - t.Fatalf("oversized batch acknowledged=%d %v", count, err) - } -} - func TestVersionMarkerColdInput(t *testing.T) { d, _ := versionEngine(t) if _, err := d.DB.Exec(`INSERT INTO version_rollup_batches VALUES ('warm',1)`); err != nil { diff --git a/internal/query/annotations.go b/internal/query/annotations.go index d3cb542f..771acef5 100644 --- a/internal/query/annotations.go +++ b/internal/query/annotations.go @@ -79,7 +79,40 @@ func createAnnotationTables(db *sql.DB) error { "namespace", "service", "kind", "start_time", "end_time", "title", "severity") } -const versionRollupWaitBudget = 20 * time.Second +const ( + versionRollupWaitBudget = 20 * time.Second + // Mixed 5k/50k-per-signal Parquet batches process about 3.8m rows in + // one second on eight threads. Bound both rows and file/marker overhead + // while amortizing each pass and the worker's 100ms progress delay. + versionRollupRowBudget = 1_000_000 + versionRollupBatchBudget = 64 +) + +// Batches are ordered by ingestion time by the caller. Indivisible oversized +// batches and failed groups still get a single-batch attempt under the deadline. +func pendingVersionBatches(batches []telemetry.BatchMetadata, marked map[string]bool, failures map[string]versionRollupFailure, now time.Time) []telemetry.BatchMetadata { + pending := []telemetry.BatchMetadata{} + count := 0 + for _, b := range batches { + if marked[b.ID] || now.Before(failures[b.ID].nextAttempt) { + continue + } + size := b.Spans + b.Logs + b.Metrics + if failures[b.ID].retrySingly && len(pending) > 0 { + break + } + if len(pending) == 0 && (size > versionRollupRowBudget || failures[b.ID].retrySingly) { + pending = append(pending, b) + break + } + if len(pending) >= versionRollupBatchBudget || count+size > versionRollupRowBudget { + break + } + pending = append(pending, b) + count += size + } + return pending +} func (d *Duck) RefreshVersionRollup(ctx context.Context) (int64, error) { return d.refreshVersionRollup(ctx, versionRollupWaitBudget) @@ -153,27 +186,7 @@ func (d *Duck) refreshVersionRollup(ctx context.Context, waitBudget time.Duratio delete(d.versionRollupFailures, id) } } - pending := []telemetry.BatchMetadata{} - count := 0 - for _, b := range batches { - if marked[b.ID] || time.Now().Before(d.versionRollupFailures[b.ID].nextAttempt) { - continue - } - size := b.Spans + b.Logs + b.Metrics - if d.versionRollupFailures[b.ID].retrySingly && len(pending) > 0 { - break - } - if len(pending) == 0 && (size > 64000 || d.versionRollupFailures[b.ID].retrySingly) { - // Oversized batches and failed groups retry alone under the 10s deadline. - pending = append(pending, b) - break - } - if len(pending) >= 64 || count+size > 64000 { - break - } - pending = append(pending, b) - count += size - } + pending := pendingVersionBatches(batches, marked, d.versionRollupFailures, time.Now()) attempted := false // writeGate protects this disposable, per-process retry state. Failed batches // remain unmarked, so a later committed pass still discloses limited history. diff --git a/internal/query/annotations_test.go b/internal/query/annotations_test.go index 6d876abb..a40b42ce 100644 --- a/internal/query/annotations_test.go +++ b/internal/query/annotations_test.go @@ -47,6 +47,7 @@ func versionEngine(t *testing.T) (*Duck, *telemetrystore.Repository) { if err != nil { t.Fatal(err) } + d.publicationBounds = restoredPublicationBounds(repo) t.Cleanup(func() { _ = d.Close(); _ = repo.Close() }) return d, repo } @@ -160,14 +161,14 @@ func (e *annotationCountingEngine) QueryContext(ctx context.Context, text string func TestVersionPassAndHistoryCaps(t *testing.T) { d, repo := versionEngine(t) at := time.Now().UTC().Add(-time.Hour) - for i := 0; i < 65; i++ { + for i := 0; i < versionRollupBatchBudget+1; i++ { id := fmt.Sprintf("version-%03d", i) n := at.Add(time.Duration(i) * time.Millisecond).UnixNano() if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: id, Spans: []telemetry.Span{{Namespace: "shop", ServiceName: "checkout", ServiceVersion: "v1", TraceID: id, SpanID: id, Name: "root", StartUnixNanos: n, EndUnixNanos: n + 1000, DurationMS: .001, IngestedAt: n}}}); err != nil { t.Fatal(err) } } - if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != 64 { + if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != versionRollupBatchBudget { t.Fatalf("first pass %d %v", n, err) } if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != 1 { @@ -197,7 +198,7 @@ func TestVersionPassAndHistoryCaps(t *testing.T) { func TestVersionDrainAndLimitedReset(t *testing.T) { d, repo := versionEngine(t) at := time.Now().UTC().Add(-time.Hour) - for i := range 70 { + for i := range versionRollupBatchBudget + 6 { n := at.UnixNano() if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: fmt.Sprintf("drain-%03d", i), Logs: []telemetry.Log{{Namespace: "shop", ServiceName: "checkout", Resource: map[string]any{"service.version": "v2"}, EventUnixNanos: n, IngestedAt: n}}}); err != nil { t.Fatal(err) @@ -217,7 +218,7 @@ func TestVersionDrainAndLimitedReset(t *testing.T) { t.Fatalf("stuck backlog=%d %v", limited, err) } var marked int - if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup_batches`).Scan(&marked); err != nil || marked != 70 { + if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup_batches`).Scan(&marked); err != nil || marked != versionRollupBatchBudget+6 { t.Fatalf("markers=%d %v", marked, err) } } @@ -234,12 +235,12 @@ func commitVersionLogs(t *testing.T, repo *telemetrystore.Repository, id string, } logs[i] = telemetry.Log{Namespace: "shop", ServiceName: "checkout", Resource: map[string]any{"service.version": version}, EventUnixNanos: n, IngestedAt: at.UnixNano()} } - if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: id, Logs: logs}); err != nil { + if err := commitRestoredFixture(repo, t.Context(), telemetrystore.Batch{ID: id, Logs: logs}); err != nil { t.Fatal(err) } } -func TestVersionOversizedBatchDrains(t *testing.T) { +func TestVersionLargeBatchDrains(t *testing.T) { d, repo := versionEngine(t) at := time.Now().UTC().Add(-time.Hour) commitVersionLogs(t, repo, "oversized", at, 64001) @@ -259,32 +260,6 @@ func TestVersionOversizedBatchDrains(t *testing.T) { } } -func TestVersionMixedBatchPasses(t *testing.T) { - d, repo := versionEngine(t) - at := time.Now().UTC().Add(-time.Hour) - for i, size := range []int{1, 64001, 2, 64002, 3} { - commitVersionLogs(t, repo, fmt.Sprintf("mixed-%d", i), at.Add(time.Duration(i)*time.Minute), size) - } - for pass := range 5 { - if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != 1 { - t.Fatalf("pass %d processed=%d %v", pass, n, err) - } - var marked, limited int - if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup_batches WHERE batch_id=?`, fmt.Sprintf("mixed-%d", pass)).Scan(&marked); err != nil || marked != 1 { - t.Fatalf("oldest batch on pass %d marked=%d %v", pass, marked, err) - } - want := 1 - if pass == 4 { - want = 0 - } - if err := d.DB.QueryRow(`SELECT last_ingested_unix_nano FROM rollup_state WHERE cache_key='version_rollup_v1_limited'`).Scan(&limited); err != nil || limited != want { - t.Fatalf("pass %d limited=%d want=%d %v", pass, limited, want, err) - } - } - if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != 0 { - t.Fatalf("drained pass=%d %v", n, err) - } -} func TestVersionResourceLogsAndMetrics(t *testing.T) { d, repo := versionEngine(t) at := time.Now().UTC().Add(-time.Hour) diff --git a/internal/query/background_admission_test.go b/internal/query/background_admission_test.go new file mode 100644 index 00000000..7c962663 --- /dev/null +++ b/internal/query/background_admission_test.go @@ -0,0 +1,85 @@ +package query + +import ( + "context" + "errors" + "testing" + "time" + + "github.com/labstack/fanout/internal/telemetry" + telemetrystore "github.com/labstack/fanout/internal/telemetry/store" +) + +func TestBackgroundPassesYieldToQueuedPublication(t *testing.T) { + d, repo := newBatchCacheTest(t) + if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "pending", Spans: []telemetry.Span{{TraceID: "trace", StartUnixNanos: 1, EndUnixNanos: 2}}}); err != nil { + t.Fatal(err) + } + mustRLock(t, &d.parquetMu) + defer d.parquetMu.RUnlock() + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + publisher := make(chan error, 1) + go func() { publisher <- d.parquetMu.LockContext(ctx) }() + waitForQueuedWriter(t, &d.parquetMu) + if err := d.lockParquetRead(t.Context(), readerQuery); err != nil { + t.Fatalf("query refused inside grace: %v", err) + } + d.parquetMu.RUnlock() + // A cache pass must skip immediately, even without a caller deadline. + cacheDone := make(chan error, 1) + go func() { _, err := d.RefreshReadCaches(t.Context()); cacheDone <- err }() + select { + case err := <-cacheDone: + if err != nil { + t.Fatal(err) + } + case <-time.After(time.Second): + t.Fatal("read cache waited behind publication") + } + markers, err := batchMarkers(t.Context(), d.DB) + if err != nil || markers["pending"] { + t.Fatalf("cache entered ahead of queued publisher: %v %v", markers, err) + } + for name, pass := range map[string]func(context.Context) error{ + "service": func(ctx context.Context) error { _, err := d.refreshServiceRollup(ctx); return err }, + "edge": func(ctx context.Context) error { _, err := d.refreshEdgeRollup(ctx); return err }, + "version": func(ctx context.Context) error { _, err := d.RefreshVersionRollup(ctx); return err }, + "stats": func(ctx context.Context) error { + err := d.lockParquetRead(ctx, readerStats) + if err == nil { + d.parquetMu.RUnlock() + } + return err + }, + } { + t.Run(name, func(t *testing.T) { + waitCtx, stop := context.WithTimeout(t.Context(), 20*time.Millisecond) + defer stop() + if err := pass(waitCtx); !errors.Is(err, ErrParquetReadWait) || !errors.Is(err, context.DeadlineExceeded) { + t.Fatalf("background pass did not wait behind publisher: %v", err) + } + }) + } + cancel() + if err := <-publisher; !errors.Is(err, context.Canceled) { + t.Fatalf("publisher cancellation: %v", err) + } + if _, err := d.RefreshReadCaches(t.Context()); err != nil { + t.Fatal(err) + } + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) + } + if _, err := d.refreshEdgeRollup(t.Context()); err != nil { + t.Fatal(err) + } + if _, err := d.RefreshVersionRollup(t.Context()); err != nil { + t.Fatal(err) + } + d.updateParquetStats(t.Context()) + markers, err = batchMarkers(t.Context(), d.DB) + if err != nil || !markers["pending"] { + t.Fatalf("cache did not resume: %v %v", markers, err) + } +} diff --git a/internal/query/backlog_pressure_test.go b/internal/query/backlog_pressure_test.go index cb749342..4d683f16 100644 --- a/internal/query/backlog_pressure_test.go +++ b/internal/query/backlog_pressure_test.go @@ -327,11 +327,10 @@ func TestBacklogServiceFailuresIdentifyStatementAndPreserveCause(t *testing.T) { } defer db.Close() cause := &duckdb.Error{Type: duckdb.ErrorTypeOutOfMemory, Msg: "Out of Memory Error: attribution fixture"} - mock.ExpectBegin() - for _, key := range []string{serviceRollupStateKey, serviceRollupRawMaxKey} { + for _, key := range []string{serviceRollupStateKey} { mock.ExpectQuery("FROM rollup_state").WithArgs(key).WillReturnRows(sqlmock.NewRows([]string{"watermark"}).AddRow(1)) } - mock.ExpectQuery("FROM \\(").WillReturnRows(sqlmock.NewRows([]string{"max"}).AddRow(2)) + mock.ExpectBegin() if label == "service_rollup/delete" { mock.ExpectExec("DELETE FROM service_rollup").WillReturnError(cause) } else { @@ -339,7 +338,7 @@ func TestBacklogServiceFailuresIdentifyStatementAndPreserveCause(t *testing.T) { mock.ExpectExec("WITH affected").WillReturnError(cause) } mock.ExpectRollback() - d := &Duck{DB: db, writeDB: db} + d := &Duck{DB: db, writeDB: db, publicationBounds: func() (int64, int64, int64) { return 2, 2, 1 }} _, err = d.refreshServiceRollup(t.Context()) var native *duckdb.Error if err == nil || !strings.Contains(err.Error(), label) || !errors.Is(err, cause) || !errors.As(err, &native) || native != cause { diff --git a/internal/query/batch_cache.go b/internal/query/batch_cache.go index 81d622bb..139668cf 100644 --- a/internal/query/batch_cache.go +++ b/internal/query/batch_cache.go @@ -133,7 +133,7 @@ func (d *Duck) RefreshReadCaches(ctx context.Context) (rows int64, err error) { defer unlock() // Cache retries are frequent. A queued publication must not park the cache // gate for the analytical rollup's much longer admission lease. - admitted := d.parquetMu.TryRLock() + admitted := d.parquetMu.TryRLock(parquetReadBackground) metrics.RecordParquetRead(readerRollup, 0, admitted) if !admitted { return 0, nil diff --git a/internal/query/duck.go b/internal/query/duck.go index 0789ab23..726869ec 100644 --- a/internal/query/duck.go +++ b/internal/query/duck.go @@ -48,10 +48,11 @@ type Duck struct { writeDB *sql.DB cfg config.Config repository *telemetrystore.Repository - // rollupLagNanos holds the rollup watermark back from the max ingested - // timestamp so late/out-of-order commits aren't skipped. Zero disables the - // lag (no trailing window). - rollupLagNanos int64 + // publicationBounds is the repository's exact commit horizon. Tests using + // mutable fixtures supply their own source; production always uses Repository. + publicationBounds func() (horizon, published, minimum int64) + // Cached under writeGate so an idle pass executes no SQL at all. + rollupWatermarks map[string]int64 // writeGate serializes writes to the rebuildable DuckDB rollup cache. writeGate writegate.WriteGate cacheGate writegate.WriteGate @@ -94,15 +95,13 @@ const ( // Bump this whenever the table's shape or the meaning of its columns // changes. serviceRollupStateKey = "service_rollup_v3" - serviceRollupRawMaxKey = "service_rollup_v3_rawmax" edgeRollupStateKey = "edge_rollup_v2" - edgeRollupRawMaxKey = "edge_rollup_v2_rawmax" edgeRollupSubCursorKey = "edge_rollup_v2_substart" edgeRollupSubWindowKey = "edge_rollup_v2_subwindow_end" defaultDuckDBPoolSize = 1 parquetCompactionCycle = 10 * time.Second parquetCompactionCycleBudget = 8 * time.Second - parquetMaintenanceBatchLimit = 128 + parquetMaintenanceBatchLimit = telemetry.CompactionBatchLimit parquetMaintenancePhaseBudget = 10 * time.Minute ) @@ -121,19 +120,6 @@ const ( // so the internal lease can be exercised without a five-second test. var parquetStatsWait = 5 * time.Second -// edgeYieldMargin is how much of a queued publication's grace has to be left -// for the edge rollup to take another sub-window. It is a rough estimate of -// what one more sub-window costs: enough that the pass usually finishes before -// readers start queuing, small enough that the eight-sub-window budget is not -// given up for a publication that has only just arrived. -const edgeYieldMargin = 10 * time.Second - -// rollupPublicationSafetyLag covers the maximum public SQL hold, publication -// grace, bounded commit retries, and queued Parquet encoding with headroom for -// a busy disk. Rows stamped at request receipt remain inside the recomputed -// tail until their Parquet commit becomes visible. -const rollupPublicationSafetyLag = 5 * time.Minute - // WriteGate returns the gate that serializes writes to DuckDB's rebuildable // rollup cache. func (d *Duck) WriteGate() *writegate.WriteGate { return &d.writeGate } @@ -262,7 +248,7 @@ func NewDuck(ctx context.Context, cfg config.Config, repository *telemetrystore. if err != nil { return nil, fmt.Errorf("open DuckDB query cache: %w (the cache at %s is rebuildable from Parquet)", err, dbPath) } - d := &Duck{DB: db, writeDB: writeDB, cfg: cfg, repository: repository, rollupLagNanos: int64(rollupPublicationSafetyLag)} + d := &Duck{DB: db, writeDB: writeDB, cfg: cfg, repository: repository, publicationBounds: repository.PublicationBounds} // Reads are the pool that can starve, so it is the one worth watching. d.releasePoolGauges = metrics.SetDuckDBPoolSource(db.Stats) // And what DuckDB admits to holding, so the gap against process RSS is @@ -306,6 +292,10 @@ func NewDuck(ctx context.Context, cfg config.Config, repository *telemetrystore. _ = d.Close() return nil, err } + if err := d.loadRollupWatermarks(ctx); err != nil { + _ = d.Close() + return nil, err + } if err := CreateParquetViews(writeDB, repository.Parquet.Dir()); err != nil { _ = d.Close() return nil, err @@ -329,8 +319,8 @@ func NewDuck(ctx context.Context, cfg config.Config, repository *telemetrystore. return d, nil } -// skipRollupToLatest advances every rollup watermark to the current max ingested -// timestamp, so existing data is treated as already-processed rather than +// skipRollupToLatest advances every rollup watermark to the publication +// horizon, so existing data is treated as already-processed rather than // aggregated as a backlog. This avoids a multi-minute first-rollup catch-up // that monopolizes DuckDB write capacity when standing up a large pre-seeded // historical dataset. Runs once at boot before RunRollups, so taking the write @@ -345,22 +335,13 @@ func (d *Duck) skipRollupToLatest(ctx context.Context) error { } defer func() { _ = tx.Rollback() }() - svc, err := maxServiceRollupWatermark(ctx, tx) - if err != nil { - return err - } - edge, err := maxEdgeRollupWatermark(ctx, tx) - if err != nil { - return err - } + horizon, _, _ := d.publicationBounds() for _, w := range []struct { key string watermark int64 }{ - {serviceRollupStateKey, svc}, - {serviceRollupRawMaxKey, svc}, - {edgeRollupStateKey, edge}, - {edgeRollupRawMaxKey, edge}, + {serviceRollupStateKey, horizon}, + {edgeRollupStateKey, horizon}, // Skipping discards any half-aggregated window, so its resume point // must go too or the next pass would reopen a window behind the // watermark it just advanced. @@ -371,7 +352,11 @@ func (d *Duck) skipRollupToLatest(ctx context.Context) error { return err } } - return tx.Commit() + if err := tx.Commit(); err != nil { + return err + } + d.rollupWatermarks = map[string]int64{serviceRollupStateKey: horizon, edgeRollupStateKey: horizon} + return nil } // openDuckDB returns the read pool and the single-connection write handle. @@ -529,6 +514,13 @@ func (d *Duck) RunRollups(ctx context.Context) { }() defer func() { <-readCacheDone }() + versionDone := make(chan struct{}) + go func() { + defer close(versionDone) + d.runVersionRollupLoop(ctx) + }() + defer func() { <-versionDone }() + ticker := time.NewTicker(d.cfg.RollupInterval) defer ticker.Stop() for { @@ -616,6 +608,22 @@ func (d *Duck) runReadCacheLoop(ctx context.Context) { } else if rows > 0 { delay = 100 * time.Millisecond } + } +} + +// Version history uses the analytical gate and its own cadence. Its gate wait +// must never delay complete-file caching on the independent cache gate. +func (d *Duck) runVersionRollupLoop(ctx context.Context) { + delay := time.Second + for { + timer := time.NewTimer(delay) + select { + case <-ctx.Done(): + timer.Stop() + return + case <-timer.C: + } + delay = time.Second if batches, err := d.DrainVersionRollup(ctx); err != nil && ctx.Err() == nil { slog.Warn("version rollup failed", "err", err) } else if batches > 0 { @@ -782,80 +790,37 @@ func (d *Duck) refreshServiceRollup(ctx context.Context) (int64, error) { // consistent and deadlock-free. unlock := d.writeGate.Lock(writegate.WriteRollupService) defer unlock() - if err := d.lockRollupParquetRead(ctx); err != nil { - return 0, err - } - defer d.parquetMu.RUnlock() - - tx, err := d.writer().BeginTx(ctx, nil) - if err != nil { - return 0, err + horizon, published, minimum := d.publicationBounds() + sourceMax = published + // Failed attempts advance the horizon without publishing rows. Until the + // first publication, retain the initial watermark so catch-up starts at + // metadata's minimum rather than taking hour-sized steps from the epoch. + if published == 0 { + result = metrics.RollupNoop + updateRollupProgress(metrics.RollupService, true, d.rollupWatermarks[serviceRollupStateKey], 0) + return 0, nil } - defer func() { _ = tx.Rollback() }() - - lastWatermark, err := rollupWatermark(ctx, tx, serviceRollupStateKey) + lastWatermark, err := d.cachedRollupWatermark(ctx, serviceRollupStateKey, horizon) if err != nil { return 0, err } watermark = lastWatermark - lastRawMax, err := rollupWatermark(ctx, tx, serviceRollupRawMaxKey) - if err != nil { - return 0, err + if horizon <= lastWatermark { + result = metrics.RollupNoop + updateRollupProgress(metrics.RollupService, true, lastWatermark, published) + return 0, nil } - - rawWatermark, err := maxServiceRollupWatermark(ctx, tx) - if err != nil { + if err := d.lockRollupParquetRead(ctx); err != nil { return 0, err } - sourceMax = rawWatermark - if rawWatermark <= lastWatermark { - err := tx.Commit() - if err == nil { - result = metrics.RollupNoop - updateRollupProgress(metrics.RollupService, true, lastWatermark, rawWatermark) - } + defer d.parquetMu.RUnlock() + tx, err := d.writer().BeginTx(ctx, nil) + if err != nil { return 0, err } - - minIngested := int64(0) - if lastWatermark == 0 { - if minIngested, err = minServiceRollupIngested(ctx, tx); err != nil { - return 0, err - } - } - windowStart, windowEnd, chunked := rollupWindow(lastWatermark, minIngested, rawWatermark) - - // The affected scan below covers (windowStart, windowEnd]. Choosing the - // stored watermark: - // - While the raw max is ahead of what any prior pass processed, never - // advance the watermark into the trailing lag window below it — - // ingested_unix_nano is stamped at ingest but signals flush - // independently and the writer retries, so a row can commit below the - // current max and must still be picked up (delete+insert is idempotent - // per bucket). This clamp applies to chunked passes too: a chunk end - // can land inside the lag window of the live tip. - // - Once the max plateaus (no new ingest since a pass processed up to - // it), the trailing window has been reprocessed once already, so - // advance straight to the raw max and let the next cycle - // short-circuit. Otherwise a burst's trailing window would be - // re-aggregated every cycle forever after ingest goes quiet. + defer func() { _ = tx.Rollback() }() + windowStart, windowEnd, _ := rollupWindow(lastWatermark, minimum, horizon) newWatermark := windowEnd - if rawWatermark > lastRawMax { - if guarded := rawWatermark - d.rollupSafetyLagNanos(); newWatermark > guarded { - newWatermark = guarded - } - if newWatermark < lastWatermark { - newWatermark = lastWatermark - } - } - // The rawmax key records the highest tip whose trailing lag window a pass - // has actually processed — advance it only as far as this pass scanned, - // or the plateau shortcut above would fire before the catch-up reached - // the tip and skip the backlog's last lag window. - rawMaxProcessed := rawWatermark - if chunked { - rawMaxProcessed = windowEnd - } args := []any{windowStart, windowEnd, windowStart, windowEnd, windowStart, windowEnd} if _, err := tx.ExecContext(ctx, serviceRollupDeleteSQL, args...); err != nil { @@ -869,14 +834,12 @@ func (d *Duck) refreshServiceRollup(ctx context.Context) (int64, error) { if err := storeRollupWatermark(ctx, tx, serviceRollupStateKey, newWatermark); err != nil { return 0, err } - if err := storeRollupWatermark(ctx, tx, serviceRollupRawMaxKey, rawMaxProcessed); err != nil { - return 0, err - } if err := tx.Commit(); err != nil { return 0, err } result = metrics.RollupSuccess - updateRollupProgress(metrics.RollupService, true, newWatermark, rawWatermark) + d.rollupWatermarks[serviceRollupStateKey] = newWatermark + updateRollupProgress(metrics.RollupService, true, newWatermark, published) rows, err := res.RowsAffected() if err != nil { @@ -924,32 +887,35 @@ func (d *Duck) refreshEdgeRollupPass(ctx context.Context) (int64, bool, error) { }() unlock := d.writeGate.Lock(writegate.WriteRollupEdge) defer unlock() - if err := d.lockRollupParquetRead(ctx); err != nil { - return 0, false, err - } - defer d.parquetMu.RUnlock() - - tx, err := d.writer().BeginTx(ctx, nil) - if err != nil { - return 0, false, err - } - defer func() { _ = tx.Rollback() }() - - lastWatermark, err := rollupWatermark(ctx, tx, edgeRollupStateKey) + horizon, published, minimum := d.publicationBounds() + sourceMax = published + // Failed attempts advance the horizon without publishing rows. Until the + // first publication, retain the initial watermark so catch-up starts at + // metadata's minimum rather than taking hour-sized steps from the epoch. + if published == 0 { + result = metrics.RollupNoop + updateRollupProgress(metrics.RollupEdge, true, d.rollupWatermarks[edgeRollupStateKey], 0) + return 0, false, nil + } + lastWatermark, err := d.cachedRollupWatermark(ctx, edgeRollupStateKey, horizon) if err != nil { return 0, false, err } watermark = lastWatermark - lastRawMax, err := rollupWatermark(ctx, tx, edgeRollupRawMaxKey) - if err != nil { + if horizon <= lastWatermark { + result = metrics.RollupNoop + updateRollupProgress(metrics.RollupEdge, true, lastWatermark, published) + return 0, false, nil + } + if err := d.lockRollupParquetRead(ctx); err != nil { return 0, false, err } - - rawWatermark, err := maxEdgeRollupWatermark(ctx, tx) + defer d.parquetMu.RUnlock() + tx, err := d.writer().BeginTx(ctx, nil) if err != nil { return 0, false, err } - sourceMax = rawWatermark + defer func() { _ = tx.Rollback() }() // A previous pass that ran out of sub-window budget recorded where to // resume and left the ingested watermark untouched. Reuse that window @@ -965,45 +931,22 @@ func (d *Duck) refreshEdgeRollupPass(ctx context.Context) (int64, bool, error) { } resuming := subCursor > 0 && resumeEnd > lastWatermark - if rawWatermark <= lastWatermark && !resuming { - err := tx.Commit() - if err == nil { - result = metrics.RollupNoop - updateRollupProgress(metrics.RollupEdge, true, lastWatermark, rawWatermark) - } - return 0, false, err - } - minIngested := int64(0) - if lastWatermark == 0 { - if minIngested, err = minEdgeRollupIngested(ctx, tx); err != nil { - return 0, false, err - } - } - windowStart, windowEnd, chunked := rollupWindow(lastWatermark, minIngested, rawWatermark) - // Before the first committed ingest watermark, there are no source rows - // below windowStart. Report that known-empty prefix instead of epoch lag. - watermark = windowStart + windowStart, windowEnd, chunked := rollupWindow(lastWatermark, minimum, horizon) + // An unfinished start-time sub-window keeps its original ingest horizon. + watermark = min(windowStart, windowEnd) if resuming { windowEnd = resumeEnd - chunked = windowEnd < rawWatermark + chunked = windowEnd < horizon } - - // Same chunking + trailing-window logic as the service rollup (see - // refreshServiceRollup): never advance into the lag window below an - // unprocessed tip — chunked or not — and only let the plateau shortcut - // fire once a pass has actually processed up to the recorded raw max. newWatermark := windowEnd - if rawWatermark > lastRawMax { - if guarded := rawWatermark - d.rollupSafetyLagNanos(); newWatermark > guarded { - newWatermark = guarded - } - if newWatermark < lastWatermark { - newWatermark = lastWatermark - } - } - rawMaxProcessed := rawWatermark - if chunked { - rawMaxProcessed = windowEnd + + // Build the incoming/recent-arrival repair relation once in this snapshot. + // Count every affected span per minute so adaptive counting preserves repair + // duplicates without retaining all of their individual rows. + // TEMP is connection-local; creation rolls back on failure, and the table + // is explicitly dropped before commit so no later pass can observe it. + if _, err := tx.ExecContext(ctx, createEdgePassBucketsSQL, windowStart, windowEnd); err != nil { + return 0, false, err } // Query the start_time range that the affected ingested-window spans cover. @@ -1012,13 +955,8 @@ func (d *Duck) refreshEdgeRollupPass(ctx context.Context) (int64, bool, error) { // even when a burst catches up hours of backlog in a single ingested window. var minStartT, maxStartT sql.NullTime err = tx.QueryRowContext(ctx, ` -SELECT - MIN(date_trunc('minute', start_time::TIMESTAMP_NS)), - MAX(date_trunc('minute', start_time::TIMESTAMP_NS)) -FROM spans -WHERE ingested_unix_nano > ? - AND ingested_unix_nano <= ? - AND start_time IS NOT NULL`, windowStart, windowEnd).Scan(&minStartT, &maxStartT) +SELECT MIN(bucket::TIMESTAMP_NS), MAX(bucket::TIMESTAMP_NS) +FROM edge_pass_buckets`).Scan(&minStartT, &maxStartT) if err != nil { return 0, false, err } @@ -1036,31 +974,22 @@ WHERE ingested_unix_nano > ? maxT := maxStartT.Time processed := 0 for !subLo.After(maxT) { - // Stop at a resumable point when the budget is spent, and also when - // a queued publication is about to start refusing readers: this - // pass holds the Parquet snapshot until it commits, so from that - // moment every arriving query waits out whatever is left of it. - // - // The trigger is the grace running out, not a publisher existing. - // While the grace holds, readers are still being admitted and - // nothing is waiting on this pass. - // - // One sub-window is the unit, and the cursor below is what makes - // stopping free. Never before the first, so a pass always makes - // progress and a busy compaction cycle cannot starve the rollup. - if processed == maxEdgeSubWindowsPerPass || (processed > 0 && d.parquetMu.publisherGraceLeft() <= edgeYieldMargin) { + // Release the snapshot at a resumable boundary as soon as a + // publisher waits. Always finish the first sub-window so a busy + // compaction cycle cannot starve the rollup. + if processed == maxEdgeSubWindowsPerPass || (processed > 0 && d.parquetMu.publisherWaiting()) { completed = false nextCursor = subLo.UnixNano() break } - subHi, err := edgeSubWindowEnd(ctx, tx, windowStart, windowEnd, subLo, maxT, maxEdgeSpansPerSubWindow) + subHi, err := edgeSubWindowEnd(ctx, tx, subLo, maxT, maxEdgeSpansPerSubWindow) if err != nil { return 0, false, err } - if _, err := tx.ExecContext(ctx, edgeRollupDeleteSQL, windowStart, windowEnd, subLo, subHi); err != nil { + if _, err := tx.ExecContext(ctx, edgeRollupDeleteSQL, subLo, subHi); err != nil { return 0, false, err } - res, err := tx.ExecContext(ctx, edgeRollupInsertSQL, windowStart, windowEnd, subLo, subHi) + res, err := tx.ExecContext(ctx, edgeRollupInsertSQL, subLo, subHi) if err != nil { return 0, false, err } @@ -1083,9 +1012,6 @@ WHERE ingested_unix_nano > ? if err := storeRollupWatermark(ctx, tx, edgeRollupStateKey, newWatermark); err != nil { return 0, false, err } - if err := storeRollupWatermark(ctx, tx, edgeRollupRawMaxKey, rawMaxProcessed); err != nil { - return 0, false, err - } if err := clearEdgeRollupCursor(ctx, tx); err != nil { return 0, false, err } @@ -1098,16 +1024,17 @@ WHERE ingested_unix_nano > ? return 0, false, err } } + if _, err := tx.ExecContext(ctx, "DROP TABLE edge_pass_buckets"); err != nil { + return 0, false, err + } if err := tx.Commit(); err != nil { return 0, false, err } result = metrics.RollupSuccess recordedRows = totalAffected - updateRollupProgress(metrics.RollupEdge, true, max(storedWatermark, windowStart), rawWatermark) - // A completed source window may intentionally retain the publication lag. - // Leave its plateau shortcut for the next tick rather than consuming that - // safety window immediately in this tick's catch-up loop. + d.rollupWatermarks[edgeRollupStateKey] = storedWatermark + updateRollupProgress(metrics.RollupEdge, true, max(storedWatermark, min(windowStart, windowEnd)), published) return totalAffected, !completed || chunked, nil } @@ -1157,7 +1084,7 @@ const maxEdgeSpansPerSubWindow int64 = 250_000 // enough for version and anomaly writes to get the gate during a backlog. const maxEdgeSubWindowsPerPass = 1 -func edgeSubWindowEnd(ctx context.Context, tx *sql.Tx, windowStart, windowEnd int64, subLo, maxT time.Time, rowLimit int64) (time.Time, error) { +func edgeSubWindowEnd(ctx context.Context, tx *sql.Tx, subLo, maxT time.Time, rowLimit int64) (time.Time, error) { maxEnd := maxT.Add(time.Minute) subHi := subLo.Add(time.Duration(edgeStartChunkNanos)) if subHi.After(maxEnd) { @@ -1166,16 +1093,10 @@ func edgeSubWindowEnd(ctx context.Context, tx *sql.Tx, windowStart, windowEnd in for rowLimit > 0 && subHi.Sub(subLo) > time.Minute { var rows int64 if err := tx.QueryRowContext(ctx, ` -SELECT COUNT(*) -FROM ( - SELECT 1 - FROM spans - WHERE ingested_unix_nano > ? - AND ingested_unix_nano <= ? - AND start_time >= ?::TIMESTAMP_NS::TIMESTAMPTZ_NS - AND start_time < ?::TIMESTAMP_NS::TIMESTAMPTZ_NS - LIMIT ? -)`, windowStart, windowEnd, subLo, subHi, rowLimit+1).Scan(&rows); err != nil { +SELECT COALESCE(SUM(spans), 0)::BIGINT +FROM edge_pass_buckets +WHERE bucket >= $1::TIMESTAMP_NS::TIMESTAMPTZ_NS + AND bucket < $2::TIMESTAMP_NS::TIMESTAMPTZ_NS`, subLo, subHi).Scan(&rows); err != nil { return time.Time{}, err } if rows <= rowLimit { @@ -1218,27 +1139,67 @@ func updateRollupProgress(component metrics.RollupComponent, enabled bool, water metrics.UpdateRollupProgress(component, enabled, watermark, sourceMax, backlogChunks) } -func minServiceRollupIngested(ctx context.Context, tx *sql.Tx) (int64, error) { - var v int64 - err := tx.QueryRowContext(ctx, ` -SELECT COALESCE(MIN(v), 0)::BIGINT -FROM ( - SELECT MIN(ingested_unix_nano) AS v FROM spans - UNION ALL - SELECT MIN(ingested_unix_nano) AS v FROM logs - UNION ALL - SELECT MIN(ingested_unix_nano) AS v FROM metrics -) mins -WHERE v IS NOT NULL`).Scan(&v) - return v, err +// loadRollupWatermarks restores progress at open. Failed attempts can leave +// an empty processed tail beyond the last durable stamp. That tail is not +// persisted in batch metadata, so a backwards clock after restart can reuse it. +// Rewind only that empty tail (and any partial window extending into it) before +// admitting fresh stamps. Affected-bucket recomputation is idempotent. +func (d *Duck) loadRollupWatermarks(ctx context.Context) error { + tx, err := d.writer().BeginTx(ctx, nil) + if err != nil { + return err + } + defer func() { _ = tx.Rollback() }() + horizon, _, _ := d.publicationBounds() + watermarks := make(map[string]int64, 2) + for _, key := range []string{serviceRollupStateKey, edgeRollupStateKey} { + value, err := rollupWatermark(ctx, tx, key) + if err != nil { + return err + } + if value > horizon { + value = horizon + if err := storeRollupWatermark(ctx, tx, key, value); err != nil { + return err + } + } + watermarks[key] = value + } + resumeEnd, err := rollupWatermark(ctx, tx, edgeRollupSubWindowKey) + if err != nil { + return err + } + if resumeEnd > horizon { + if err := clearEdgeRollupCursor(ctx, tx); err != nil { + return err + } + } + if err := tx.Commit(); err != nil { + return err + } + d.rollupWatermarks = watermarks + return nil } -func minEdgeRollupIngested(ctx context.Context, tx *sql.Tx) (int64, error) { - var v int64 - err := tx.QueryRowContext(ctx, ` -SELECT COALESCE(MIN(ingested_unix_nano), 0)::BIGINT -FROM spans`).Scan(&v) - return v, err +// cachedRollupWatermark is called under writeGate. Read persisted progress once; +// after that an idle pass needs neither a connection nor a Parquet snapshot. +func (d *Duck) cachedRollupWatermark(ctx context.Context, key string, horizon int64) (int64, error) { + if d.rollupWatermarks == nil { + d.rollupWatermarks = make(map[string]int64) + } + if value, ok := d.rollupWatermarks[key]; ok { + return value, nil + } + if horizon == 0 { + return 0, nil + } + var value int64 + err := d.writer().QueryRowContext(ctx, `SELECT last_ingested_unix_nano FROM rollup_state WHERE cache_key = ?`, key).Scan(&value) + if err != nil && err != sql.ErrNoRows { + return 0, err + } + d.rollupWatermarks[key] = value + return value, nil } func rollupWatermark(ctx context.Context, tx *sql.Tx, key string) (int64, error) { @@ -1292,35 +1253,6 @@ func serviceRollupQuantileSQL(alias string, index int, column string) string { return fmt.Sprintf("COALESCE(%s[%d], %s[%d]) AS %s", served, index, all, index, column) } -// rollupSafetyLagNanos is how far behind the max ingested timestamp the rollup -// watermark is held, covering the worst-case delay between a row being stamped at -// ingest and committed to Parquet (the bounded commit retry window plus queueing). -func (d *Duck) rollupSafetyLagNanos() int64 { - return d.rollupLagNanos -} - -func maxServiceRollupWatermark(ctx context.Context, tx *sql.Tx) (int64, error) { - var watermark int64 - err := tx.QueryRowContext(ctx, ` -SELECT COALESCE(MAX(v), 0)::BIGINT -FROM ( - SELECT COALESCE(MAX(ingested_unix_nano), 0) AS v FROM spans - UNION ALL - SELECT COALESCE(MAX(ingested_unix_nano), 0) AS v FROM logs - UNION ALL - SELECT COALESCE(MAX(ingested_unix_nano), 0) AS v FROM metrics -) maxes`).Scan(&watermark) - return watermark, err -} - -func maxEdgeRollupWatermark(ctx context.Context, tx *sql.Tx) (int64, error) { - var watermark int64 - err := tx.QueryRowContext(ctx, ` -SELECT COALESCE(MAX(ingested_unix_nano), 0)::BIGINT -FROM spans`).Scan(&watermark) - return watermark, err -} - const serviceRollupDeleteSQL = ` WITH affected AS ( SELECT DISTINCT namespace, date_trunc('minute', start_time::TIMESTAMP_NS) AS bucket, service @@ -1477,16 +1409,69 @@ LEFT JOIN span_agg s USING (namespace, bucket, service) LEFT JOIN log_agg l USING (namespace, bucket, service) LEFT JOIN metric_agg m USING (namespace, bucket, service);` -const edgeRollupDeleteSQL = ` -WITH affected AS ( - SELECT DISTINCT namespace, date_trunc('minute', start_time::TIMESTAMP_NS) AS bucket +// edgeArrivalGap bounds recent-arrival repair behind the completed ingest +// watermark. Older relationships are not guaranteed to be repaired. +const edgeArrivalGap = 5 * time.Minute + +// Only relationship keys are read from the recent ingestion range. Its stamp +// predicates allow Parquet footer pruning independently of event-time history. +// Messaging uses the aggregate's exact keys, including the shared minute. +var createEdgePassBucketsSQL = fmt.Sprintf(` +CREATE TEMP TABLE edge_pass_buckets AS +WITH incoming AS MATERIALIZED ( + SELECT namespace, trace_id, span_id, start_time, kind, + messaging_destination, messaging_system FROM spans - WHERE ingested_unix_nano > ? - AND ingested_unix_nano <= ? + WHERE ingested_unix_nano > $1::BIGINT + AND ingested_unix_nano <= $2::BIGINT AND start_time IS NOT NULL - AND start_time >= ?::TIMESTAMP_NS::TIMESTAMPTZ_NS - AND start_time < ?::TIMESTAMP_NS::TIMESTAMPTZ_NS +), +recent AS MATERIALIZED ( + SELECT namespace, trace_id, parent_span_id, start_time, kind, + messaging_destination, messaging_system + FROM spans + WHERE ingested_unix_nano > ($1::BIGINT - %d) + AND ingested_unix_nano <= $1::BIGINT + AND start_time IS NOT NULL +), +affected_spans AS ( + SELECT namespace, start_time FROM incoming + UNION ALL + SELECT child.namespace, child.start_time + FROM recent child + SEMI JOIN incoming parent + ON child.namespace = parent.namespace + AND child.trace_id = parent.trace_id + AND child.parent_span_id = parent.span_id + UNION ALL + SELECT r.namespace, r.start_time + FROM recent r + SEMI JOIN incoming i + ON r.namespace = i.namespace + AND date_trunc('minute', r.start_time::TIMESTAMP_NS) = date_trunc('minute', i.start_time::TIMESTAMP_NS) + AND r.messaging_destination = i.messaging_destination + AND r.messaging_system = i.messaging_system + AND r.kind = CASE i.kind + WHEN 'SPAN_KIND_PRODUCER' THEN 'SPAN_KIND_CONSUMER' + WHEN 'SPAN_KIND_CONSUMER' THEN 'SPAN_KIND_PRODUCER' END +) +SELECT namespace, + date_trunc('minute', start_time::TIMESTAMP_NS)::TIMESTAMPTZ_NS AS bucket, + COUNT(*) AS spans +FROM affected_spans +GROUP BY namespace, bucket +`, int64(edgeArrivalGap)) + +const edgeAffectedBucketsSQL = ` +WITH affected AS ( + SELECT namespace, bucket::TIMESTAMP_NS AS bucket + FROM edge_pass_buckets + WHERE bucket >= $1::TIMESTAMP_NS::TIMESTAMPTZ_NS + AND bucket < $2::TIMESTAMP_NS::TIMESTAMPTZ_NS ) +` + +const edgeRollupDeleteSQL = edgeAffectedBucketsSQL + ` DELETE FROM edge_rollup WHERE EXISTS ( SELECT 1 @@ -1495,16 +1480,7 @@ WHERE EXISTS ( AND affected.bucket = edge_rollup.bucket );` -const edgeRollupInsertSQL = ` -WITH affected AS ( - SELECT DISTINCT namespace, date_trunc('minute', start_time::TIMESTAMP_NS) AS bucket - FROM spans - WHERE ingested_unix_nano > ? - AND ingested_unix_nano <= ? - AND start_time IS NOT NULL - AND start_time >= ?::TIMESTAMP_NS::TIMESTAMPTZ_NS - AND start_time < ?::TIMESTAMP_NS::TIMESTAMPTZ_NS -), +const edgeRollupInsertSQL = edgeAffectedBucketsSQL + `, -- The affected bucket range, computed once. As four scalar subqueries -- repeated across the predicates below, these read as correlated to the -- planner and cost a re-derivation each. @@ -1843,12 +1819,15 @@ const ( readerStats = "stats" ) -// lockParquetRead admits a reader to the Parquet snapshot and records what the -// wait cost. The publisher's wait was already measured and the reader's was -// not, which is why a multi-second query could not be attributed to anything. +// lockParquetRead records snapshot admission waits. Only ordinary queries use +// the publisher's grace; rollups and stats wait behind queued publishers. func (d *Duck) lockParquetRead(ctx context.Context, reader string) error { start := time.Now() - if err := d.parquetMu.RLockContext(ctx); err != nil { + mode := parquetReadBackground + if reader == readerQuery { + mode = parquetReadQuery + } + if err := d.parquetMu.RLockContext(ctx, mode); err != nil { metrics.RecordParquetRead(reader, time.Since(start).Seconds(), false) return errors.Join(ErrParquetReadWait, err) } @@ -1864,6 +1843,19 @@ func (d *Duck) lockRollupParquetRead(ctx context.Context) error { // ---- Queries for API ---- +// CompletedServiceRollupMinute is the exclusive end of detector input. The +// minute containing the ingest watermark may still be incomplete. +func (d *Duck) CompletedServiceRollupMinute(ctx context.Context) (time.Time, error) { + var stamp int64 + if err := d.QueryRowScan(ctx, []any{&stamp}, `SELECT coalesce((SELECT last_ingested_unix_nano FROM rollup_state WHERE cache_key=?),0)`, serviceRollupStateKey); err != nil { + return time.Time{}, err + } + if stamp == 0 { + return time.Time{}, nil + } + return time.Unix(0, stamp).UTC().Truncate(time.Minute), nil +} + type LatencyRow struct { ServiceName string `json:"service_name"` P95Ms float64 `json:"p95_ms"` diff --git a/internal/query/duck_test.go b/internal/query/duck_test.go index 46313fa6..0bb84d2e 100644 --- a/internal/query/duck_test.go +++ b/internal/query/duck_test.go @@ -183,7 +183,6 @@ func TestNewDuckUsesUTCForEveryConnection(t *testing.T) { }}}); err != nil { t.Fatalf("commit timezone fixture: %v", err) } - d.rollupLagNanos = 0 if _, err := d.rollupOnce(ctx); err != nil { t.Fatalf("roll up timezone fixture: %v", err) } @@ -425,7 +424,7 @@ func TestWaitingMaintenanceDoesNotBlockNewReaders(t *testing.T) { } func TestRollupReadLockHonorsContext(t *testing.T) { - d := &Duck{} + d := &Duck{publicationBounds: func() (int64, int64, int64) { return 2, 2, 1 }, rollupWatermarks: map[string]int64{serviceRollupStateKey: 1}} mustLock(&d.parquetMu) ctx, cancel := context.WithTimeout(context.Background(), 25*time.Millisecond) defer cancel() @@ -446,16 +445,14 @@ func TestRollupAdmissionLeaseDoesNotCancelAdmittedWork(t *testing.T) { rollupReaderLease = 5 * time.Millisecond t.Cleanup(func() { rollupReaderLease = originalLease }) - mock.ExpectBegin() mock.ExpectQuery("FROM rollup_state").WithArgs(serviceRollupStateKey). - WillReturnRows(sqlmock.NewRows([]string{"last_ingested_unix_nano"}).AddRow(100)) - mock.ExpectQuery("FROM rollup_state").WithArgs(serviceRollupRawMaxKey). - WillReturnRows(sqlmock.NewRows([]string{"last_ingested_unix_nano"}).AddRow(100)) - mock.ExpectQuery("FROM \\(").WillDelayFor(20 * time.Millisecond). WillReturnRows(sqlmock.NewRows([]string{"watermark"}).AddRow(100)) + mock.ExpectBegin() + mock.ExpectExec("DELETE FROM service_rollup").WillDelayFor(20 * time.Millisecond).WillReturnResult(sqlmock.NewResult(0, 0)) + mock.ExpectExec("WITH affected").WillReturnResult(sqlmock.NewResult(0, 0)) + mock.ExpectExec("INSERT INTO rollup_state").WillReturnResult(sqlmock.NewResult(0, 1)) mock.ExpectCommit() - - d := &Duck{DB: db, writeDB: db} + d := &Duck{DB: db, writeDB: db, publicationBounds: func() (int64, int64, int64) { return 200, 200, 100 }} if _, err := d.refreshServiceRollup(context.Background()); err != nil { t.Fatalf("admitted rollup was canceled by its admission lease: %v", err) } @@ -519,7 +516,7 @@ func TestRepositoryPublicationDoesNotWaitForDuckDBWrites(t *testing.T) { t.Fatal(err) } defer repository.Close() - if err := repository.Commit(context.Background(), telemetrystore.Batch{ID: "expired", Spans: []telemetry.Span{{TraceID: "trace", IngestedAt: 1}}}); err != nil { + if err := commitRestoredFixture(repository, context.Background(), telemetrystore.Batch{ID: "expired", Spans: []telemetry.Span{{TraceID: "trace", IngestedAt: 1}}}); err != nil { t.Fatal(err) } mock.ExpectExec("DELETE FROM service_rollup").WillReturnResult(sqlmock.NewResult(0, 0)) @@ -640,7 +637,7 @@ func TestMaintenanceRecoversCompactionBeforeRetention(t *testing.T) { Logs: []telemetry.Log{{Body: "old", IngestedAt: 1}}, Metrics: []telemetry.Metric{{Name: "old", IngestedAt: 1}}, } - if err := repository.Commit(context.Background(), batch); err != nil { + if err := commitRestoredFixture(repository, context.Background(), batch); err != nil { t.Fatal(err) } } @@ -758,7 +755,6 @@ func TestFailedRollupStillPublishesLag(t *testing.T) { component: "service", stateReads: []stateRead{ {serviceRollupStateKey, watermarkNanos}, - {serviceRollupRawMaxKey, watermarkNanos}, }, refresh: func(d *Duck, ctx context.Context) (int64, error) { return d.refreshServiceRollup(ctx) }, }, @@ -766,7 +762,6 @@ func TestFailedRollupStillPublishesLag(t *testing.T) { component: "edge", stateReads: []stateRead{ {edgeRollupStateKey, watermarkNanos}, - {edgeRollupRawMaxKey, watermarkNanos}, }, refresh: func(d *Duck, ctx context.Context) (int64, error) { return d.refreshEdgeRollup(ctx) }, }, @@ -781,22 +776,24 @@ func TestFailedRollupStillPublishesLag(t *testing.T) { } defer db.Close() - d := &Duck{DB: db, writeDB: db, cfg: config.Config{}} + d := &Duck{DB: db, writeDB: db, publicationBounds: func() (int64, int64, int64) { return sourceNanos, sourceNanos, 1 }, cfg: config.Config{}} watermarkRows := func(value int64) *sqlmock.Rows { return sqlmock.NewRows([]string{"last_ingested_unix_nano"}).AddRow(value) } - mock.ExpectBegin() for _, read := range tc.stateReads { mock.ExpectQuery("FROM rollup_state").WithArgs(read.key). WillReturnRows(watermarkRows(read.value)) } - mock.ExpectQuery("FROM spans"). - WillReturnRows(sqlmock.NewRows([]string{"v"}).AddRow(sourceNanos)) + mock.ExpectBegin() // Everything past this point fails, so the rollup returns an error // without advancing its watermark. - mock.ExpectQuery("."). - WillReturnError(errors.New("rollup query failed")) + if tc.component == "service" { + mock.ExpectExec(".").WillReturnError(errors.New("rollup query failed")) + } else { + mock.ExpectQuery(".").WillReturnError(errors.New("rollup query failed")) + } + mock.ExpectRollback() if _, err := tc.refresh(d, context.Background()); err == nil { t.Fatalf("refresh %s rollup: error = nil, want the injected failure surfaced", tc.component) diff --git a/internal/query/edge_arrival_test.go b/internal/query/edge_arrival_test.go new file mode 100644 index 00000000..2a7cb049 --- /dev/null +++ b/internal/query/edge_arrival_test.go @@ -0,0 +1,154 @@ +package query + +import ( + "encoding/json" + "fmt" + "strings" + "testing" + "time" + + "github.com/labstack/fanout/internal/telemetry" + telemetrystore "github.com/labstack/fanout/internal/telemetry/store" +) + +func TestEdgeRollupRepairsRelatedArrivals(t *testing.T) { + for _, tc := range []struct { + name string + parentFirst bool + gap time.Duration + want int64 + }{ + {"child first across minute boundary", false, time.Minute, 1}, + {"parent first across minute boundary", true, time.Minute, 1}, + {"child at arrival gap boundary", false, edgeArrivalGap, 1}, + {"child beyond arrival gap", false, edgeArrivalGap + time.Nanosecond, 0}, + } { + t.Run(tc.name, func(t *testing.T) { + d, repo := newBatchCacheTest(t) + base := time.Date(2026, 10, 1, 12, 0, 0, 0, time.UTC) + stamp := base.Add(time.Hour).UnixNano() + first := stamp + d.publicationBounds = func() (int64, int64, int64) { return stamp, stamp, first } + child := telemetry.Span{Namespace: "shop", TraceID: "trace", SpanID: "child", ParentSpanID: "parent", ServiceName: "checkout", StartUnixNanos: base.Add(time.Second).UnixNano()} + parent := telemetry.Span{Namespace: "shop", TraceID: "trace", SpanID: "parent", ServiceName: "gateway", StartUnixNanos: base.Add(-time.Second).UnixNano()} + a, b := child, parent + if tc.parentFirst { + a, b = parent, child + } + commit := func(id string, span telemetry.Span) { + span.IngestedAt = stamp + if err := commitRestoredFixture(repo, t.Context(), telemetrystore.Batch{ID: id, Spans: []telemetry.Span{span}}); err != nil { + t.Fatal(err) + } + } + refresh := func() { + for i := 0; i < 10; i++ { + _, pending, err := d.refreshEdgeRollupPass(t.Context()) + if err != nil { + t.Fatal(err) + } + if !pending { + return + } + } + t.Fatal("edge pass did not converge") + } + commit("first", a) + refresh() + requireRowCount(t, d.DB, "SELECT count(*) FROM edge_rollup WHERE edge_type=?", "call", 0) + // Advance the completed ingest watermark with an unrelated publication. + // The repair horizon is measured from that watermark, not from wall time. + stamp += int64(tc.gap) - 1 + commit("progress", telemetry.Span{Namespace: "other", TraceID: "trace", SpanID: "parent", ServiceName: "unrelated", StartUnixNanos: base.Add(-time.Second).UnixNano()}) + refresh() + stamp++ + commit("second", b) + refresh() + var calls int64 + if err := d.DB.QueryRow(`SELECT coalesce(sum(calls),0) FROM edge_rollup WHERE namespace='shop' AND caller='gateway' AND callee='checkout' AND bucket=?`, base).Scan(&calls); err != nil || calls != tc.want { + t.Fatalf("calls=%d want=%d err=%v", calls, tc.want, err) + } + requireRowCount(t, d.DB, "SELECT count(*) FROM edge_rollup WHERE caller=?", "unrelated", 0) + }) + } +} + +func TestEdgeRollupMessagingArrivalsUseAggregateKeys(t *testing.T) { + for _, producerFirst := range []bool{true, false} { + t.Run(fmt.Sprint("producerFirst=", producerFirst), func(t *testing.T) { + d, repo := newBatchCacheTest(t) + base := time.Now().UTC().Truncate(time.Minute).Add(-time.Hour) + makeSpan := func(kind, service, ns, destination, system string) telemetry.Span { + return telemetry.Span{Namespace: ns, TraceID: service, SpanID: service, ServiceName: service, Kind: kind, StartUnixNanos: base.UnixNano(), Attributes: map[string]any{"messaging.destination.name": destination, "messaging.system": system}} + } + producer := makeSpan("SPAN_KIND_PRODUCER", "publisher", "shop", "jobs", "kafka") + consumer := makeSpan("SPAN_KIND_CONSUMER", "worker", "shop", "jobs", "kafka") + first, second := producer, consumer + if !producerFirst { + first, second = consumer, producer + } + commit := func(id string, spans ...telemetry.Span) { + if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: id, Spans: spans}); err != nil { + t.Fatal(err) + } + if _, _, err := d.refreshEdgeRollupPass(t.Context()); err != nil { + t.Fatal(err) + } + } + commit("first", first) + commit("second", second, makeSpan("SPAN_KIND_PRODUCER", "wrong-namespace", "other", "jobs", "kafka"), makeSpan("SPAN_KIND_PRODUCER", "wrong-destination", "shop", "elsewhere", "kafka"), makeSpan("SPAN_KIND_PRODUCER", "wrong-system", "shop", "jobs", "other")) + requireRowCount(t, d.DB, `SELECT count(*) FROM edge_rollup WHERE namespace='shop' AND caller='publisher' AND callee='worker' AND calls=1 AND edge_type=?`, "messaging", 1) + requireRowCount(t, d.DB, `SELECT count(*) FROM edge_rollup WHERE caller LIKE ?`, "wrong-%", 0) + }) + } +} + +func TestEdgeArrivalLookupPrunesOldParquetAndReadsKeys(t *testing.T) { + d, repo := newBatchCacheTest(t) + at := time.Now().UTC().Truncate(time.Minute) + watermark := at.UnixNano() + for i, stamp := range []int64{watermark - int64(6*time.Minute), watermark - int64(time.Minute), watermark + 1} { + span := telemetry.Span{Namespace: "ns", TraceID: "trace", SpanID: fmt.Sprint(i), ParentSpanID: "2", ServiceName: "api", StartUnixNanos: at.UnixNano(), IngestedAt: stamp} + if err := commitRestoredFixture(repo, t.Context(), telemetrystore.Batch{ID: fmt.Sprint("batch-", i), Spans: []telemetry.Span{span}}); err != nil { + t.Fatal(err) + } + } + var key, plan string + if err := d.DB.QueryRow("EXPLAIN (ANALYZE, FORMAT JSON) "+createEdgePassBucketsSQL, watermark, watermark+1).Scan(&key, &plan); err != nil { + t.Fatal(err) + } + var profile any + if err := json.Unmarshal([]byte(plan), &profile); err != nil { + t.Fatal(err) + } + var recent map[string]any + var visit func(any) + visit = func(v any) { + switch x := v.(type) { + case map[string]any: + if x["type"] == "TABLE_SCAN" { + extra := x["extra_info"].(map[string]any) + cols := fmt.Sprint(extra["Projections"]) + if strings.Contains(cols, "parent_span_id") { + recent = x + for _, unrelated := range []string{"duration", "status", "resource", "service", "body"} { + if strings.Contains(cols, unrelated) { + t.Fatalf("repair lookup reads non-key column %q: %s", unrelated, cols) + } + } + } + } + for _, child := range x { + visit(child) + } + case []any: + for _, child := range x { + visit(child) + } + } + } + visit(profile) + if recent == nil || recent["row_groups_scanned"] != float64(1) || recent["total_row_groups_to_scan"] != float64(3) { + t.Fatalf("recent ingestion lookup did not prune two unrelated groups: %+v", recent) + } +} diff --git a/internal/query/edge_backlog_test.go b/internal/query/edge_backlog_test.go index b570b173..af313136 100644 --- a/internal/query/edge_backlog_test.go +++ b/internal/query/edge_backlog_test.go @@ -28,7 +28,7 @@ func TestEdgeRollupBacklog(t *testing.T) { } d := &Duck{ - DB: db, writeDB: db, + DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30, DuckDBMemory: "1GB"}, } ctx := context.Background() @@ -263,7 +263,7 @@ func TestEdgeRollupBoundsSubWindowsPerPass(t *testing.T) { if err := CreateViews(db); err != nil { t.Fatalf("CreateViews: %v", err) } - d := &Duck{DB: db, writeDB: db, cfg: config.Config{RetentionDays: 30, DuckDBMemory: "1GB"}} + d := &Duck{DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30, DuckDBMemory: "1GB"}} ctx := context.Background() // One ingested instant, but start_time spread over 600 minutes: 20 @@ -394,7 +394,10 @@ WHERE ingested_unix_nano > ? AND ingested_unix_nano <= ?`, ingested-1, ingested) t.Fatal(err) } defer func() { _ = tx.Rollback() }() - subHi, err := edgeSubWindowEnd(ctx, tx, ingested-1, ingested, base, base.Add(29*time.Minute), 10) + if _, err := tx.ExecContext(ctx, createEdgePassBucketsSQL, ingested-1, ingested); err != nil { + t.Fatal(err) + } + subHi, err := edgeSubWindowEnd(ctx, tx, base, base.Add(29*time.Minute), 10) if err != nil { t.Fatal(err) } diff --git a/internal/query/edge_pass_test.go b/internal/query/edge_pass_test.go new file mode 100644 index 00000000..9e754cf3 --- /dev/null +++ b/internal/query/edge_pass_test.go @@ -0,0 +1,148 @@ +package query + +import ( + "testing" + "time" +) + +func TestEdgePassBucketsPreserveRepairCounts(t *testing.T) { + db := openTestDuck(t) + at := time.Date(2026, 10, 1, 12, 0, 0, 0, time.UTC) + if _, err := db.Exec(`CREATE TABLE spans AS + SELECT namespace,trace_id,span_id,parent_span_id,start_time::TIMESTAMPTZ_NS AS start_time, + kind,messaging_destination,messaging_system,ingested_unix_nano + FROM (VALUES + ('ns','trace','child','parent',?::TIMESTAMP_NS,'SPAN_KIND_CONSUMER','jobs','kafka',100), + ('ns','trace','parent','',?::TIMESTAMP_NS,'SPAN_KIND_PRODUCER','jobs','kafka',101), + ('ns','other','other','',?::TIMESTAMP_NS,'SPAN_KIND_SERVER',NULL,NULL,101) + ) s(namespace,trace_id,span_id,parent_span_id,start_time,kind,messaging_destination,messaging_system,ingested_unix_nano)`, + at.Add(time.Nanosecond), at.Add(2*time.Nanosecond), at.Add(time.Minute+3*time.Nanosecond)); err != nil { + t.Fatal(err) + } + tx, err := db.BeginTx(t.Context(), nil) + if err != nil { + t.Fatal(err) + } + defer tx.Rollback() + if _, err := tx.ExecContext(t.Context(), createEdgePassBucketsSQL, 100, 101); err != nil { + t.Fatal(err) + } + // The recent child matches both repairs. Round 5 counted it twice in + // adaptive probes; the bucket counts must retain that multiplicity. + var buckets, spans int64 + if err := tx.QueryRow("SELECT count(*), sum(spans)::BIGINT FROM edge_pass_buckets").Scan(&buckets, &spans); err != nil || buckets != 2 || spans != 4 { + t.Fatalf("buckets=%d spans=%d err=%v", buckets, spans, err) + } + // Later probes consume only the materialized relation, even without source. + if _, err := tx.Exec("DROP TABLE spans"); err != nil { + t.Fatal(err) + } + hi, err := edgeSubWindowEnd(t.Context(), tx, at, at.Add(time.Minute), 3) + if err != nil || !hi.Equal(at.Add(time.Minute)) { + t.Fatalf("sub-window end=%s err=%v", hi, err) + } +} + +func TestEdgePassRelationIsPrivateAndRollsBack(t *testing.T) { + db := openTestDuck(t) + db.SetMaxOpenConns(2) + if err := CreateTables(db); err != nil { + t.Fatal(err) + } + if err := CreateViews(db); err != nil { + t.Fatal(err) + } + conn, err := db.Conn(t.Context()) + if err != nil { + t.Fatal(err) + } + defer conn.Close() + tx, err := conn.BeginTx(t.Context(), nil) + if err != nil { + t.Fatal(err) + } + defer tx.Rollback() + if _, err := tx.ExecContext(t.Context(), createEdgePassBucketsSQL, 0, 1); err != nil { + t.Fatal(err) + } + // Another connection shares the durable schema, but cannot see pass state. + var count int + if err := db.QueryRow("SELECT count(*) FROM spans").Scan(&count); err != nil { + t.Fatal(err) + } + if err := db.QueryRow("SELECT count(*) FROM edge_pass_buckets").Scan(&count); err == nil { + t.Fatal("pass relation visible outside its connection") + } + if err := tx.Rollback(); err != nil { + t.Fatal(err) + } + if err := conn.QueryRowContext(t.Context(), "SELECT count(*) FROM edge_pass_buckets").Scan(&count); err == nil { + t.Fatal("rollback retained pass relation on its connection") + } +} + +func TestEdgePassDropsRelationOnEveryExit(t *testing.T) { + for _, empty := range []bool{false, true} { + name := "resume and retry" + if empty { + name = "empty window" + } + t.Run(name, func(t *testing.T) { + db := openTestDuck(t) + if err := CreateTables(db); err != nil { + t.Fatal(err) + } + if err := CreateViews(db); err != nil { + t.Fatal(err) + } + at := time.Date(2026, 10, 1, 12, 0, 0, 0, time.UTC) + stamp := at.UnixNano() + if !empty { + if _, err := db.Exec(`INSERT INTO telemetry.spans + (namespace,trace_id,span_id,service,start_time,start_unix_nano,ingested_at,ingested_unix_nano) + VALUES ('ns','a','a','api',?::TIMESTAMP_NS::TIMESTAMPTZ_NS,?,?,?), + ('ns','b','b','api',?::TIMESTAMP_NS::TIMESTAMPTZ_NS,?,?,?)`, + at, at.UnixNano(), at, stamp, + at.Add(31*time.Minute), at.Add(31*time.Minute).UnixNano(), at, stamp); err != nil { + t.Fatal(err) + } + } + d := &Duck{DB: db, writeDB: db, publicationBounds: func() (int64, int64, int64) { return stamp, stamp, stamp }} + checkAbsent := func() { + var count int + if err := db.QueryRow("SELECT count(*) FROM duckdb_tables() WHERE table_name='edge_pass_buckets'").Scan(&count); err != nil || count != 0 { + t.Fatalf("pass relation survived: count=%d err=%v", count, err) + } + } + if !empty { + // Fail after materialization, then retry on the same SQL connection. + if _, err := db.Exec("ALTER TABLE edge_rollup RENAME TO saved_edge_rollup"); err != nil { + t.Fatal(err) + } + if _, _, err := d.refreshEdgeRollupPass(t.Context()); err == nil { + t.Fatal("missing rollup table did not fail the pass") + } + checkAbsent() + if watermark, cursor := readEdgeRollupState(t, d); watermark != 0 || cursor != 0 { + t.Fatalf("failed pass advanced state: watermark=%d cursor=%d", watermark, cursor) + } + if _, err := db.Exec("ALTER TABLE saved_edge_rollup RENAME TO edge_rollup"); err != nil { + t.Fatal(err) + } + } + if _, pending, err := d.refreshEdgeRollupPass(t.Context()); err != nil || pending == empty { + t.Fatalf("first pass pending=%v err=%v", pending, err) + } + checkAbsent() + if !empty { + if _, pending, err := d.refreshEdgeRollupPass(t.Context()); err != nil || pending { + t.Fatalf("resumed pass pending=%v err=%v", pending, err) + } + checkAbsent() + } + if watermark, cursor := readEdgeRollupState(t, d); watermark != stamp || cursor != 0 { + t.Fatalf("completed state: watermark=%d cursor=%d", watermark, cursor) + } + }) + } +} diff --git a/internal/query/edge_rollup_plan_test.go b/internal/query/edge_rollup_plan_test.go index 959d8b62..357842ff 100644 --- a/internal/query/edge_rollup_plan_test.go +++ b/internal/query/edge_rollup_plan_test.go @@ -36,7 +36,10 @@ func TestEdgeRollupPlanUsesHashJoins(t *testing.T) { spanLo := time.Date(2026, 8, 1, 0, 0, 0, 0, time.UTC) spanHi := time.Date(2026, 10, 1, 0, 0, 0, 0, time.UTC) - shippedPlan := explain(t, db, edgeRollupInsertSQL, windowLo, windowHi, spanLo, spanHi) + if _, err := db.Exec(createEdgePassBucketsSQL, windowLo, windowHi); err != nil { + t.Fatal(err) + } + shippedPlan := explain(t, db, edgeRollupInsertSQL, spanLo, spanHi) // DuckDB 2 optimizes the historical comma form too. Guard the shipped plan // directly rather than requiring the optimizer to retain an old defect. @@ -59,13 +62,16 @@ func TestEdgeRollupPlanUsesHashJoins(t *testing.T) { // asserted: the ratios are consistent but the absolute numbers are not // stable enough across machines to fail a build on. var want []string - for _, form := range []struct{ name, sql string }{ - {"shipped", edgeRollupInsertSQL}, - {"comma", commaForm}, - {"pre-fix (range predicate in the ON clause)", string(preFix)}, + for _, form := range []struct { + name, sql string + args []any + }{ + {"shipped", edgeRollupInsertSQL, []any{spanLo, spanHi}}, + {"comma", commaForm, []any{spanLo, spanHi}}, + {"pre-fix (range predicate in the ON clause)", string(preFix), []any{windowLo, windowHi, spanLo, spanHi}}, } { start := time.Now() - edges := runEdgeRollup(t, db, form.sql, windowLo, windowHi, spanLo, spanHi) + edges := runEdgeRollup(t, db, form.sql, form.args...) t.Logf("%-44s %6.0fms %d edges", form.name, float64(time.Since(start).Microseconds())/1000, len(edges)) if want == nil { if len(edges) == 0 { @@ -252,7 +258,10 @@ func TestEdgeRollupParentTraceScope(t *testing.T) { t.Fatal(err) } lo := time.Date(2026, 9, 20, 12, 0, 0, 0, time.UTC) - if _, err := db.Exec(edgeRollupInsertSQL, 50, 200, lo, lo.Add(time.Minute)); err != nil { + if _, err := db.Exec(createEdgePassBucketsSQL, 50, 200); err != nil { + t.Fatal(err) + } + if _, err := db.Exec(edgeRollupInsertSQL, lo, lo.Add(time.Minute)); err != nil { t.Fatal(err) } var namespace, caller, callee, edgeType string diff --git a/internal/query/edge_tick_test.go b/internal/query/edge_tick_test.go index 6a3cb5da..f00cda87 100644 --- a/internal/query/edge_tick_test.go +++ b/internal/query/edge_tick_test.go @@ -33,13 +33,12 @@ func TestEdgeRollupTickDrainsMultiHourBacklog(t *testing.T) { } watermark, cursor := readEdgeRollupState(t, d) source := now.Add(-4*time.Hour + 11*step).UnixNano() - want := source - d.rollupSafetyLagNanos() + want := source - int64(0) if cursor != 0 || watermark != want { t.Fatalf("one tick did not drain the backlog: watermark=%d cursor=%d want=%d", watermark, cursor, want) } assertBacklogEdges(t, d) - // The unchanged plateau rule completes the safety-lag tail on the - // next tick, rather than bypassing the lag inside this tick. + // An unchanged publication horizon makes the next tick idle. if _, err := d.rollupOnce(t.Context()); err != nil { t.Fatal(err) } @@ -107,7 +106,7 @@ func TestEdgeRollupTickReleasesGateBetweenSubWindows(t *testing.T) { t.Fatalf("tick did not advance many passes: rows=%d passes=%d err=%v", n, passes, err) } watermark, cursor := readEdgeRollupState(t, d) - if watermark != now.UnixNano()-d.rollupSafetyLagNanos() || cursor != 0 { + if watermark != now.UnixNano()-int64(0) || cursor != 0 { t.Fatalf("tick left a backlog: watermark=%d cursor=%d", watermark, cursor) } assertBacklogEdges(t, d) @@ -159,7 +158,7 @@ func TestEdgeRollupTickContinuesPastEmptyPendingPass(t *testing.T) { } } -func TestEdgeRollupTickPreservesPublicationLag(t *testing.T) { +func TestEdgeRollupTickPicksUpRestampedLateChild(t *testing.T) { d, repo := versionEngine(t) d.cfg.RollupInterval = time.Minute now := time.Now().UTC().Truncate(time.Minute) @@ -168,8 +167,8 @@ func TestEdgeRollupTickPreservesPublicationLag(t *testing.T) { t.Fatal(err) } watermark, cursor := readEdgeRollupState(t, d) - if want := now.UnixNano() - d.rollupSafetyLagNanos(); watermark != want || cursor != 0 { - t.Fatalf("tick consumed the publication lag: watermark=%d cursor=%d want=%d", watermark, cursor, want) + if want := now.UnixNano() - int64(0); watermark != want || cursor != 0 { + t.Fatalf("tick did not reach the horizon: watermark=%d cursor=%d want=%d", watermark, cursor, want) } base := now.Add(-3 * time.Hour).UnixNano() if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "late-edge", Spans: []telemetry.Span{{Namespace: "ns-a", ServiceName: "late-child", TraceID: "0", SpanID: "late", ParentSpanID: "s0", Kind: "SPAN_KIND_CLIENT", StartUnixNanos: base, EndUnixNanos: base + int64(time.Millisecond), DurationMS: 1, IngestedAt: now.Add(-time.Second).UnixNano()}}}); err != nil { diff --git a/internal/query/file_snapshot_test.go b/internal/query/file_snapshot_test.go index a30abaa7..d96512e4 100644 --- a/internal/query/file_snapshot_test.go +++ b/internal/query/file_snapshot_test.go @@ -154,7 +154,7 @@ func TestBatchCachesStayExactThroughCompactionAndRetention(t *testing.T) { at := time.Now().UTC().Truncate(time.Hour) for i := range 8 { n := at.Add(time.Duration(i) * time.Second).UnixNano() - if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: fmt.Sprint("part", i), Spans: []telemetry.Span{{Namespace: "prod", ServiceName: "api", TraceID: "trace", SpanID: fmt.Sprint(i), StartUnixNanos: n, EndUnixNanos: n + 1, IngestedAt: at.UnixNano()}}, Logs: []telemetry.Log{{Namespace: "prod", TimeUnixNanos: n, IngestedAt: at.UnixNano()}}}); err != nil { + if err := commitRestoredFixture(repo, t.Context(), telemetrystore.Batch{ID: fmt.Sprint("part", i), Spans: []telemetry.Span{{Namespace: "prod", ServiceName: "api", TraceID: "trace", SpanID: fmt.Sprint(i), StartUnixNanos: n, EndUnixNanos: n + 1, IngestedAt: at.UnixNano()}}, Logs: []telemetry.Log{{Namespace: "prod", TimeUnixNanos: n, IngestedAt: at.UnixNano()}}}); err != nil { t.Fatal(err) } } @@ -264,10 +264,14 @@ func TestFailedBatchCacheTransactionPublishesNoContributions(t *testing.T) { func TestReadCacheWorkerAcknowledgesNewFilesWithoutRollupTick(t *testing.T) { d, repo := newBatchCacheTest(t) + release := d.writeGate.Lock(writegate.WriteRollupService) + defer release() ctx, cancel := context.WithCancel(t.Context()) done := make(chan struct{}) + versionDone := make(chan struct{}) + go func() { defer close(versionDone); d.runVersionRollupLoop(ctx) }() go func() { defer close(done); d.runReadCacheLoop(ctx) }() - t.Cleanup(func() { cancel(); <-done }) + t.Cleanup(func() { cancel(); <-done; <-versionDone }) if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "new", Logs: []telemetry.Log{{TimeUnixNanos: 1, IngestedAt: 1}}}); err != nil { t.Fatal(err) } @@ -285,6 +289,23 @@ func TestReadCacheWorkerAcknowledgesNewFilesWithoutRollupTick(t *testing.T) { t.Fatal(err) } if count == 1 { + // Let the version worker reach its blocked pass, then publish + // another file that requires a later read-cache pass. + time.Sleep(1100 * time.Millisecond) + if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "second", Logs: []telemetry.Log{{TimeUnixNanos: 2}}}); err != nil { + t.Fatal(err) + } + until := time.Now().Add(3 * time.Second) + for time.Now().Before(until) { + if err := d.DB.QueryRow(`SELECT count(*) FROM read_batches`).Scan(&count); err != nil { + t.Fatal(err) + } + if count == 2 { + return + } + time.Sleep(10 * time.Millisecond) + } + t.Fatal("blocked version pass delayed the next read-cache pass") return } } @@ -407,9 +428,9 @@ func TestPreparedReplacementDoesNotHoldCacheWriteGate(t *testing.T) { if _, err := d.RefreshReadCaches(t.Context()); err != nil { t.Fatal(err) } - // Pin a reader so publication has to drain. The worker must still be able to - // acknowledge new ingest and must not collect the prepared output marker. - if err := d.parquetMu.RLockContext(t.Context()); err != nil { + // Pin a reader so publication has to drain. Preparation must release the + // cache write gate; new cache passes skip until the publisher is gone. + if err := d.parquetMu.RLockContext(t.Context(), parquetReadQuery); err != nil { t.Fatal(err) } defer d.parquetMu.RUnlock() @@ -436,14 +457,20 @@ func TestPreparedReplacementDoesNotHoldCacheWriteGate(t *testing.T) { if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "new-input", Logs: []telemetry.Log{{TimeUnixNanos: 2, IngestedAt: 2}}}); err != nil { t.Fatal(err) } + waitForQueuedWriter(t, &d.parquetMu) passCtx, stop := context.WithTimeout(t.Context(), time.Second) defer stop() + unlock, err := d.cacheGate.LockContext(passCtx, writegate.WriteReadCache) + if err != nil { + t.Fatalf("preparation held cache gate behind publication: %v", err) + } + unlock() if _, err := d.RefreshReadCaches(passCtx); err != nil { t.Fatalf("worker blocked behind publication: %v", err) } markers, err := batchMarkers(t.Context(), d.DB) - if err != nil || !markers["output"] || !markers["new-input"] { - t.Fatalf("prepared output/new ingest lost: %v %v", markers, err) + if err != nil || !markers["output"] || markers["new-input"] { + t.Fatalf("prepared output lost or cache entered ahead of publisher: %v %v", markers, err) } cancel() if err := <-done; err == nil { @@ -453,8 +480,8 @@ func TestPreparedReplacementDoesNotHoldCacheWriteGate(t *testing.T) { t.Fatal(err) } markers, err = batchMarkers(t.Context(), d.DB) - if err != nil || markers["output"] { - t.Fatalf("failed output was not collected: %v %v", markers, err) + if err != nil || markers["output"] || !markers["new-input"] { + t.Fatalf("cache did not collect failed output and acknowledge new ingest: %v %v", markers, err) } } @@ -462,11 +489,11 @@ func TestRetiredTraceRepairsOnlyItsActiveScopeAndBounds(t *testing.T) { d, repo := newBatchCacheTest(t) at := time.Now().UTC().Truncate(time.Hour) old := at.Add(-2 * time.Hour).UnixNano() - if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "retire-scope", Spans: []telemetry.Span{{Namespace: "gone", ServiceName: "retired", TraceID: "shared", StartUnixNanos: old, EndUnixNanos: old + 1, StatusCode: "ERROR", IngestedAt: old}}}); err != nil { + if err := commitRestoredFixture(repo, t.Context(), telemetrystore.Batch{ID: "retire-scope", Spans: []telemetry.Span{{Namespace: "gone", ServiceName: "retired", TraceID: "shared", StartUnixNanos: old, EndUnixNanos: old + 1, StatusCode: "ERROR", IngestedAt: old}}}); err != nil { t.Fatal(err) } now := at.UnixNano() - if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "keep-scope", Spans: []telemetry.Span{ + if err := commitRestoredFixture(repo, t.Context(), telemetrystore.Batch{ID: "keep-scope", Spans: []telemetry.Span{ {Namespace: "prod", ServiceName: "api", TraceID: "shared", StartUnixNanos: now, EndUnixNanos: now + 1, IngestedAt: now}, {Namespace: "prod", ServiceName: "api", TraceID: "winner", StartUnixNanos: now, EndUnixNanos: now + 1000, IngestedAt: now}, }}); err != nil { diff --git a/internal/query/parquet_gate.go b/internal/query/parquet_gate.go index 2ec1cb7c..9670160d 100644 --- a/internal/query/parquet_gate.go +++ b/internal/query/parquet_gate.go @@ -7,7 +7,7 @@ import ( "time" ) -// defaultWriterGrace bounds how long readers may keep entering ahead of a +// defaultWriterGrace bounds how long query readers may keep entering ahead of a // waiting publisher. Long enough that ordinary dashboard traffic never queues // behind maintenance, short enough that retention and compaction always run. const defaultWriterGrace = 30 * time.Second @@ -21,12 +21,20 @@ var rollupReaderLease = defaultWriterGrace / 2 // ErrParquetReadWait distinguishes publication contention from a query error. var ErrParquetReadWait = errors.New("wait for Parquet publication") +type parquetReadMode uint8 + +const ( + parquetReadQuery parquetReadMode = iota + parquetReadBackground +) + // parquetReadGate protects Parquet file publication without sync.RWMutex's // unconditional writer preference. Queuing maintenance must not stall // unrelated API reads or readiness probes, so readers continue to be admitted // while a publisher waits — but only until that publisher's grace period // expires, after which new readers queue so retention and compaction cannot be -// starved by overlapping query traffic. +// starved by overlapping query traffic. Background readers always yield to +// queued publishers so repeated passes cannot extend publication's wait. type parquetReadGate struct { once sync.Once mu sync.Mutex @@ -67,62 +75,44 @@ func (g *parquetReadGate) grace() time.Duration { return defaultWriterGrace } -// admitsReaderLocked reports whether a new reader may enter. A reader is -// refused once a publisher is active, or once the longest-waiting publisher -// has been queued for longer than the grace period. -func (g *parquetReadGate) admitsReaderLocked() bool { +// admitsReaderLocked gives only query readers the waiting publisher's grace. +func (g *parquetReadGate) admitsReaderLocked(mode parquetReadMode) bool { if g.writer { return false } if len(g.waiting) == 0 { return true } + if mode == parquetReadBackground { + return false + } return g.clock().Sub(g.waiting[0].queuedAt) < g.grace() } -// publisherGraceLeft reports how long the oldest queued publication may still -// be kept waiting before the gate starts refusing new readers. -// -// A long-running internal reader asks between units of work, so it can stop at -// a resumable point rather than make every query behind it wait out the rest -// of its pass. It is the remaining grace and not the mere presence of a -// publisher that matters: while the grace holds, readers are still being -// admitted and nothing is blocked, so yielding then would give up throughput -// to relieve congestion that does not exist yet. -// -// Zero means a publication is holding the gate, or has waited out its grace -// and new readers are already queuing. With nothing queued, the full grace. -func (g *parquetReadGate) publisherGraceLeft() time.Duration { +// publisherWaiting lets resumable internal readers release their snapshot +// promptly, even while ordinary readers are still admitted during the grace. +func (g *parquetReadGate) publisherWaiting() bool { g.init() g.mu.Lock() defer g.mu.Unlock() - if g.writer { - return 0 - } - if len(g.waiting) == 0 { - return g.grace() - } - if left := g.grace() - g.clock().Sub(g.waiting[0].queuedAt); left > 0 { - return left - } - return 0 + return len(g.waiting) > 0 } -func (g *parquetReadGate) TryRLock() bool { +func (g *parquetReadGate) TryRLock(mode parquetReadMode) bool { g.init() g.mu.Lock() defer g.mu.Unlock() - if !g.admitsReaderLocked() { + if !g.admitsReaderLocked(mode) { return false } g.readers++ return true } -func (g *parquetReadGate) RLockContext(ctx context.Context) error { +func (g *parquetReadGate) RLockContext(ctx context.Context, mode parquetReadMode) error { g.init() g.mu.Lock() - for !g.admitsReaderLocked() { + for !g.admitsReaderLocked(mode) { changed := g.changed g.mu.Unlock() select { diff --git a/internal/query/parquet_gate_test.go b/internal/query/parquet_gate_test.go index db1c260f..50a08eaf 100644 --- a/internal/query/parquet_gate_test.go +++ b/internal/query/parquet_gate_test.go @@ -4,6 +4,7 @@ import ( "context" "errors" "sync" + "sync/atomic" "testing" "time" ) @@ -33,7 +34,7 @@ func TestParquetGateRemovesCanceledPublisher(t *testing.T) { t.Fatalf("canceled publisher remained queued: %d", got) } gate.RUnlock() - if !gate.TryRLock() { + if !gate.TryRLock(parquetReadQuery) { t.Fatal("canceled publisher continued blocking readers") } gate.RUnlock() @@ -76,13 +77,13 @@ func waitForQueuedWriters(t *testing.T, gate *parquetReadGate, count int) { func TestParquetGateAdmitsReadersWhileWriterGraceRuns(t *testing.T) { clock := &fakeClock{now: time.Date(2026, 8, 26, 12, 0, 0, 0, time.UTC)} gate := &parquetReadGate{now: clock.Now} - if !gate.TryRLock() { + if !gate.TryRLock(parquetReadQuery) { t.Fatal("first reader was not admitted") } go mustLock(gate) waitForQueuedWriter(t, gate) clock.Advance(defaultWriterGrace / 2) - if !gate.TryRLock() { + if !gate.TryRLock(parquetReadQuery) { t.Fatal("reader refused while the publisher was still inside its grace period") } gate.RUnlock() @@ -92,13 +93,13 @@ func TestParquetGateAdmitsReadersWhileWriterGraceRuns(t *testing.T) { func TestParquetGateQueuesReadersOnceWriterGraceExpires(t *testing.T) { clock := &fakeClock{now: time.Date(2026, 8, 26, 12, 0, 0, 0, time.UTC)} gate := &parquetReadGate{now: clock.Now} - if !gate.TryRLock() { + if !gate.TryRLock(parquetReadQuery) { t.Fatal("first reader was not admitted") } go mustLock(gate) waitForQueuedWriter(t, gate) clock.Advance(defaultWriterGrace + time.Second) - if gate.TryRLock() { + if gate.TryRLock(parquetReadQuery) { gate.RUnlock() gate.RUnlock() t.Fatal("reader admitted past an expired publisher grace; maintenance can starve indefinitely") @@ -118,7 +119,7 @@ func TestParquetGatePublishesAfterOverlappingReadersDrain(t *testing.T) { }() waitForQueuedWriter(t, gate) // Overlapping traffic keeps arriving, but only within the grace period. - if !gate.TryRLock() { + if !gate.TryRLock(parquetReadQuery) { t.Fatal("reader refused inside the grace period") } clock.Advance(defaultWriterGrace + time.Second) @@ -131,6 +132,118 @@ func TestParquetGatePublishesAfterOverlappingReadersDrain(t *testing.T) { } } +func TestParquetGateBackgroundArrivalsYieldDuringQueryGrace(t *testing.T) { + clock := &fakeClock{now: time.Now()} + gate := &parquetReadGate{now: clock.Now} + for range 3 { + if !gate.TryRLock(parquetReadBackground) { + t.Fatal("idle gate refused background work") + } + } + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + acquired := make(chan error, 1) + release := make(chan struct{}) + defer close(release) + go func() { + err := gate.LockContext(ctx) + acquired <- err + if err == nil { + <-release + gate.Unlock() + } + }() + waitForQueuedWriter(t, gate) + var admitted atomic.Int64 + var wg sync.WaitGroup + defer wg.Wait() + stop := make(chan struct{}) + defer close(stop) + // Keep trying while the publisher is both waiting and active. + for range 4 { + attempted := make(chan struct{}) + wg.Go(func() { + ticker := time.NewTicker(time.Millisecond) + defer ticker.Stop() + first := true + for { + if gate.TryRLock(parquetReadBackground) { + admitted.Add(1) + gate.RUnlock() + } + if first { + close(attempted) + first = false + } + select { + case <-stop: + return + case <-ticker.C: + } + } + }) + <-attempted + } + for range 10 { + if !gate.TryRLock(parquetReadQuery) { + t.Fatal("ordinary reader refused inside the publisher's grace") + } + gate.RUnlock() + } + for range 3 { + gate.RUnlock() + } + select { + case err := <-acquired: + if err != nil { + t.Fatal(err) + } + case <-time.After(time.Second): + t.Fatal("publisher did not acquire after in-flight background readers drained") + } + if gate.TryRLock(parquetReadBackground) { + gate.RUnlock() + t.Fatal("background reader entered during publication") + } + if got := admitted.Load(); got != 0 { + t.Fatalf("background arrivals admitted ahead of publisher: %d", got) + } +} + +func TestParquetGateBackgroundWaitResumesAfterPublisherCancellation(t *testing.T) { + var gate parquetReadGate + mustRLock(t, &gate) + defer gate.RUnlock() + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + publisher := make(chan error, 1) + go func() { publisher <- gate.LockContext(ctx) }() + waitForQueuedWriter(t, &gate) + waitCtx, stop := context.WithTimeout(t.Context(), 20*time.Millisecond) + defer stop() + if err := gate.RLockContext(waitCtx, parquetReadBackground); !errors.Is(err, context.DeadlineExceeded) { + if err == nil { + gate.RUnlock() + } + t.Fatalf("background admission with publisher queued: %v", err) + } + background := make(chan error, 1) + go func() { background <- gate.RLockContext(t.Context(), parquetReadBackground) }() + cancel() + if err := <-publisher; !errors.Is(err, context.Canceled) { + t.Fatalf("publisher cancellation: %v", err) + } + select { + case err := <-background: + if err != nil { + t.Fatal(err) + } + gate.RUnlock() + case <-time.After(time.Second): + t.Fatal("background reader did not resume after publisher canceled") + } +} + func TestParquetGateDistinguishesWritersQueuedAtSameInstant(t *testing.T) { clock := &fakeClock{now: time.Date(2026, 8, 26, 12, 0, 0, 0, time.UTC)} gate := &parquetReadGate{now: clock.Now} @@ -163,7 +276,7 @@ func TestParquetGateDistinguishesWritersQueuedAtSameInstant(t *testing.T) { time.Sleep(time.Millisecond) } deadline = time.Now().Add(time.Second) - for !gate.TryRLock() { + for !gate.TryRLock(parquetReadQuery) { if time.Now().After(deadline) { t.Fatal("reader refused after both publishers completed") } @@ -174,7 +287,7 @@ func TestParquetGateDistinguishesWritersQueuedAtSameInstant(t *testing.T) { func mustRLock(t *testing.T, gate *parquetReadGate) { t.Helper() - if err := gate.RLockContext(context.Background()); err != nil { + if err := gate.RLockContext(context.Background(), parquetReadQuery); err != nil { t.Fatalf("RLockContext: %v", err) } } diff --git a/internal/query/rollup_test.go b/internal/query/rollup_test.go index 726aff0e..4e75ce77 100644 --- a/internal/query/rollup_test.go +++ b/internal/query/rollup_test.go @@ -20,7 +20,7 @@ func TestRollupOnceRebuildsAffectedServiceBuckets(t *testing.T) { } d := &Duck{ - DB: db, writeDB: db, + DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}, } ctx := context.Background() @@ -83,7 +83,7 @@ func TestServiceRollupLatencyExcludesDependencyWaits(t *testing.T) { if err := CreateViews(db); err != nil { t.Fatalf("CreateViews failed: %v", err) } - d := &Duck{DB: db, writeDB: db, cfg: config.Config{RetentionDays: 30}} + d := &Duck{DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}} ctx := context.Background() bucket := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Minute) @@ -138,7 +138,7 @@ func TestRollupOnceRebuildsAffectedEdgeBuckets(t *testing.T) { } d := &Duck{ - DB: db, writeDB: db, + DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}, } ctx := context.Background() @@ -227,7 +227,7 @@ func TestRollupOnceIgnoresRowsWithoutBucketTimestamp(t *testing.T) { } d := &Duck{ - DB: db, writeDB: db, + DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}, } ctx := context.Background() @@ -301,7 +301,7 @@ func TestRollupOnceMessagingEdgeCountsConsumedMessages(t *testing.T) { } d := &Duck{ - DB: db, writeDB: db, + DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}, } ctx := context.Background() @@ -372,7 +372,7 @@ func TestRollupOnceDropsCallEdgeParentOutsideWindow(t *testing.T) { } d := &Duck{ - DB: db, writeDB: db, + DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}, } ctx := context.Background() @@ -505,7 +505,7 @@ func TestRollupOnceChunksWideBacklog(t *testing.T) { } d := &Duck{ - DB: db, writeDB: db, + DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}, } ctx := context.Background() @@ -723,7 +723,7 @@ func TestRecreatingAServiceRollupClearsItsWatermark(t *testing.T) { if err := CreateViews(db); err != nil { t.Fatalf("CreateViews failed: %v", err) } - d := &Duck{DB: db, writeDB: db, cfg: config.Config{RetentionDays: 30}} + d := &Duck{DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30}} ctx := context.Background() bucket := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Minute) @@ -746,9 +746,25 @@ func TestRecreatingAServiceRollupClearsItsWatermark(t *testing.T) { t.Fatalf("CreateTables after the schema change: %v", err) } requireRowCount(t, db, `SELECT count(*) FROM service_rollup`, nil, 0) + d.rollupWatermarks = nil if _, err := d.rollupOnce(ctx); err != nil { t.Fatalf("rollupOnce after recreate failed: %v", err) } requireServiceRollupSpans(t, db, "ns", bucket, "checkout", 1) } + +// Mutable-table fixtures have no Repository. Their source is explicit and is +// never used by the production Parquet path. +func tablePublicationBounds(db *sql.DB) func() (int64, int64, int64) { + return func() (int64, int64, int64) { + var hi, lo int64 + if err := db.QueryRow(`SELECT coalesce(max(v),0), coalesce(min(v),0) FROM ( + SELECT ingested_unix_nano v FROM telemetry.spans UNION ALL + SELECT ingested_unix_nano FROM telemetry.logs UNION ALL + SELECT ingested_unix_nano FROM telemetry.metrics)`).Scan(&hi, &lo); err != nil { + panic(err) + } + return hi, hi, lo + } +} diff --git a/internal/query/rollup_watermark_test.go b/internal/query/rollup_watermark_test.go index 56e61960..683bdd59 100644 --- a/internal/query/rollup_watermark_test.go +++ b/internal/query/rollup_watermark_test.go @@ -1,201 +1,280 @@ package query import ( - "context" + "os" "testing" "time" + "github.com/DATA-DOG/go-sqlmock" "github.com/labstack/fanout/internal/config" + "github.com/labstack/fanout/internal/metrics" + "github.com/labstack/fanout/internal/telemetry" + telemetrystore "github.com/labstack/fanout/internal/telemetry/store" + "github.com/prometheus/client_golang/prometheus/testutil" ) -func TestRollupPublicationLagExceedsReaderAndPublisherWindow(t *testing.T) { - minimum := defaultWriterGrace + time.Duration(maxQueryTimeoutMs)*time.Millisecond - if rollupPublicationSafetyLag <= minimum { - t.Fatalf("rollup publication lag = %s, must exceed reader+publisher window %s", rollupPublicationSafetyLag, minimum) - } -} - -// TestRollupWatermarkPicksUpLateLowIngestedRow reproduces the silent-data-loss -// bug: a row that commits with an ingested timestamp below a watermark already -// advanced by another signal would be excluded from the rollup forever. The -// safety lag must keep it in the reprocessed window. -func TestRollupWatermarkPicksUpLateLowIngestedRow(t *testing.T) { +func TestRollupHorizonDoesNotSkipInFlightRows(t *testing.T) { db := openTestDuck(t) if err := CreateTables(db); err != nil { - t.Fatalf("CreateTables: %v", err) + t.Fatal(err) } if err := CreateViews(db); err != nil { - t.Fatalf("CreateViews: %v", err) + t.Fatal(err) } - - const lag = 2 * time.Second - d := &Duck{ - DB: db, writeDB: db, - cfg: config.Config{RetentionDays: 30}, - rollupLagNanos: lag.Nanoseconds(), + horizon := int64(99) + minimum := int64(200) + d := &Duck{DB: db, writeDB: db, publicationBounds: func() (int64, int64, int64) { return horizon, 200, minimum }} + bucket := time.Now().UTC().Truncate(time.Minute).Add(-time.Minute) + insert := func(id string, stamp int64) { + insertRollupTestSpan(t, db, rollupTestSpan{namespace: "ns", traceID: "trace", spanID: id, parentSpanID: "parent", service: id, start: bucket, ingested: stamp}) } - ctx := context.Background() - - bucket := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Minute) - tNow := time.Now().UnixNano() - - // First signal commits at the high-water mark and the rollup advances. - insertRollupTestSpan(t, db, rollupTestSpan{ - namespace: "ns", traceID: "t1", spanID: "s1", service: "alpha", - operation: "op", start: bucket.Add(time.Second), duration: 10 * time.Millisecond, - ingested: tNow, - }) - if _, err := d.rollupOnce(ctx); err != nil { - t.Fatalf("first rollupOnce: %v", err) + insertRollupTestSpan(t, db, rollupTestSpan{namespace: "ns", traceID: "trace", spanID: "parent", service: "gateway", start: bucket, ingested: 200}) + insert("later", 200) + if _, err := d.rollupOnce(t.Context()); err != nil { + t.Fatal(err) } - - // A second signal commits LATER but with a lower ingested timestamp (within - // the lag window). Pre-fix, this was below the stored watermark and dropped. - insertRollupTestSpan(t, db, rollupTestSpan{ - namespace: "ns", traceID: "t2", spanID: "s2", service: "beta", - operation: "op", start: bucket.Add(time.Second), duration: 10 * time.Millisecond, - ingested: tNow - time.Second.Nanoseconds(), - }) - if _, err := d.rollupOnce(ctx); err != nil { - t.Fatalf("second rollupOnce: %v", err) + requireRowCount(t, db, "SELECT count(*) FROM service_rollup WHERE ?", true, 0) + for _, component := range []string{"service", "edge"} { + if got := testutil.ToFloat64(metrics.RollupWatermark.WithLabelValues(component)); got > float64(horizon)/1e9 { + t.Fatalf("%s progress %g exceeds horizon %g", component, got, float64(horizon)/1e9) + } } + // Stamp 100 remained in flight while stamp 200 published. Once it + // publishes, both the service and edge passes must include it. + insert("earlier", 100) + minimum = 100 + horizon = 200 + if _, err := d.rollupOnce(t.Context()); err != nil { + t.Fatal(err) + } + requireServiceRollupSpans(t, db, "ns", bucket, "earlier", 1) + requireServiceRollupSpans(t, db, "ns", bucket, "later", 1) + requireRowCount(t, db, "SELECT count(*) FROM edge_rollup WHERE caller='gateway' AND callee=?", "earlier", 1) +} - requireServiceRollupSpans(t, db, "ns", bucket, "beta", 1) - - // After the max plateaus (no new ingest), the rollup must go idle rather than - // re-aggregating the trailing window every cycle forever. - affected, err := d.rollupOnce(ctx) +func TestRollupIdleHorizonExecutesNoSQL(t *testing.T) { + db, mock, err := sqlmock.New() if err != nil { - t.Fatalf("third rollupOnce: %v", err) + t.Fatal(err) + } + defer db.Close() + d := &Duck{DB: db, writeDB: db, publicationBounds: func() (int64, int64, int64) { return 100, 200, 1 }, rollupWatermarks: map[string]int64{serviceRollupStateKey: 100, edgeRollupStateKey: 100}} + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) } - if affected != 0 { - t.Errorf("third rollupOnce affected %d rows; want 0 (should short-circuit once ingest plateaus)", affected) + if _, _, err := d.refreshEdgeRollupPass(t.Context()); err != nil { + t.Fatal(err) + } + if err := mock.ExpectationsWereMet(); err != nil { + t.Fatal(err) } } -// TestRollupWatermarkLagSurvivesChunkedCatchUp pins the interaction between -// chunked catch-up and the safety lag (the chunked backlog test runs with lag -// disabled, so it cannot catch either regression): -// - the lag clamp must apply on chunked passes too — a chunk end landing -// inside the tip's lag window must not advance the watermark past rows -// that commit late below it; -// - the rawmax key must advance only as far as a pass actually scanned — -// storing the full tip on a chunked pass lets the plateau shortcut close -// the watermark at the tip before its lag window was ever reprocessed. -// -// Reverting either half of the fix drops one of the two late rows forever. -func TestRollupWatermarkLagSurvivesChunkedCatchUp(t *testing.T) { - db := openTestDuck(t) - if err := CreateTables(db); err != nil { - t.Fatalf("CreateTables: %v", err) +func TestRollupWindowsPartitionSteadyIngest(t *testing.T) { + watermark := int64(0) + seen := make(map[int64]int) + for horizon := int64(100); horizon <= 1000; horizon += 100 { + start, end, _ := rollupWindow(watermark, 1, horizon) + for row := int64(1); row <= horizon; row++ { + if row > start && row <= end { + seen[row]++ + } + } + watermark = end } - if err := CreateViews(db); err != nil { - t.Fatalf("CreateViews: %v", err) + for row := int64(1); row <= 1000; row++ { + if seen[row] != 1 { + t.Fatalf("stamp %d processed %d times", row, seen[row]) + } } +} - const lag = 2 * time.Second - d := &Duck{ - DB: db, writeDB: db, - cfg: config.Config{RetentionDays: 30}, - rollupLagNanos: lag.Nanoseconds(), +func TestRollupPicksUpRetriedCommit(t *testing.T) { + d, repo := newBatchCacheTest(t) + bucket := time.Now().UTC().Truncate(time.Minute).Add(-time.Minute) + batch := telemetrystore.Batch{ID: "retry", Spans: []telemetry.Span{{Namespace: "ns", ServiceName: "retried", TraceID: "trace", SpanID: "span", StartUnixNanos: bucket.UnixNano(), IngestedAt: 1}}} + path := repo.Parquet.BatchPath(batch.ID) + if err := os.WriteFile(path, []byte("block publication"), 0600); err != nil { + t.Fatal(err) } - ctx := context.Background() - - bucket := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Minute) - const base = int64(1_000_000) // synthetic ingest clock, nanos - chunkEnd := base - 1 + rollupChunkNanos - tip := base + rollupChunkNanos + time.Second.Nanoseconds() // 1s past the chunk end: pass 1 is chunked AND its end is inside the tip's lag window - - insert := func(spanID, service string, ingested int64) { - insertRollupTestSpan(t, db, rollupTestSpan{ - namespace: "ns", traceID: "tr-" + spanID, spanID: spanID, service: service, - operation: "op", start: bucket.Add(time.Second), duration: 10 * time.Millisecond, - ingested: ingested, - }) + if err := repo.Commit(t.Context(), batch); err == nil { + t.Fatal("blocked publication succeeded") } - - insert("s-base", "alpha", base) - insert("s-tip", "delta", tip) - - // Pass 1: chunked. The watermark must stop at tip-lag, not the chunk end. - if _, err := d.rollupOnce(ctx); err != nil { - t.Fatalf("first rollupOnce: %v", err) + failedStamp := batch.Spans[0].IngestedAt + if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "other", Logs: []telemetry.Log{{Namespace: "ns", ServiceName: "other", TimeUnixNanos: bucket.UnixNano()}}}); err != nil { + t.Fatal(err) } - requireServiceRollupSpans(t, db, "ns", bucket, "alpha", 1) - - // Late row below the chunk end but inside the tip's lag window. Without - // the chunked-pass clamp the watermark already passed it. - insert("s-late-clamp", "beta", chunkEnd-500*time.Millisecond.Nanoseconds()) - if _, err := d.rollupOnce(ctx); err != nil { - t.Fatalf("second rollupOnce: %v", err) + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) } - - // Late row just below the tip. With rawmax stored at the full tip on the - // chunked pass, the plateau shortcut has already closed the watermark at - // the tip and the next pass short-circuits past this row. - insert("s-late-plateau", "gamma", tip-time.Second.Nanoseconds()) - if _, err := d.rollupOnce(ctx); err != nil { - t.Fatalf("third rollupOnce: %v", err) + if d.rollupWatermarks[serviceRollupStateKey] <= failedStamp { + t.Fatal("fixture did not advance past failed stamp") } - - requireServiceRollupSpans(t, db, "ns", bucket, "beta", 1) - requireServiceRollupSpans(t, db, "ns", bucket, "gamma", 1) + if err := os.Remove(path); err != nil { + t.Fatal(err) + } + if err := repo.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) + } + requireServiceRollupSpans(t, d.DB, "ns", bucket, "retried", 1) } -// TestEdgeRollupWatermarkPicksUpLateChild exercises the edge rollup's safety-lag -// path (the existing edge test runs with lag disabled): a child span that commits -// after the watermark advanced, with a lower ingested timestamp, must still -// produce its dependency edge. -func TestEdgeRollupWatermarkPicksUpLateChild(t *testing.T) { - db := openTestDuck(t) - if err := CreateTables(db); err != nil { - t.Fatalf("CreateTables: %v", err) +func TestRollupFailedFirstAttemptDoesNotOpenEpochWindow(t *testing.T) { + d, repo := newBatchCacheTest(t) + bucket := time.Now().UTC().Truncate(time.Minute).Add(-time.Minute) + batch := telemetrystore.Batch{ID: "first-attempt", Spans: []telemetry.Span{{Namespace: "ns", ServiceName: "first", TraceID: "trace", SpanID: "span", StartUnixNanos: bucket.UnixNano()}}} + path := repo.Parquet.BatchPath(batch.ID) + if err := os.WriteFile(path, []byte("block publication"), 0600); err != nil { + t.Fatal(err) } - if err := CreateViews(db); err != nil { - t.Fatalf("CreateViews: %v", err) + if err := repo.Commit(t.Context(), batch); err == nil { + t.Fatal("blocked publication succeeded") } - - const lag = 2 * time.Second - d := &Duck{ - DB: db, writeDB: db, - cfg: config.Config{RetentionDays: 30}, - rollupLagNanos: lag.Nanoseconds(), - } - ctx := context.Background() - bucket := time.Now().UTC().Truncate(time.Minute).Add(-2 * time.Minute) - tNow := time.Now().UnixNano() - start := bucket.Add(time.Second) - - // Parent + first child commit at the high-water mark; edge advances. - insertRollupTestSpan(t, db, rollupTestSpan{ - namespace: "ns", traceID: "tr", spanID: "p1", service: "gateway", - operation: "op", kind: "SPAN_KIND_SERVER", start: start, duration: 10 * time.Millisecond, ingested: tNow, - }) - insertRollupTestSpan(t, db, rollupTestSpan{ - namespace: "ns", traceID: "tr", spanID: "c1", parentSpanID: "p1", service: "orders", - operation: "op", kind: "SPAN_KIND_CLIENT", start: start, duration: 5 * time.Millisecond, ingested: tNow, - }) - if _, err := d.rollupOnce(ctx); err != nil { - t.Fatalf("first rollupOnce: %v", err) + if _, err := d.rollupOnce(t.Context()); err != nil { + t.Fatal(err) + } + if d.rollupWatermarks[serviceRollupStateKey] != 0 || d.rollupWatermarks[edgeRollupStateKey] != 0 { + t.Fatal("failed attempt opened an epoch catch-up window") + } + if err := os.Remove(path); err != nil { + t.Fatal(err) + } + if err := repo.Commit(t.Context(), batch); err != nil { + t.Fatal(err) } + if _, err := d.rollupOnce(t.Context()); err != nil { + t.Fatal(err) + } + requireServiceRollupSpans(t, d.DB, "ns", bucket, "first", 1) +} - // A late child of the same parent commits with a lower ingested timestamp. - insertRollupTestSpan(t, db, rollupTestSpan{ - namespace: "ns", traceID: "tr", spanID: "c2", parentSpanID: "p1", service: "payments", - operation: "op", kind: "SPAN_KIND_CLIENT", start: start, duration: 5 * time.Millisecond, - ingested: tNow - time.Second.Nanoseconds(), - }) - if _, err := d.rollupOnce(ctx); err != nil { - t.Fatalf("second rollupOnce: %v", err) +func TestRollupRestartRewindsFailedAttemptTail(t *testing.T) { + cfg := config.Config{DataDir: t.TempDir(), DuckDBMemory: "256MB", DuckDBThreads: 2, DuckDBMaxConns: 2} + repo, err := telemetrystore.Open(cfg.TelemetryDir()) + if err != nil { + t.Fatal(err) + } + bucket := time.Now().UTC().Truncate(time.Minute).Add(-time.Minute) + future := time.Now().Add(time.Hour).UnixNano() + batch := telemetrystore.Batch{ID: "durable", Spans: []telemetry.Span{{Namespace: "ns", ServiceName: "original", TraceID: "trace", SpanID: "span", StartUnixNanos: bucket.UnixNano(), IngestedAt: future}}} + if err := commitRestoredFixture(repo, t.Context(), batch); err != nil { + t.Fatal(err) + } + repo.Close() + repo, err = telemetrystore.Open(cfg.TelemetryDir()) + if err != nil { + t.Fatal(err) + } + d, err := NewDuck(t.Context(), cfg, repo) + if err != nil { + t.Fatal(err) + } + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) + } + batch.ID = "retry" + batch.Spans[0].ServiceName = "after-restart" + path := repo.Parquet.BatchPath(batch.ID) + if err := os.WriteFile(path, []byte("block publication"), 0600); err != nil { + t.Fatal(err) + } + if err := repo.Commit(t.Context(), batch); err == nil { + t.Fatal("blocked publication succeeded") + } + failed := batch.Spans[0].IngestedAt + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) + } + if d.rollupWatermarks[serviceRollupStateKey] != failed { + t.Fatal("fixture did not process the failed attempt's empty tail") + } + for _, v := range []struct { + key string + value int64 + }{{edgeRollupSubWindowKey, failed}, {edgeRollupSubCursorKey, bucket.UnixNano()}} { + if _, err := d.DB.Exec(`INSERT INTO rollup_state VALUES (?,?,now()) ON CONFLICT(cache_key) DO UPDATE SET last_ingested_unix_nano=excluded.last_ingested_unix_nano`, v.key, v.value); err != nil { + t.Fatal(err) + } + } + d.Close() + repo.Close() + if err := os.Remove(path); err != nil { + t.Fatal(err) + } + repo, err = telemetrystore.Open(cfg.TelemetryDir()) + if err != nil { + t.Fatal(err) } + defer repo.Close() + d, err = NewDuck(t.Context(), cfg, repo) + if err != nil { + t.Fatal(err) + } + defer d.Close() + if d.rollupWatermarks[serviceRollupStateKey] != future { + t.Fatal("empty tail survived restart") + } + _, cursor := readEdgeRollupState(t, d) + if cursor != 0 { + t.Fatal("partial empty-tail cursor survived restart") + } + if err := repo.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } + if batch.Spans[0].IngestedAt != failed { + t.Fatal("fixture did not reuse the failed attempt's nondurable stamp") + } + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) + } + requireServiceRollupSpans(t, d.DB, "ns", bucket, "after-restart", 1) +} - var calls int64 - if err := db.QueryRowContext(ctx, - `SELECT COALESCE(SUM(calls), 0) FROM edge_rollup WHERE namespace = 'ns' AND caller = 'gateway' AND callee = 'payments'`). - Scan(&calls); err != nil { - t.Fatalf("query edge_rollup: %v", err) +func TestRollupIncludesRenamedFirstAttemptBeforeAdoption(t *testing.T) { + if os.Geteuid() == 0 { + t.Skip("directory permission failure injection requires an unprivileged user") + } + d, repo := newBatchCacheTest(t) + bucket := time.Now().UTC().Truncate(time.Minute).Add(-time.Minute) + batch := telemetrystore.Batch{ID: "first-sync-fails", Spans: []telemetry.Span{{Namespace: "ns", ServiceName: "first", TraceID: "trace", SpanID: "span", StartUnixNanos: bucket.UnixNano()}}} + // Allow rename but deny opening the parent directory for its final fsync. + // The stage has its own readable directory; no production fault hook is needed. + dir := repo.Parquet.BatchesDir() + if err := os.Chmod(dir, 0300); err != nil { + t.Fatal(err) + } + t.Cleanup(func() { _ = os.Chmod(dir, 0755) }) + err := repo.Commit(t.Context(), batch) + if restoreErr := os.Chmod(dir, 0755); restoreErr != nil { + t.Fatal(restoreErr) + } + if err == nil { + t.Fatal("commit succeeded despite denied directory fsync") + } + if info, err := os.Stat(repo.Parquet.BatchPath(batch.ID)); err != nil || !info.IsDir() { + t.Fatalf("rename did not complete: %v", err) + } + if len(repo.Parquet.BatchMetadata()) != 0 { + t.Fatal("failed commit was registered") + } + stamp := batch.Spans[0].IngestedAt + if err := repo.Commit(t.Context(), telemetrystore.Batch{ID: "second", Logs: []telemetry.Log{{Namespace: "ns", ServiceName: "other", TimeUnixNanos: bucket.UnixNano()}}}); err != nil { + t.Fatal(err) + } + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) + } + if d.rollupWatermarks[serviceRollupStateKey] <= stamp { + t.Fatal("rollup did not pass the failed stamp") + } + if err := repo.Commit(t.Context(), batch); err != nil { + t.Fatal(err) } - if calls < 1 { - t.Errorf("late child edge gateway->payments missing (calls=%d); safety lag should have caught it", calls) + if _, err := d.refreshServiceRollup(t.Context()); err != nil { + t.Fatal(err) } + requireServiceRollupSpans(t, d.DB, "ns", bucket, "first", 1) } diff --git a/internal/query/rollup_yield_test.go b/internal/query/rollup_yield_test.go index 4362e36d..0396587b 100644 --- a/internal/query/rollup_yield_test.go +++ b/internal/query/rollup_yield_test.go @@ -3,7 +3,6 @@ package query import ( "context" "fmt" - "sync/atomic" "testing" "time" @@ -57,17 +56,13 @@ func newSpreadDuck(t *testing.T, rows, spreadMins int) *Duck { if err := CreateViews(db); err != nil { t.Fatalf("CreateViews: %v", err) } - d := &Duck{DB: db, writeDB: db, cfg: config.Config{RetentionDays: 30, DuckDBMemory: "1GB"}} + d := &Duck{DB: db, writeDB: db, publicationBounds: tablePublicationBounds(db), cfg: config.Config{RetentionDays: 30, DuckDBMemory: "1GB"}} seedEdgeSpread(t, d, rows, spreadMins) return d } -// A rollup pass holds the Parquet snapshot until it commits, so a publication -// whose grace has run out makes every arriving query wait out the rest of that -// pass. The one-sub-window budget also bounds that wait without a publisher. -// The pass now stops at the first sub-window boundary once that happens, which -// costs nothing to arrange: the resume cursor already exists for the per-pass -// budget, and the ingested watermark already stays behind an unfinished window. +// A fresh publisher must get the snapshot at the first resumable boundary, +// while the pass still completes at least one sub-window and can resume later. func TestEdgeRollupYieldsToAQueuedPublisher(t *testing.T) { const ( rows = 6_000 @@ -85,19 +80,7 @@ func TestEdgeRollupYieldsToAQueuedPublisher(t *testing.T) { } yielding := newSpreadDuck(t, rows, spreadMins) - // A publisher can only queue while something is reading, so the test holds - // a reader of its own. The gate's clock is the test's: the pass is admitted - // with the grace intact, and the clock jumps past it once the pass is - // under way — which is the state the rollup yields for, and the only one - // in which a query is actually blocked behind it. - spend := spendGraceOnCue(&yielding.parquetMu) - if err := yielding.parquetMu.RLockContext(ctx); err != nil { - t.Fatalf("hold a reader: %v", err) - } - queued := queuePublisher(t, yielding) - spendOnceAdmitted(&yielding.parquetMu, spend) - - if _, err := yielding.refreshEdgeRollup(ctx); err != nil { + if _, err := edgePassBeforeQueuedPublisher(t, yielding, false); err != nil { t.Fatalf("yielding pass: %v", err) } watermark, yieldCursor := readEdgeRollupState(t, yielding) @@ -113,8 +96,6 @@ func TestEdgeRollupYieldsToAQueuedPublisher(t *testing.T) { // Yielding must not stall the rollup: with the publisher gone the same // instance finishes the window. - yielding.parquetMu.RUnlock() - queued.done() for passes := 0; ; passes++ { if passes > spreadMins/30+4 { t.Fatal("edge rollup did not converge after yielding") @@ -131,99 +112,63 @@ func TestEdgeRollupYieldsToAQueuedPublisher(t *testing.T) { } } -// A publisher that is always queued must not stop the rollup dead: every pass -// has to complete at least one sub-window, or a busy compaction cycle starves -// the cache the whole product reads from. +// An admitted pass completes one sub-window even if a publisher's grace +// expires while the pass is in flight. func TestEdgeRollupAlwaysCompletesOneSubWindow(t *testing.T) { - ctx := context.Background() d := newSpreadDuck(t, 4_000, 180) - spend := spendGraceOnCue(&d.parquetMu) - if err := d.parquetMu.RLockContext(ctx); err != nil { - t.Fatalf("hold a reader: %v", err) - } - queued := queuePublisher(t, d) - // Overdue from the pass's very first boundary: it must still complete one - // sub-window, or a busy compaction cycle starves the cache. - spendOnceAdmitted(&d.parquetMu, spend) - - rows, err := d.refreshEdgeRollup(ctx) + rows, err := edgePassBeforeQueuedPublisher(t, d, true) if err != nil { t.Fatalf("pass with a publisher queued: %v", err) } if rows == 0 { - t.Fatal("a pass yielded before doing any work; a busy compaction cycle would starve the cache") + t.Fatal("an admitted pass yielded before doing any work") } - d.parquetMu.RUnlock() - queued.done() } -// queuePublisher parks a publication in the gate's wait list and returns a -// handle that releases it. It requires a reader to already hold the snapshot, -// which is the only state in which a publisher waits rather than enters. -func queuePublisher(t *testing.T, d *Duck) (handle struct{ done func() }) { +// Hold the only SQL connection after loading admission's prerequisites. The +// pass can take its snapshot but cannot begin SQL until publication queues. +func edgePassBeforeQueuedPublisher(t *testing.T, d *Duck, overdue bool) (int64, error) { t.Helper() - entered := make(chan struct{}) - release := make(chan struct{}) - go func() { - if err := d.parquetMu.LockContext(context.Background()); err != nil { - close(entered) - return - } - close(entered) - <-release - d.parquetMu.Unlock() - }() - deadline := time.Now().Add(2 * time.Second) - for queuedPublishers(&d.parquetMu) == 0 { + ctx := t.Context() + horizon, published, minimum := d.publicationBounds() + d.publicationBounds = func() (int64, int64, int64) { return horizon, published, minimum } + if _, err := d.cachedRollupWatermark(ctx, edgeRollupStateKey, horizon); err != nil { + t.Fatal(err) + } + clock := &fakeClock{now: time.Now()} + d.parquetMu.now = clock.Now + conn, err := d.writer().Conn(ctx) + if err != nil { + t.Fatal(err) + } + defer conn.Close() + type result struct { + rows int64 + err error + } + finished := make(chan result, 1) + go func() { rows, err := d.refreshEdgeRollup(ctx); finished <- result{rows, err} }() + deadline := time.Now().Add(time.Second) + for readers(&d.parquetMu) == 0 { if time.Now().After(deadline) { - t.Fatal("publisher never queued") + t.Fatal("edge pass never entered its snapshot") } time.Sleep(time.Millisecond) } - handle.done = func() { - <-entered - close(release) + publishedResult := make(chan error, 1) + go func() { publishedResult <- d.PublishParquet(ctx, func(context.Context) error { return nil }) }() + waitForQueuedWriter(t, &d.parquetMu) + if overdue { + clock.Advance(defaultWriterGrace + time.Second) } - return handle -} - -// spendGraceOnCue replaces the gate's clock with one the test moves. Until the -// returned function is called the clock stands still, so a queued publication -// keeps its whole grace and readers are admitted; afterwards the clock is an -// hour later, so the grace is spent and every new reader would queue. -func spendGraceOnCue(gate *parquetReadGate) (spend func()) { - base := time.Now() - var spent atomic.Bool - gate.now = func() time.Time { - if spent.Load() { - return base.Add(time.Hour) - } - return base + if err := conn.Close(); err != nil { + t.Fatal(err) } - return func() { spent.Store(true) } -} - -// queuedPublishers reads the gate's wait list. The grace-based predicate the -// rollup uses cannot serve here: a publication that has only just queued still -// has its whole grace, which is exactly the state this waits to observe. -func queuedPublishers(gate *parquetReadGate) int { - gate.init() - gate.mu.Lock() - defer gate.mu.Unlock() - return len(gate.waiting) -} - -// spendOnceAdmitted spends the queued publication's grace the moment the rollup -// has entered the snapshot, so the pass is admitted with the grace intact and -// finds it gone at its first sub-window boundary. Waiting on the reader count -// rather than on a duration keeps that ordering exact. -func spendOnceAdmitted(gate *parquetReadGate, spend func()) { - go func() { - for readers(gate) < 2 { - time.Sleep(time.Millisecond) - } - spend() - }() + pass := <-finished + if err := <-publishedResult; err != nil { + t.Fatal(err) + } + return pass.rows, pass.err } func readers(gate *parquetReadGate) int { diff --git a/internal/query/stall_instrumentation_test.go b/internal/query/stall_instrumentation_test.go index da74aba4..2192c669 100644 --- a/internal/query/stall_instrumentation_test.go +++ b/internal/query/stall_instrumentation_test.go @@ -114,42 +114,39 @@ func TestSnapshotWaitIsMeasuredForReaders(t *testing.T) { } } -func TestPublisherGraceLeftTracksAWaitingSwap(t *testing.T) { - gate := parquetReadGate{writerGrace: time.Second} - if left := gate.publisherGraceLeft(); left != time.Second { - t.Fatalf("an idle gate reports %v of grace left, want the whole %v", left, time.Second) - } - if err := gate.RLockContext(context.Background()); err != nil { - t.Fatalf("RLockContext: %v", err) +func TestPublisherWaitingTracksFreshAndCanceledPublication(t *testing.T) { + gate := parquetReadGate{} + base := time.Now() + gate.now = func() time.Time { return base } + if gate.publisherWaiting() { + t.Fatal("idle gate reports a waiting publisher") + } + if err := gate.RLockContext(t.Context(), parquetReadQuery); err != nil { + t.Fatal(err) } - queued := make(chan struct{}) - go func() { - close(queued) - if err := gate.LockContext(context.Background()); err == nil { - gate.Unlock() - } - }() - <-queued + defer gate.RUnlock() + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + done := make(chan error, 1) + go func() { done <- gate.LockContext(ctx) }() deadline := time.Now().Add(time.Second) - for gate.publisherGraceLeft() == time.Second { + for !gate.publisherWaiting() { if time.Now().After(deadline) { - t.Fatal("a publisher waiting for readers did not start consuming its grace") + t.Fatal("fresh publisher was not observed") } time.Sleep(time.Millisecond) } - // The grace runs down rather than vanishing: a reader admitted now is not - // blocking anything yet, which is what stops the rollup yielding on sight. - if left := gate.publisherGraceLeft(); left <= 0 || left > time.Second { - t.Fatalf("grace left = %v, want a positive remainder under %v", left, time.Second) - } - deadline = time.Now().Add(3 * time.Second) - for gate.publisherGraceLeft() > 0 { - if time.Now().After(deadline) { - t.Fatal("grace never ran out") - } - time.Sleep(5 * time.Millisecond) + if !gate.TryRLock(parquetReadQuery) { + t.Fatal("fresh publisher exhausted reader grace") } gate.RUnlock() + cancel() + if err := <-done; err != context.Canceled { + t.Fatalf("publication: %v", err) + } + if gate.publisherWaiting() { + t.Fatal("canceled publisher remained waiting") + } } // database/sql closes a connector that implements io.Closer when its DB is diff --git a/internal/query/timestamp_plan_test.go b/internal/query/timestamp_plan_test.go index 81a42da9..26c00591 100644 --- a/internal/query/timestamp_plan_test.go +++ b/internal/query/timestamp_plan_test.go @@ -26,7 +26,7 @@ func TestNativeTimestampPredicatesPruneParquetAndPreserveNanoseconds(t *testing. n := base.Add(time.Duration(i/50000)*time.Minute + time.Duration(i%50000)).UnixNano() spans[i] = telemetry.Span{TraceID: "trace", SpanID: fmt.Sprintf("%06d", i), StartUnixNanos: n, EndUnixNanos: n + 1, ServiceName: "api", DurationMS: 1} } - if err := store.CommitBatch(context.Background(), telemetry.BatchMetadata{ID: "time"}, spans, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &telemetry.BatchMetadata{ID: "time"}, spans, nil, nil); err != nil { t.Fatal(err) } db := openTestDuck(t) diff --git a/internal/query/version_budget_test.go b/internal/query/version_budget_test.go new file mode 100644 index 00000000..cd590db9 --- /dev/null +++ b/internal/query/version_budget_test.go @@ -0,0 +1,180 @@ +package query + +import ( + "context" + "fmt" + "runtime" + "strings" + "testing" + "time" + + "github.com/labstack/fanout/internal/annotations" + "github.com/labstack/fanout/internal/config" + "github.com/labstack/fanout/internal/telemetry" + telemetrystore "github.com/labstack/fanout/internal/telemetry/store" +) + +func TestVersionPendingBudgetsAndSingleRetries(t *testing.T) { + now := time.Now() + mixed := func(id string, n int) telemetry.BatchMetadata { + return telemetry.BatchMetadata{ID: id, Spans: n, Logs: n, Metrics: n} + } + for _, tc := range []struct { + name string + batches []telemetry.BatchMetadata + failures map[string]versionRollupFailure + want []string + }{ + {name: "exact row budget", batches: []telemetry.BatchMetadata{mixed("a", 300000), {ID: "b", Logs: 100000}, mixed("c", 1)}, want: []string{"a", "b"}}, + {name: "combined signals exceed rows", batches: []telemetry.BatchMetadata{mixed("a", 200000), mixed("b", 200000)}, want: []string{"a"}}, + {name: "oversized alone", batches: []telemetry.BatchMetadata{mixed("large", versionRollupRowBudget/3+1), mixed("new", 1)}, want: []string{"large"}}, + {name: "oversized waits for next pass", batches: []telemetry.BatchMetadata{mixed("old", 1), mixed("large", versionRollupRowBudget/3+1)}, want: []string{"old"}}, + {name: "failed group retries singly", batches: []telemetry.BatchMetadata{mixed("retry", 1), mixed("new", 1)}, failures: map[string]versionRollupFailure{"retry": {retrySingly: true}}, want: []string{"retry"}}, + {name: "retry waits for next pass", batches: []telemetry.BatchMetadata{mixed("old", 1), mixed("retry", 1)}, failures: map[string]versionRollupFailure{"retry": {retrySingly: true}}, want: []string{"old"}}, + {name: "backoff permits newer work", batches: []telemetry.BatchMetadata{mixed("retry", 1), mixed("new", 1)}, failures: map[string]versionRollupFailure{"retry": {nextAttempt: now.Add(time.Minute)}}, want: []string{"new"}}, + } { + t.Run(tc.name, func(t *testing.T) { + got := pendingVersionBatches(tc.batches, nil, tc.failures, now) + ids := make([]string, len(got)) + for i, b := range got { + ids[i] = b.ID + } + if fmt.Sprint(ids) != fmt.Sprint(tc.want) { + t.Fatalf("got %v want %v", ids, tc.want) + } + }) + } + batches := make([]telemetry.BatchMetadata, 65) + for i := range batches { + batches[i] = mixed(fmt.Sprint(i), 1) + } + if got := pendingVersionBatches(batches, nil, nil, now); len(got) != 64 { + t.Fatalf("batch cap: %d", len(got)) + } +} + +func TestVersionMixedBacklogDrainsAndAllowsAnomalyPersistence(t *testing.T) { + // Exercise the budget on the same eight-thread host shape as its sizing + // measurement, rather than the two-thread/256MB small annotation fixture. + cfg := config.Config{DataDir: t.TempDir(), DuckDBMemory: "2GB", DuckDBThreads: 8, DuckDBMaxConns: 8, RetentionDays: 30} + repo, err := telemetrystore.Open(cfg.TelemetryDir()) + if err != nil { + t.Fatal(err) + } + d, err := NewDuck(t.Context(), cfg, repo) + if err != nil { + _ = repo.Close() + t.Fatal(err) + } + t.Cleanup(func() { _ = d.Close(); _ = repo.Close() }) + const total = 60 + // 4.95m rows in 180 real Parquet files. Each full pass admits 12 + // batches (990k rows), preserving all signals and complete acknowledgements. + for i := range total { + size := 5000 + if i%2 == 1 { + size = 50000 + } + commitMixedVersionBatch(t, repo, fmt.Sprintf("mixed-%03d", i), size) + } + for pass, want := range []int64{12, 12, 12, 12, 12, 0} { + if n, err := d.RefreshVersionRollup(t.Context()); err != nil || n != want { + t.Fatalf("pass %d: batches=%d want=%d err=%v", pass, n, want, err) + } + } + var marked, limited int + if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup_batches`).Scan(&marked); err != nil || marked != total { + t.Fatalf("markers=%d err=%v", marked, err) + } + if err := d.DB.QueryRow(`SELECT last_ingested_unix_nano FROM rollup_state WHERE cache_key='version_rollup_v1_limited'`).Scan(&limited); err != nil || limited != 0 { + t.Fatalf("limited=%d err=%v", limited, err) + } + var versions int + if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup`).Scan(&versions); err != nil || versions != 120 { + t.Fatalf("versions=%d err=%v", versions, err) + } + // Requeue the same real backlog and park the production version loop after + // it owns writeGate, so the anomaly writer demonstrably contends with it. + if _, err := d.writer().Exec(`DELETE FROM version_rollup_batches`); err != nil { + t.Fatal(err) + } + if err := d.parquetMu.LockContext(t.Context()); err != nil { + t.Fatal(err) + } + locked := true + defer func() { + if locked { + d.parquetMu.Unlock() + } + }() + ctx, cancel := context.WithTimeout(t.Context(), 15*time.Second) + done := make(chan struct{}) + go func() { defer close(done); d.runVersionRollupLoop(ctx) }() + defer func() { cancel(); <-done }() + waitForVersionBudgetStack(t, "query.(*Duck).runVersionRollupLoop", "query.(*parquetReadGate).RLockContext") + now := time.Now().UTC() + finding := annotations.Anomaly{Namespace: "namespace-0", Service: "service-0", Kind: "volume", From: now.Add(-time.Minute), To: now, Title: "Low volume", Severity: "warn"} + persisted := make(chan error, 1) + go func() { persisted <- d.RecordAnomalies(ctx, []annotations.Anomaly{finding}, now) }() + waitForVersionBudgetStack(t, "query.(*Duck).RecordAnomalies", "writegate.(*WriteGate).LockContext") + start := time.Now() + d.parquetMu.Unlock() + locked = false + select { + case err := <-persisted: + if err != nil { + t.Fatal(err) + } + case <-time.After(5 * time.Second): + t.Fatal("anomaly persistence starved behind busy version loop") + } + t.Logf("anomaly persisted behind productive version pass in %v", time.Since(start)) + var count int + if err := d.DB.QueryRow(`SELECT count(*) FROM anomaly_log WHERE title='Low volume'`).Scan(&count); err != nil || count != 1 { + t.Fatalf("persisted=%d err=%v", count, err) + } + if err := d.DB.QueryRow(`SELECT count(*) FROM version_rollup_batches`).Scan(&marked); err != nil || marked == 0 { + t.Fatalf("version loop made no progress: %d %v", marked, err) + } +} + +func waitForVersionBudgetStack(t *testing.T, caller, frame string) { + t.Helper() + deadline := time.NewTimer(3 * time.Second) + defer deadline.Stop() + ticker := time.NewTicker(time.Millisecond) + defer ticker.Stop() + buffer := make([]byte, 1<<20) + for { + for stack := range strings.SplitSeq(string(buffer[:runtime.Stack(buffer, true)]), "\n\n") { + if strings.Contains(stack, "[select]") && strings.Contains(stack, caller) && strings.Contains(stack, frame) { + return + } + } + select { + case <-deadline.C: + t.Fatalf("never observed %s waiting in %s", caller, frame) + case <-ticker.C: + } + } +} + +func commitMixedVersionBatch(t testing.TB, repo *telemetrystore.Repository, id string, size int) { + t.Helper() + at := time.Now().UTC().Add(-time.Hour).UnixNano() + batch := telemetrystore.Batch{ID: id, Spans: make([]telemetry.Span, size), Logs: make([]telemetry.Log, size), Metrics: make([]telemetry.Metric, size)} + for i := range size { + ns := fmt.Sprintf("namespace-%d", i%3) + svc := fmt.Sprintf("service-%d", i%24) + version := fmt.Sprintf("v%d", i%5) + resource := map[string]any{"service.version": version, "deployment.environment": "production", "host.name": fmt.Sprintf("host-%d", i%31), "count": int64(i), "enabled": true} + attrs := map[string]any{"http.method": "GET", "http.status_code": int64(200), "http.route": "/api/items"} + stamp := at + int64(i)*1000 + batch.Spans[i] = telemetry.Span{Namespace: ns, ServiceName: svc, ServiceVersion: version, TraceID: fmt.Sprintf("%s-%d", id, i/2), SpanID: fmt.Sprint(i), Name: "GET /api/items", Kind: "SPAN_KIND_SERVER", StartUnixNanos: stamp, EndUnixNanos: stamp + 1000000, DurationMS: 1, StatusCode: "STATUS_CODE_OK", Resource: resource, Attributes: attrs} + batch.Logs[i] = telemetry.Log{Namespace: ns, ServiceName: svc, EventUnixNanos: stamp, Severity: "INFO", Body: fmt.Sprintf("request %d completed successfully", i), Resource: resource, Attributes: attrs} + batch.Metrics[i] = telemetry.Metric{Namespace: ns, ServiceName: svc, EventUnixNanos: stamp, Name: "http.requests", Type: "sum", Value: float64(i), Resource: resource, Attributes: attrs} + } + if err := repo.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } +} diff --git a/internal/query/views_schema_test.go b/internal/query/views_schema_test.go index 3ac0fa29..cfee83f8 100644 --- a/internal/query/views_schema_test.go +++ b/internal/query/views_schema_test.go @@ -15,7 +15,7 @@ func TestParquetMessagingViewProjectsShreddedKeysIntoScan(t *testing.T) { t.Fatal(err) } defer store.Close() - if err := store.CommitBatch(context.Background(), telemetry.BatchMetadata{ID: "attrs"}, []telemetry.Span{ + if err := store.CommitBatch(context.Background(), &telemetry.BatchMetadata{ID: "attrs"}, []telemetry.Span{ {TraceID: "one", SpanID: "a", Resource: map[string]any{"service.name": "api"}, Attributes: map[string]any{"messaging.system": "kafka", "messaging.destination.name": "jobs"}}, {TraceID: "two", SpanID: "b", Resource: map[string]any{"service.name": "worker"}, Attributes: map[string]any{"messaging.system": "nats", "messaging.destination.name": "events"}}, }, nil, nil); err != nil { diff --git a/internal/telemetry/commit_memory_test.go b/internal/telemetry/commit_memory_test.go index 96fa6e37..84eb8c69 100644 --- a/internal/telemetry/commit_memory_test.go +++ b/internal/telemetry/commit_memory_test.go @@ -150,7 +150,7 @@ func TestCommitBatchAllocationStaysNearPayloadSize(t *testing.T) { // A distinct ID each time: CommitBatch is idempotent, and a repeat // would return early and measure nothing. id := fmt.Sprintf("peak-heap-%d", attempt) - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: id}, spans, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: id}, spans, nil, nil); err != nil { t.Errorf("commit batch: %v", err) } }) @@ -189,7 +189,7 @@ func BenchmarkCommitBatch(b *testing.B) { b.Fatalf("open parquet store: %v", err) } observed, _ := samplePeakHeapInuse(func() { - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: fmt.Sprintf("bench-%d", i)}, spans, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: fmt.Sprintf("bench-%d", i)}, spans, nil, nil); err != nil { b.Fatalf("commit batch: %v", err) } }) diff --git a/internal/telemetry/compaction_debt.go b/internal/telemetry/compaction_debt.go new file mode 100644 index 00000000..163d7a64 --- /dev/null +++ b/internal/telemetry/compaction_debt.go @@ -0,0 +1,104 @@ +package telemetry + +import ( + "context" + "time" +) + +const ( + CompactionMaxRows = 25_000_000 + CompactionBatchLimit = 128 + CompactionDebtLimit = 1024 +) + +// Generation0BatchCount is the exact live ingest-batch inventory, including +// terminal oversized batches and underfilled day groups. No metadata scan. +func (p *ParquetStore) Generation0BatchCount() int { + p.mu.RLock() + defer p.mu.RUnlock() + return p.generation0Batches +} + +// CompactionDebt returns the reclaimable generation-0 backlog, excluding +// batches that the compaction policy cannot yet merge. No metadata scan. +func (p *ParquetStore) CompactionDebt() int { + p.mu.RLock() + defer p.mu.RUnlock() + return p.compactionDebt +} + +// changeGeneration0Locked also maintains conservative, reclaimable debt. A raw +// generation-0 limit can deadlock on arbitrary oversized requests or on many +// finished days with fewer than eight inputs. Exempt batches above half the +// merge row ceiling, and reserve one underfilled group per day. Positive debt +// then guarantees a selectable group without changing compaction policy. +func (p *ParquetStore) changeGeneration0Locked(b BatchMetadata, delta int) { + if b.Generation != 0 { + return + } + p.generation0Batches += delta + rows := int64(b.Spans) + int64(b.Logs) + int64(b.Metrics) + if b.MaxIngestedNanos <= 0 || rows <= 0 || rows > CompactionMaxRows/2 { + return + } + if p.generation0ByDay == nil { + p.generation0ByDay = make(map[int64]int) + } + day := b.MaxIngestedNanos / int64(24*time.Hour) + before := p.generation0ByDay[day] + after := before + delta + p.compactionDebt += max(0, after-(CompactionBatchLimit-1)) - max(0, before-(CompactionBatchLimit-1)) + if after == 0 { + delete(p.generation0ByDay, day) + } else { + p.generation0ByDay[day] = after + } +} + +// setBatchLocked is the sole live-catalog mutation. Replacement, restoration, +// rollback, startup and retention all use the same inventory accounting. +func (p *ParquetStore) setBatchLocked(id string, batch *storedBatch) { + debtBefore := p.compactionDebt + if old := p.batches[id]; old != nil { + p.changeGeneration0Locked(old.metadata, -1) + } + if batch == nil { + delete(p.batches, id) + } else { + p.batches[id] = batch + p.changeGeneration0Locked(batch.metadata, 1) + } + if p.compactionDebt < debtBefore && p.debtChanged != nil { + close(p.debtChanged) + p.debtChanged = nil + } +} + +// WaitForCompaction releases the catalog lock before sleeping and wakes on a +// debt retirement or cancellation. No storage lock or query gate is held. +func (p *ParquetStore) WaitForCompaction(ctx context.Context) (time.Duration, error) { + var began time.Time + for { + p.mu.Lock() + if p.compactionDebt < CompactionDebtLimit { + p.mu.Unlock() + if began.IsZero() { + return 0, ctx.Err() + } + return time.Since(began), ctx.Err() + } + if p.debtChanged == nil { + p.debtChanged = make(chan struct{}) + } + changed := p.debtChanged + p.mu.Unlock() + if began.IsZero() { + began = time.Now() + } + select { + case <-changed: + case <-ctx.Done(): + return time.Since(began), ctx.Err() + } + } +} diff --git a/internal/telemetry/compaction_debt_test.go b/internal/telemetry/compaction_debt_test.go new file mode 100644 index 00000000..1996994e --- /dev/null +++ b/internal/telemetry/compaction_debt_test.go @@ -0,0 +1,122 @@ +package telemetry + +import ( + "context" + "fmt" + "testing" + "time" +) + +func TestGenerationZeroInventoryTracksCatalogChanges(t *testing.T) { + p := &ParquetStore{batches: make(map[string]*storedBatch)} + add := func(id string, generation int) { + p.installBatch(&storedBatch{metadata: BatchMetadata{ID: id, Generation: uint32(generation), MaxIngestedNanos: 1, Spans: 1}}) + } + add("a", 0) + add("b", 0) + add("a", 0) + if p.Generation0BatchCount() != 2 { + t.Fatal("idempotent install double counted") + } + add("a", 1) + if p.Generation0BatchCount() != 1 { + t.Fatal("replacement not counted") + } + p.mu.Lock() + p.setBatchLocked("b", nil) + p.mu.Unlock() + if p.Generation0BatchCount() != 0 { + t.Fatal("retirement not counted") + } + add("b", 0) + if p.Generation0BatchCount() != 1 { + t.Fatal("restoration not counted") + } +} +func TestCompactionWaitWakesOnRetirementAndCancellation(t *testing.T) { + for _, cancelWait := range []bool{false, true} { + t.Run(fmt.Sprint(cancelWait), func(t *testing.T) { + p := &ParquetStore{batches: make(map[string]*storedBatch)} + for i := 0; i < CompactionDebtLimit+CompactionBatchLimit-1; i++ { + p.installBatch(&storedBatch{metadata: BatchMetadata{ID: fmt.Sprint(i), Spans: 1, MaxIngestedNanos: 1}}) + } + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + done := make(chan error, 1) + go func() { _, err := p.WaitForCompaction(ctx); done <- err }() + // Observe the registered wait under the same lock; no timing assumption. + until := time.Now().Add(time.Second) + for { + p.mu.RLock() + waiting := p.debtChanged != nil + p.mu.RUnlock() + if waiting { + break + } + if time.Now().After(until) { + t.Fatal("wait not registered") + } + time.Sleep(time.Millisecond) + } + select { + case <-done: + t.Fatal("wait did not block") + default: + } + if cancelWait { + cancel() + } else { + p.mu.Lock() + p.setBatchLocked("0", nil) + p.mu.Unlock() + } + select { + case err := <-done: + if cancelWait && err != context.Canceled || !cancelWait && err != nil { + t.Fatal(err) + } + case <-time.After(time.Second): + t.Fatal("wait did not wake") + } + }) + } +} +func TestIrreducibleGenerationZeroBatchesDoNotStall(t *testing.T) { + p := &ParquetStore{batches: make(map[string]*storedBatch)} + for i := 0; i < 2048; i++ { + p.installBatch(&storedBatch{metadata: BatchMetadata{ID: fmt.Sprint(i), Spans: CompactionMaxRows, MaxIngestedNanos: 1}}) + } + for day := 1; day < 200; day++ { + for i := 0; i < 7; i++ { + p.installBatch(&storedBatch{metadata: BatchMetadata{ID: fmt.Sprintf("%d-%d", day, i), Spans: 1, MaxIngestedNanos: int64(day) * int64(24*time.Hour)}}) + } + } + if p.Generation0BatchCount() < CompactionDebtLimit || p.compactionDebt != 0 { + t.Fatalf("inventory=%d debt=%d", p.Generation0BatchCount(), p.compactionDebt) + } + if waited, err := p.WaitForCompaction(t.Context()); err != nil || waited != 0 { + t.Fatalf("irreducible inputs stalled: %s %v", waited, err) + } +} + +func TestCompactionDebtExcludesUnreclaimableInventory(t *testing.T) { + p := &ParquetStore{batches: make(map[string]*storedBatch)} + for i := 0; i < CompactionBatchLimit-1+CompactionDebtLimit/2; i++ { + p.installBatch(&storedBatch{metadata: BatchMetadata{ID: fmt.Sprint(i), Spans: 1, MaxIngestedNanos: 1}}) + want := max(0, i+1-(CompactionBatchLimit-1)) + if got := p.CompactionDebt(); got != want { + t.Fatalf("after install %d debt=%d want=%d", i, got, want) + } + } + p.installBatch(&storedBatch{metadata: BatchMetadata{ID: "oversized", Spans: CompactionMaxRows, MaxIngestedNanos: 1}}) + p.installBatch(&storedBatch{metadata: BatchMetadata{ID: "another-day", Spans: 1, MaxIngestedNanos: int64(24 * time.Hour)}}) + if got := p.CompactionDebt(); got != CompactionDebtLimit/2 { + t.Fatalf("unreclaimable inputs raised debt: %d", got) + } + p.mu.Lock() + p.setBatchLocked("0", nil) + p.mu.Unlock() + if got := p.CompactionDebt(); got != CompactionDebtLimit/2-1 { + t.Fatalf("retirement debt=%d", got) + } +} diff --git a/internal/telemetry/compaction_index_test.go b/internal/telemetry/compaction_index_test.go index c290a730..dc475d52 100644 --- a/internal/telemetry/compaction_index_test.go +++ b/internal/telemetry/compaction_index_test.go @@ -33,7 +33,7 @@ func TestCompactionStreamingIndexMatchesReread(t *testing.T) { spans[i] = Span{Namespace: fmt.Sprint("ns-", n%3), TraceID: fmt.Sprint("trace-", n%97), SpanID: fmt.Sprint("span-", n), StartUnixNanos: int64(n%11) - 5, EndUnixNanos: int64(n%11) + 5, IngestedAt: 100, Resource: map[string]any{"bytes": []byte{0, 255}, "typed": []any{int64(n), false}}, Attributes: map[string]any{"n": int64(n)}} } id := fmt.Sprint("input-", part) - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: id}, spans, nil, nil); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: id}, spans, nil, nil); err != nil { t.Fatal(err) } inputs = append(inputs, filepath.Join(store.BatchPath(id), "spans.parquet")) @@ -133,7 +133,7 @@ func TestCancelledSpanMergeRemovesOutputAndIndex(t *testing.T) { for i := range spans { spans[i] = Span{TraceID: fmt.Sprint("trace-", i), SpanID: fmt.Sprint(i), StartUnixNanos: int64(i), IngestedAt: 100} } - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "input"}, spans, nil, nil); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "input"}, spans, nil, nil); err != nil { t.Fatal(err) } base, cancel := context.WithCancel(t.Context()) diff --git a/internal/telemetry/event_bounds_test.go b/internal/telemetry/event_bounds_test.go index 1ccc183c..ce3bd353 100644 --- a/internal/telemetry/event_bounds_test.go +++ b/internal/telemetry/event_bounds_test.go @@ -18,7 +18,7 @@ func TestEventBoundsUsePhysicalNanosecondsAfterReopen(t *testing.T) { spans := []Span{{TraceID: "trace", SpanID: "negative", StartUnixNanos: -7, EndUnixNanos: -3, IngestedAt: 999}, {TraceID: "trace", SpanID: "positive", StartUnixNanos: 23, EndUnixNanos: 24, IngestedAt: 999}} logs := []Log{{EventUnixNanos: 5, TimeUnixNanos: 1, IngestedAt: 999}, {ObservedTimeNanos: 17, IngestedAt: 999}} metrics := []Metric{{EventUnixNanos: 11, TimeUnixNanos: 1, IngestedAt: 999}, {IngestedAt: 999}} - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "bounds"}, spans, logs, metrics); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "bounds"}, spans, logs, metrics); err != nil { t.Fatal(err) } store, err = OpenParquetStore(dir) diff --git a/internal/telemetry/metric_format_test.go b/internal/telemetry/metric_format_test.go index 77031e36..0e500bc1 100644 --- a/internal/telemetry/metric_format_test.go +++ b/internal/telemetry/metric_format_test.go @@ -19,7 +19,7 @@ func TestMetricPhysicalRowKeepsFidelityColumns(t *testing.T) { metric := Metric{Name: "net", Type: "sum", Temporality: "delta", Monotonic: true, StartTimeUnixNanos: 1790855940000000017, TimeUnixNanos: 1790856000000000009, IngestedAt: 1790856000000000010} metric.SeriesID = MetricSeriesID(metric) - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "fidelity"}, nil, nil, []Metric{metric}); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "fidelity"}, nil, nil, []Metric{metric}); err != nil { t.Fatal(err) } got := readOneParquetRow[metricParquetRow](t, filepath.Join(store.BatchPath("fidelity"), "metrics.parquet")) @@ -42,7 +42,7 @@ func TestFormatThreeIsRefusedBeforeCleanup(t *testing.T) { if err != nil { t.Fatal(err) } - err = store.CommitBatch(t.Context(), BatchMetadata{ID: "old"}, []Span{completeTestSpan()}, []Log{{Body: "ready", TimeUnixNanos: 1}}, + err = store.CommitBatch(t.Context(), &BatchMetadata{ID: "old"}, []Span{completeTestSpan()}, []Log{{Body: "ready", TimeUnixNanos: 1}}, []Metric{{Name: "n", Type: "gauge", TimeUnixNanos: 1, IngestedAt: 1}}) if err != nil { t.Fatal(err) @@ -128,7 +128,7 @@ func TestFormatFourRequiresNewMetricPhysicalSchema(t *testing.T) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "schema"}, nil, nil, + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "schema"}, nil, nil, []Metric{{Name: "n", Type: "sum", Monotonic: true, Temporality: "cumulative", TimeUnixNanos: 1, IngestedAt: 1}}); err != nil { t.Fatal(err) } @@ -165,7 +165,7 @@ func TestPartiallyRemovedRetiredBatchDoesNotStopOpen(t *testing.T) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "partial"}, + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "partial"}, []Span{completeTestSpan()}, []Log{{Body: "ready", TimeUnixNanos: 1}}, []Metric{{Name: "n", Type: "gauge", TimeUnixNanos: 1}}); err != nil { t.Fatal(err) @@ -211,7 +211,7 @@ func TestMetricPhysicalRowsReadBackThroughDuckDB(t *testing.T) { m.SeriesID = MetricSeriesID(m) metrics[i] = m } - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "readback"}, nil, nil, metrics); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "readback"}, nil, nil, metrics); err != nil { t.Fatal(err) } verifier, err := NewBatchVerifier(t.Context(), store.BatchPath("readback")) diff --git a/internal/telemetry/metric_series_test.go b/internal/telemetry/metric_series_test.go index 7629ada8..49cd0173 100644 --- a/internal/telemetry/metric_series_test.go +++ b/internal/telemetry/metric_series_test.go @@ -33,7 +33,7 @@ func TestMetricSeriesIDSurvivesParquetCompaction(t *testing.T) { m := Metric{Namespace: "test", Name: "net", Type: "gauge", TimeUnixNanos: int64(i + 1), Attributes: map[string]any{"nested": []any{map[string]any{"id": int64(i)}}}} m.SeriesID = MetricSeriesID(m) id := fmt.Sprintf("series%d", i) - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: id}, nil, nil, []Metric{m}); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: id}, nil, nil, []Metric{m}); err != nil { t.Fatal(err) } if err := ValidatePublishedBatch(store.BatchPath(id)); err != nil { diff --git a/internal/telemetry/parquet.go b/internal/telemetry/parquet.go index 4b8b2859..c7fc1c3e 100644 --- a/internal/telemetry/parquet.go +++ b/internal/telemetry/parquet.go @@ -84,12 +84,16 @@ type storedBatch struct { } type ParquetStore struct { - dir string - batchesDir string - stagingDir string - mu sync.RWMutex - publishGate chan struct{} - batches map[string]*storedBatch + dir string + batchesDir string + stagingDir string + mu sync.RWMutex + publishGate chan struct{} + batches map[string]*storedBatch + generation0Batches int + generation0ByDay map[int64]int + compactionDebt int + debtChanged chan struct{} } type ParquetStats struct { @@ -192,6 +196,17 @@ func (p *ParquetStore) BatchMetadata() []BatchMetadata { return out } +// batchMetadataByID returns one installed batch without scanning the catalog. +func (p *ParquetStore) batchMetadataByID(id string) (BatchMetadata, bool) { + p.mu.RLock() + defer p.mu.RUnlock() + batch, ok := p.batches[id] + if !ok { + return BatchMetadata{}, false + } + return batch.metadata, true +} + func (p *ParquetStore) RowCount() uint64 { p.mu.RLock() defer p.mu.RUnlock() @@ -205,15 +220,17 @@ func (p *ParquetStore) RowCount() uint64 { // CommitBatch publishes one atomic batch directory. Preparation is allowed to // finish; only the final publish-gate wait is capped. A stalled publication // therefore cannot hang ingest, while a large valid encode does not consume -// the gate budget before it starts waiting. -func (p *ParquetStore) CommitBatch(ctx context.Context, metadata BatchMetadata, spans []Span, logs []Log, metrics []Metric) error { +// the gate budget before it starts waiting. On success metadata is replaced +// with the actual published metadata, including an adopted earlier attempt. +func (p *ParquetStore) CommitBatch(ctx context.Context, metadata *BatchMetadata, spans []Span, logs []Log, metrics []Metric) error { if err := ValidateBatchID(metadata.ID); err != nil { return err } metadata.Version = batchMetadataVersion metadata.Spans, metadata.Logs, metadata.Metrics = len(spans), len(logs), len(metrics) final := p.BatchPath(metadata.ID) - if p.hasBatch(metadata.ID) { + if existing, ok := p.batchMetadataByID(metadata.ID); ok { + *metadata = existing return nil } if info, err := os.Stat(final); err == nil && info.IsDir() { @@ -233,6 +250,7 @@ func (p *ParquetStore) CommitBatch(ctx context.Context, metadata BatchMetadata, return err } p.installBatch(adopted) + *metadata = adopted.metadata return nil } else if err != nil && !errors.Is(err, os.ErrNotExist) { return err @@ -339,7 +357,8 @@ func (p *ParquetStore) CommitBatch(ctx context.Context, metadata BatchMetadata, return err } defer p.unlockPublish() - if p.hasBatch(metadata.ID) { + if existing, ok := p.batchMetadataByID(metadata.ID); ok { + *metadata = existing complete = true return os.RemoveAll(stage) } @@ -352,7 +371,11 @@ func (p *ParquetStore) CommitBatch(ctx context.Context, metadata BatchMetadata, if err := syncDirectory(p.batchesDir); err != nil { return errors.Join(err, removeErr) } - return errors.Join(p.registerBatch(final), removeErr) + if err := p.registerBatch(final); err != nil { + return errors.Join(err, removeErr) + } + *metadata, _ = p.batchMetadataByID(metadata.ID) + return removeErr } return fmt.Errorf("publish Parquet batch: %w", err) } @@ -361,8 +384,9 @@ func (p *ParquetStore) CommitBatch(ctx context.Context, metadata BatchMetadata, return err } p.mu.Lock() - p.batches[metadata.ID] = prepared + p.setBatchLocked(metadata.ID, prepared) p.mu.Unlock() + *metadata = prepared.metadata return nil } @@ -435,9 +459,9 @@ func (p *ParquetStore) RestoreRetiredInputs(inputs []string, replacementID strin defer p.mu.Unlock() for _, input := range prepared { if _, err := os.Stat(input.active); err == nil { - p.batches[input.id] = input.batch + p.setBatchLocked(input.id, input.batch) } else { - delete(p.batches, input.id) + p.setBatchLocked(input.id, nil) } } } @@ -707,7 +731,7 @@ func (p *ParquetStore) PruneBefore(cutoff int64, maxBatches int, publish func(fu } p.mu.Lock() for _, id := range retiredIDs { - delete(p.batches, id) + p.setBatchLocked(id, nil) } p.mu.Unlock() return nil @@ -828,9 +852,9 @@ func (p *ParquetStore) PublishReplacement(stage string, metadata BatchMetadata, p.mu.Lock() defer p.mu.Unlock() for _, id := range inputs { - delete(p.batches, id) + p.setBatchLocked(id, nil) } - p.batches[metadata.ID] = replacement + p.setBatchLocked(metadata.ID, replacement) } rollback := func() error { var rollbackErr error @@ -844,12 +868,12 @@ func (p *ParquetStore) PublishReplacement(stage string, metadata BatchMetadata, } } p.mu.Lock() - delete(p.batches, metadata.ID) + p.setBatchLocked(metadata.ID, nil) for id := range inputBatches { - delete(p.batches, id) + p.setBatchLocked(id, nil) } for id, batch := range restore { - p.batches[id] = batch + p.setBatchLocked(id, batch) } p.mu.Unlock() return errors.Join(rollbackErr, syncDirectory(p.batchesDir)) @@ -866,7 +890,7 @@ func (p *ParquetStore) PublishReplacement(stage string, metadata BatchMetadata, } source = stage p.mu.Lock() - delete(p.batches, metadata.ID) + p.setBatchLocked(metadata.ID, nil) p.mu.Unlock() } for _, id := range inputs { @@ -1097,7 +1121,7 @@ func verifyTypedParquet[T any](path string, expected int, visit func(T, uint64) // installBatch publishes a validated batch into the queryable set. func (p *ParquetStore) installBatch(batch *storedBatch) { p.mu.Lock() - p.batches[batch.metadata.ID] = batch + p.setBatchLocked(batch.metadata.ID, batch) p.mu.Unlock() } @@ -1213,13 +1237,6 @@ func parquetTimeRange(file *parquet.File, column string) TimeRange { return result } -func (p *ParquetStore) hasBatch(id string) bool { - p.mu.RLock() - _, ok := p.batches[id] - p.mu.RUnlock() - return ok -} - func spanSortingColumns() parquet.SortingOption { return parquet.SortingColumns( parquet.Ascending("_trace_hash"), diff --git a/internal/telemetry/parquet_encoding_test.go b/internal/telemetry/parquet_encoding_test.go index c94ce1d4..98c64205 100644 --- a/internal/telemetry/parquet_encoding_test.go +++ b/internal/telemetry/parquet_encoding_test.go @@ -30,7 +30,7 @@ func TestSpanParquetDictionaryEncodesLowCardinalityColumns(t *testing.T) { spans[i] = Span{Namespace: "prod", TraceID: strings.Repeat("a", 30) + string(rune('a'+i%26)) + string(rune('a'+i/26)), SpanID: strings.Repeat("b", 14) + string(rune('a'+i%26)) + string(rune('a'+i/26)), ServiceName: "checkout", Name: "POST /orders", Kind: "SPAN_KIND_SERVER", StatusCode: "STATUS_CODE_UNSET", StartUnixNanos: int64(i + 1), EndUnixNanos: int64(i + 2), IngestedAt: 999} } - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "encodings"}, spans, nil, nil); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "encodings"}, spans, nil, nil); err != nil { t.Fatal(err) } f, err := os.Open(filepath.Join(store.BatchPath("encodings"), "spans.parquet")) @@ -84,7 +84,7 @@ func TestSpanDictionaryFallsBackToPlainPastItsBound(t *testing.T) { ServiceName: "checkout", HTTPRoute: fmt.Sprintf("/%0100d", i), Name: "op", Kind: "SPAN_KIND_SERVER", StatusCode: "STATUS_CODE_OK", StartUnixNanos: int64(i + 1), EndUnixNanos: int64(i + 2), IngestedAt: 999} } - if err := store.CommitBatch(t.Context(), BatchMetadata{ID: "bounded"}, spans, nil, nil); err != nil { + if err := store.CommitBatch(t.Context(), &BatchMetadata{ID: "bounded"}, spans, nil, nil); err != nil { t.Fatal(err) } f, err := os.Open(filepath.Join(store.BatchPath("bounded"), "spans.parquet")) diff --git a/internal/telemetry/parquet_test.go b/internal/telemetry/parquet_test.go index df0e7c20..be6f8b69 100644 --- a/internal/telemetry/parquet_test.go +++ b/internal/telemetry/parquet_test.go @@ -25,7 +25,7 @@ func TestParquetStorePublishesCompleteBatchAndRecovers(t *testing.T) { } span := completeTestSpan() metadata := BatchMetadata{ID: "batch-1", MinIngestedNanos: span.IngestedAt, MaxIngestedNanos: span.IngestedAt} - if err := store.CommitBatch(context.Background(), metadata, []Span{span}, []Log{{Namespace: "tenant", Body: "ready", TimeUnixNanos: 12}}, []Metric{{Namespace: "tenant", Name: "requests", TimeUnixNanos: 13}}); err != nil { + if err := store.CommitBatch(context.Background(), &metadata, []Span{span}, []Log{{Namespace: "tenant", Body: "ready", TimeUnixNanos: 12}}, []Metric{{Namespace: "tenant", Name: "requests", TimeUnixNanos: 13}}); err != nil { t.Fatal(err) } @@ -38,7 +38,7 @@ func TestParquetStorePublishesCompleteBatchAndRecovers(t *testing.T) { if got := store.RowCount(); got != 3 { t.Fatalf("row count = %d, want 3", got) } - if err := store.CommitBatch(context.Background(), metadata, []Span{span}, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &metadata, []Span{span}, nil, nil); err != nil { t.Fatalf("idempotent commit: %v", err) } if got := store.RowCount(); got != 3 { @@ -94,7 +94,7 @@ func TestParquetStoreTraceUsesExactIDAndEventOrder(t *testing.T) { {TraceID: "other", SpanID: "other", StartUnixNanos: 20}, {TraceID: "wanted", SpanID: "earlier", StartUnixNanos: 10}, } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "batch"}, spans, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "batch"}, spans, nil, nil); err != nil { t.Fatal(err) } got, err := traceAll(store, "wanted") @@ -115,7 +115,7 @@ func TestValidatePublishedBatchDetectsTraceIndexDataDivergence(t *testing.T) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "diverged"}, []Span{{ + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "diverged"}, []Span{{ TraceID: "trace", SpanID: "span", StartUnixNanos: 1, }}, nil, nil); err != nil { t.Fatal(err) @@ -159,7 +159,7 @@ func TestParquetStoreTraceFiltersAndBoundsResultsDuringRead(t *testing.T) { Span{Namespace: "staging", TraceID: "large-trace", SpanID: "wrong-namespace", StartUnixNanos: 11}, Span{Namespace: "prod", TraceID: "large-trace", SpanID: "outside-window", StartUnixNanos: 200}, ) - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "large"}, spans, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "large"}, spans, nil, nil); err != nil { t.Fatal(err) } @@ -193,7 +193,7 @@ func TestParquetStorePreservesCompleteLogAndMetricRows(t *testing.T) { ExemplarsJSON: `[{"trace_id":"trace"}]`, Attributes: map[string]any{"route": "/pay"}, Resource: map[string]any{"host": "one"}, ScopeName: "scope", ScopeVersion: "1.2.3", IngestedAt: 24, } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "complete-signals"}, nil, []Log{logRow}, []Metric{metricRow}); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "complete-signals"}, nil, []Log{logRow}, []Metric{metricRow}); err != nil { t.Fatal(err) } batchDir := store.BatchPath("complete-signals") @@ -218,7 +218,7 @@ func TestParquetStoreSkipsTraceIndexesOutsideTimeWindow(t *testing.T) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "old-traces"}, []Span{{ + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "old-traces"}, []Span{{ TraceID: "wanted", SpanID: "old", StartUnixNanos: 100, }}, nil, nil); err != nil { t.Fatal(err) @@ -261,7 +261,7 @@ func TestPruneReaderWaitDoesNotBlockCommit(t *testing.T) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "expired", MaxIngestedNanos: 1}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "expired", MaxIngestedNanos: 1}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { t.Fatal(err) } entered := make(chan struct{}) @@ -282,7 +282,7 @@ func TestPruneReaderWaitDoesNotBlockCommit(t *testing.T) { } commitDone := make(chan error, 1) go func() { - commitDone <- store.CommitBatch(context.Background(), BatchMetadata{ID: "concurrent", MaxIngestedNanos: 3}, []Span{{TraceID: "trace-2"}}, nil, nil) + commitDone <- store.CommitBatch(context.Background(), &BatchMetadata{ID: "concurrent", MaxIngestedNanos: 3}, []Span{{TraceID: "trace-2"}}, nil, nil) }() select { case err := <-commitDone: @@ -303,7 +303,7 @@ func TestPrunePublicationContextBoundsStorageLockWait(t *testing.T) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "expired", MaxIngestedNanos: 1}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "expired", MaxIngestedNanos: 1}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { t.Fatal(err) } if err := store.lockPublish(context.Background()); err != nil { @@ -330,11 +330,11 @@ func TestReplacementReaderWaitDoesNotBlockCommit(t *testing.T) { t.Fatal(err) } span := []Span{{TraceID: "trace", SpanID: "span", StartUnixNanos: 1}} - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "input"}, span, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "input"}, span, nil, nil); err != nil { t.Fatal(err) } output := BatchMetadata{ID: "output"} - if err := store.CommitBatch(context.Background(), output, span, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &output, span, nil, nil); err != nil { t.Fatal(err) } entered := make(chan struct{}) @@ -355,7 +355,7 @@ func TestReplacementReaderWaitDoesNotBlockCommit(t *testing.T) { } commitDone := make(chan error, 1) go func() { - commitDone <- store.CommitBatch(context.Background(), BatchMetadata{ID: "concurrent"}, []Span{{TraceID: "trace-2"}}, nil, nil) + commitDone <- store.CommitBatch(context.Background(), &BatchMetadata{ID: "concurrent"}, []Span{{TraceID: "trace-2"}}, nil, nil) }() select { case err := <-commitDone: @@ -377,11 +377,11 @@ func TestPublishReplacementKeepsOutputOnlyAfterSyncFailure(t *testing.T) { t.Fatal(err) } span := []Span{{TraceID: "trace", SpanID: "span", StartUnixNanos: 1}} - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "input"}, span, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "input"}, span, nil, nil); err != nil { t.Fatal(err) } output := BatchMetadata{ID: "output"} - if err := store.CommitBatch(context.Background(), output, span, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &output, span, nil, nil); err != nil { t.Fatal(err) } originalSync := syncPublishedDirectory @@ -412,11 +412,11 @@ func TestPublishReplacementUnpublishesRecoveredOutputBeforeRetiringInputs(t *tes t.Fatal(err) } span := []Span{{TraceID: "trace", SpanID: "span", StartUnixNanos: 1}} - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "input"}, span, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "input"}, span, nil, nil); err != nil { t.Fatal(err) } output := BatchMetadata{ID: "output"} - if err := store.CommitBatch(context.Background(), output, span, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &output, span, nil, nil); err != nil { t.Fatal(err) } blockedRetired := filepath.Join(store.BatchesDir(), "input.retired-output") @@ -454,7 +454,7 @@ func TestParquetStoreRejectsUnsafeBatchID(t *testing.T) { t.Fatal(err) } for _, id := range []string{"", ".hidden", "../escape", "has space"} { - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: id}, []Span{{TraceID: "t"}}, nil, nil); err == nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: id}, []Span{{TraceID: "t"}}, nil, nil); err == nil { t.Fatalf("CommitBatch accepted unsafe ID %q", id) } } @@ -466,7 +466,7 @@ func TestParquetStoreRejectsMetadataRowCountMismatchOnOpen(t *testing.T) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "mismatch"}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "mismatch"}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { t.Fatal(err) } metadataPath := filepath.Join(store.BatchPath("mismatch"), "metadata.json") @@ -546,7 +546,7 @@ func TestCommitBatchDoesNotBlockIndefinitelyOnStalledPublication(t *testing.T) { metadata := BatchMetadata{ID: "batch-stalled", MinIngestedNanos: span.IngestedAt, MaxIngestedNanos: span.IngestedAt} done := make(chan error, 1) - go func() { done <- store.CommitBatch(ctx, metadata, []Span{span}, nil, nil) }() + go func() { done <- store.CommitBatch(ctx, &metadata, []Span{span}, nil, nil) }() select { case err := <-done: if !errors.Is(err, context.DeadlineExceeded) { diff --git a/internal/telemetry/store/backpressure_test.go b/internal/telemetry/store/backpressure_test.go new file mode 100644 index 00000000..2b3d68b5 --- /dev/null +++ b/internal/telemetry/store/backpressure_test.go @@ -0,0 +1,283 @@ +package store + +import ( + "context" + "fmt" + "strings" + "sync" + "sync/atomic" + "testing" + "testing/synctest" + "time" + + "github.com/labstack/fanout/internal/metrics" + "github.com/labstack/fanout/internal/telemetry" + "github.com/prometheus/client_golang/prometheus/testutil" +) + +type blockedCompactionCommitter struct { + entered, release, committed chan struct{} + once sync.Once +} + +func (s *blockedCompactionCommitter) Commit(context.Context, Batch) error { + s.once.Do(func() { close(s.committed) }) + return nil +} +func (s *blockedCompactionCommitter) CompactionDebt() int { return 0 } + +func (s *blockedCompactionCommitter) WaitForCompaction(ctx context.Context) (time.Duration, error) { + select { + case s.entered <- struct{}{}: + default: + } + at := time.Now() + select { + case <-s.release: + return time.Since(at), nil + case <-ctx.Done(): + return time.Since(at), ctx.Err() + } +} +func TestWriterBackpressureKeepsSubmissionsQueuedAndHonorsContexts(t *testing.T) { + before := testutil.ToFloat64(metrics.IngestBackpressureSeconds) + s := &blockedCompactionCommitter{entered: make(chan struct{}, 1), release: make(chan struct{}), committed: make(chan struct{})} + w := NewWriter(nil, 50000) + w.repository = s + ctx, cancel := context.WithCancel(t.Context()) + defer cancel() + done := make(chan error, 1) + go func() { done <- w.Run(ctx) }() + <-s.entered + submitCtx, stop := context.WithTimeout(t.Context(), 20*time.Millisecond) + defer stop() + if err := w.Submit(submitCtx, testBatch()); err != context.DeadlineExceeded { + t.Fatalf("submit=%v", err) + } + if len(w.submissions) != 1 { + t.Fatalf("queued=%d", len(w.submissions)) + } + select { + case <-s.committed: + t.Fatal("committed while debt blocked") + default: + } + close(s.release) + select { + case <-s.committed: + case <-time.After(time.Second): + t.Fatal("retirement did not unblock writer") + } + cancel() + if err := <-done; err != nil { + t.Fatal(err) + } + if testutil.ToFloat64(metrics.IngestBackpressureSeconds) <= before { + t.Fatal("writer wait time not counted") + } +} +func TestWriterBackpressureStopsOnShutdown(t *testing.T) { + s := &blockedCompactionCommitter{entered: make(chan struct{}, 1), release: make(chan struct{}), committed: make(chan struct{})} + w := NewWriter(nil, 50000) + w.repository = s + ctx, cancel := context.WithCancel(t.Context()) + done := make(chan error, 1) + go func() { done <- w.Run(ctx) }() + <-s.entered + cancel() + select { + case err := <-done: + if err != nil { + t.Fatal(err) + } + case <-time.After(time.Second): + t.Fatal("shutdown stuck behind debt") + } +} +func TestCompactionPressureDrainsGenerationZeroBeforeHigherGenerations(t *testing.T) { + for _, mode := range []string{"current", "finished", "higher-same-day", "higher-older-day"} { + t.Run(mode, func(t *testing.T) { + var batches []telemetry.BatchMetadata + count := telemetry.CompactionDebtLimit + telemetry.CompactionBatchLimit - 1 + for i := 0; i < count; i++ { + batches = append(batches, telemetry.BatchMetadata{ID: fmt.Sprint(i), Spans: 5000, MaxIngestedNanos: 1}) + } + if mode == "finished" { + batches = append(batches, telemetry.BatchMetadata{ID: "new-day", Spans: 1, MaxIngestedNanos: int64(24*time.Hour) + 1}) + } + if mode == "higher-same-day" || mode == "higher-older-day" { + stamp := int64(1) + if mode == "higher-older-day" { + // Keep all stamps positive; generation 0 belongs to day 1. + for i := range batches { + batches[i].MaxIngestedNanos += int64(24 * time.Hour) + } + stamp = 1 + } + for i := 0; i < 128; i++ { + batches = append(batches, telemetry.BatchMetadata{ID: fmt.Sprint("higher", i), Generation: 1, Spans: 5000, MaxIngestedNanos: stamp}) + } + } + debt := telemetry.CompactionDebtLimit + for pass := 0; debt >= telemetry.CompactionDebtLimit/2; pass++ { + selected := selectCompactionBatches(batches, 128, debt) + if len(selected) < 2 { + t.Fatal("positive debt has no selection") + } + if selected[0].Generation != 0 { + t.Fatalf("debt=%d selected generation %d before eligible generation 0", debt, selected[0].Generation) + } + debt -= len(selected) + remove := map[string]bool{} + for _, b := range selected { + remove[b.ID] = true + } + var next []telemetry.BatchMetadata + for _, b := range batches { + if !remove[b.ID] { + next = append(next, b) + } + } + output := selected[0] + output.ID = fmt.Sprint("output", pass) + output.Generation++ + output.Spans *= len(selected) + next = append(next, output) + batches = next + } + if strings.HasPrefix(mode, "higher-") { + selected := selectCompactionBatches(batches, 128, debt) + if len(selected) < 2 || selected[0].Generation == 0 { + t.Fatalf("higher generations did not resume at debt=%d: %v", debt, selected) + } + } + }) + } + // Finished days with eight batches are selectable, but fewer than eight + // per day and individually oversized inputs prove a raw-count stall unsafe. + var small []telemetry.BatchMetadata + for i := 0; i < 8; i++ { + small = append(small, telemetry.BatchMetadata{ID: fmt.Sprint(i), Spans: 1, MaxIngestedNanos: 1}) + } + small = append(small, telemetry.BatchMetadata{ID: "today", Spans: 1, MaxIngestedNanos: int64(24*time.Hour) + 1}) + if len(selectCompactionBatches(small, 128, 0)) != 8 { + t.Fatal("finished eight-input group stranded") + } + var terminal []telemetry.BatchMetadata + for i := 0; i < 1024; i++ { + terminal = append(terminal, telemetry.BatchMetadata{ID: fmt.Sprint(i), Spans: maxCompactionRows, MaxIngestedNanos: 1}) + } + if len(selectCompactionBatches(terminal, 128, 0)) != 0 { + t.Fatal("terminal counterexample changed") + } +} + +type pressureRecordingCommitter struct { + *recordingCommitter + debt atomic.Int64 +} + +func (c *pressureRecordingCommitter) WaitForCompaction(ctx context.Context) (time.Duration, error) { + return 0, ctx.Err() +} +func (c *pressureRecordingCommitter) CompactionDebt() int { return int(c.debt.Load()) } + +func TestWriterAdaptsAdmissionToReclaimableDebt(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + c := &pressureRecordingCommitter{recordingCommitter: &recordingCommitter{}} + w := testWriter(c, maxGroupBatchRows) + ctx, cancel := context.WithCancel(t.Context()) + done := make(chan error, 1) + go func() { done <- w.Run(ctx) }() + defer func() { + cancel() + if err := <-done; err != nil { + t.Fatal(err) + } + }() + for _, debt := range []int{telemetry.CompactionDebtLimit/2 - 1, telemetry.CompactionDebtLimit / 2, telemetry.CompactionDebtLimit/2 + 1, 0} { + c.debt.Store(int64(debt)) + before := len(c.batches) + acks := make(chan error, 2) + var latencies [2]time.Duration + submit := func(i int) { + at := time.Now() + err := w.Submit(ctx, testBatch()) + latencies[i] = time.Since(at) + acks <- err + } + go submit(0) + synctest.Wait() + time.Sleep(20 * time.Millisecond) + go submit(1) + synctest.Wait() + time.Sleep(300 * time.Millisecond) + for range 2 { + if err := <-acks; err != nil { + t.Fatal(err) + } + } + synctest.Wait() + want := 2 + wantLatency := [2]time.Duration{10 * time.Millisecond, 10 * time.Millisecond} + if debt >= telemetry.CompactionDebtLimit/2 { + want = 1 + wantLatency = [2]time.Duration{250 * time.Millisecond, 230 * time.Millisecond} + } + if latencies != wantLatency { + t.Fatalf("debt=%d acknowledgement latencies=%v want=%v", debt, latencies, wantLatency) + } + if got := len(c.batches) - before; got != want { + t.Fatalf("debt=%d batches=%d want=%d", debt, got, want) + } + rows := 0 + for _, b := range c.batches[before:] { + rows += batchRows(b) + } + if rows != 2*batchRows(testBatch()) { + t.Fatalf("lost rows at debt=%d: %d", debt, rows) + } + } + }) +} + +func TestWriterPressureAdmissionClosesAtEveryBound(t *testing.T) { + for _, bound := range []string{"rows", "requests", "bytes"} { + t.Run(bound, func(t *testing.T) { + synctest.Test(t, func(t *testing.T) { + c := &pressureRecordingCommitter{recordingCommitter: &recordingCommitter{}} + c.debt.Store(telemetry.CompactionDebtLimit / 2) + w := testWriter(c, maxGroupBatchRows) + w.compaction = c + w.submissions = make(chan submission, maxAdmissionRequests) + request := submission{batch: Batch{Spans: []telemetry.Span{{SpanID: "first"}}}, ack: make(chan error, 1)} + switch bound { + case "rows": + request.batch.Spans = make([]telemetry.Span, maxGroupBatchRows) + case "requests": + for range maxAdmissionRequests - 1 { + w.submissions <- request + } + case "bytes": + request.bytes = maxGroupBatchBytes / 2 + w.submissions <- request + } + out := make(chan commitJob, maxAdmissionRequests) + at := time.Now() + if err := w.enqueueSubmissions(t.Context(), request, out); err != nil { + t.Fatal(err) + } + if elapsed := time.Since(at); elapsed != 0 { + t.Fatalf("%s bound waited %v", bound, elapsed) + } + if len(out) != 1 { + t.Fatalf("jobs=%d", len(out)) + } + job := <-out + if len(job.acks) > maxAdmissionRequests || batchRows(job.batches[0]) > maxGroupBatchRows { + t.Fatal("group bound exceeded") + } + }) + }) + } +} diff --git a/internal/telemetry/store/compaction.go b/internal/telemetry/store/compaction.go index d7f31f38..e1ecf979 100644 --- a/internal/telemetry/store/compaction.go +++ b/internal/telemetry/store/compaction.go @@ -16,7 +16,7 @@ import ( ) const ( - maxCompactionRows = 25_000_000 + maxCompactionRows = telemetry.CompactionMaxRows // maxCompactionBytes bounds a pass by the bytes it admits, because that is // what a merge costs: parquet-go opens a cursor per row group across every @@ -145,7 +145,7 @@ func (r *Repository) CompactParquet(ctx context.Context, publisher ParquetPublis } // A pass that was killed mid-merge left a record of how much it tried to // take. Take less. - selected := selectCompactionBatches(r.Parquet.BatchMetadata(), compactionBatchCap(maxBatches, readCompactionAttempt(r.root))) + selected := selectCompactionBatches(r.Parquet.BatchMetadata(), compactionBatchCap(maxBatches, readCompactionAttempt(r.root)), r.Parquet.CompactionDebt()) if len(selected) < minCompactionMergeInputs { return 0, nil } @@ -259,7 +259,7 @@ func (r *Repository) CompactParquet(ctx context.Context, publisher ParquetPublis return len(selected), nil } -func selectCompactionBatches(batches []telemetry.BatchMetadata, maxBatches int) []telemetry.BatchMetadata { +func selectCompactionBatches(batches []telemetry.BatchMetadata, maxBatches, debt int) []telemetry.BatchMetadata { // minCompactionInputs is a "worth the effort" policy and belongs to the // caller, which applies it to the ceiling it was asked for. Here the floor // is only what a merge needs: after an interrupted pass the ceiling is @@ -276,28 +276,12 @@ func selectCompactionBatches(batches []telemetry.BatchMetadata, maxBatches int) key := compactionKey{day: batch.MaxIngestedNanos / int64(24*time.Hour), generation: batch.Generation} groups[key] = append(groups[key], batch) } - // Within a day, take the HIGHEST generation that has a compactable group, - // not the lowest. - // - // Lowest-first starves everything above it. Ingest refills generation 0 - // continuously, so if it always wins no later generation is ever selected, - // while each pass it does run adds one more batch to the generation above. - // Observed on the live box as 508 / 371 / 290 batches at generations - // 0 / 1 / 2, generation 2 untouched for hours, and the live file count - // settling at an equilibrium instead of falling. That count is what every - // query pays per-file overhead on, so an equilibrium there is a permanent - // tax rather than a backlog that clears. - // - // Highest-first cannot starve anything. A generation above 0 only grows by - // one batch per pass of the generation below it, so its group fills slowly - // and empties in a few passes; once it no longer has a full group it stops - // being a candidate and generation 0 -- which is almost always ready -- - // takes every remaining pass. Reducing the count by a group is worth the - // same wherever it happens, because the cost being reduced is per file. - // - // The older day still wins outright. Reclaiming space retention is about to - // drop matters more than consolidating today, and a day no longer being - // written finishes and stays finished. + // Under writer pressure, reclaim generation-0 debt before starting a + // potentially long higher-generation merge, even on an older day. Within + // that priority keep the normal order: oldest day, then highest generation. + // Below pressure, higher generations run first within each day so continuous + // ingest cannot starve them. + pressure := debt >= telemetry.CompactionDebtLimit/2 newestDay := int64(math.MinInt64) for key := range groups { if key.day > newestDay { @@ -312,9 +296,11 @@ func selectCompactionBatches(batches []telemetry.BatchMetadata, maxBatches int) if len(candidate) < 2 { continue } - better := !found || - key.day < chosen.day || - key.day == chosen.day && key.generation > chosen.generation + priority := pressure && key.generation == 0 + chosenPriority := pressure && chosen.generation == 0 + better := !found || priority && !chosenPriority || + priority == chosenPriority && (key.day < chosen.day || + key.day == chosen.day && key.generation > chosen.generation) if better { chosen, selected, found = key, candidate, true } diff --git a/internal/telemetry/store/compaction_starvation_test.go b/internal/telemetry/store/compaction_starvation_test.go index 28f70953..dc287f13 100644 --- a/internal/telemetry/store/compaction_starvation_test.go +++ b/internal/telemetry/store/compaction_starvation_test.go @@ -34,7 +34,7 @@ func TestSelectCompactionBatchesDoesNotStarveHigherGenerations(t *testing.T) { // so both are valid candidates and the tie-break decides. batches := append(genBatches(1, 0, 508, 1_000), genBatches(1, 2, 290, 200_000)...) - selected := selectCompactionBatches(batches, 128) + selected := selectCompactionBatches(batches, 128, 0) if len(selected) == 0 { t.Fatal("selected nothing with two compactable groups available") } @@ -50,7 +50,7 @@ func TestSelectCompactionBatchesDoesNotStarveHigherGenerations(t *testing.T) { func TestSelectCompactionBatchesStillPrefersTheOlderDay(t *testing.T) { batches := append(genBatches(1, 0, 200, 1_000), genBatches(5, 2, 290, 200_000)...) - selected := selectCompactionBatches(batches, 128) + selected := selectCompactionBatches(batches, 128, 0) if len(selected) == 0 { t.Fatal("selected nothing") } @@ -60,13 +60,51 @@ func TestSelectCompactionBatchesStillPrefersTheOlderDay(t *testing.T) { } } +func TestSelectCompactionBatchesPressureThreshold(t *testing.T) { + for _, debt := range []int{telemetry.CompactionDebtLimit/2 - 1, telemetry.CompactionDebtLimit / 2, telemetry.CompactionDebtLimit/2 + 1} { + t.Run(fmt.Sprint(debt), func(t *testing.T) { + // Debt excludes the reserved underfilled group for the day. + batches := append(genBatches(2, 0, telemetry.CompactionBatchLimit-1+debt, 1000), genBatches(2, 2, 128, 200_000)...) + want := uint32(2) + if debt >= telemetry.CompactionDebtLimit/2 { + want = 0 + } + selected := selectCompactionBatches(batches, 128, debt) + if len(selected) < 2 || selected[0].Generation != want { + t.Fatalf("debt=%d selected=%v want generation %d", debt, selected, want) + } + }) + } +} + +func TestSelectCompactionBatchesPressureKeepsOldestEligibleGenerationZero(t *testing.T) { + for _, cap := range []int{2, 8, 128} { + t.Run(fmt.Sprint(cap), func(t *testing.T) { + batches := genBatches(1, 2, 128, 1000) + // An older day has generation 0, but cannot form a merge. + batches = append(batches, genBatches(1, 0, 1, 1000)...) + batches = append(batches, genBatches(2, 0, 8, 1000)...) + batches = append(batches, genBatches(3, 0, 1200, 1000)...) + selected := selectCompactionBatches(batches, cap, telemetry.CompactionDebtLimit) + if len(selected) != min(cap, 8) || selected[0].Generation != 0 || selected[0].MaxIngestedNanos/int64(24*time.Hour) != 2 { + t.Fatalf("selected=%v, want oldest eligible generation-0 group within cap %d", selected, cap) + } + // Clearing pressure restores the older higher-generation group. + selected = selectCompactionBatches(batches, cap, 0) + if len(selected) < 2 || selected[0].Generation != 2 || selected[0].MaxIngestedNanos/int64(24*time.Hour) != 1 { + t.Fatalf("normal order did not resume: %v", selected) + } + }) + } +} + // Generation 0 must still be served: it is refilled constantly, so once the // higher generations no longer have a full group it should take every pass. func TestSelectCompactionBatchesServesGenerationZeroWhenNothingIsPiledAbove(t *testing.T) { // Only generation 0 has enough to form a group. batches := append(genBatches(1, 0, 200, 1_000), genBatches(1, 2, 3, 1_000)...) - selected := selectCompactionBatches(batches, 128) + selected := selectCompactionBatches(batches, 128, 0) if len(selected) == 0 { t.Fatal("selected nothing with a full generation-0 group available") } diff --git a/internal/telemetry/store/publication_test.go b/internal/telemetry/store/publication_test.go new file mode 100644 index 00000000..e2e0d1a1 --- /dev/null +++ b/internal/telemetry/store/publication_test.go @@ -0,0 +1,156 @@ +package store + +import ( + "fmt" + "os" + "testing" + "time" + + "github.com/labstack/fanout/internal/telemetry" +) + +func TestPublicationHorizonWaitsForEarlierAttempts(t *testing.T) { + r := &Repository{} + a := r.beginPublication(100) + b := r.beginPublication(90) + if a != 100 || b != 101 { + t.Fatalf("stamps %d %d", a, b) + } + r.finishPublication(b, telemetry.BatchMetadata{MinIngestedNanos: b, MaxIngestedNanos: b}) + if h, p, _ := r.PublicationBounds(); h != 99 || p != 101 { + t.Fatalf("bounds %d %d", h, p) + } + r.finishPublication(a, telemetry.BatchMetadata{MinIngestedNanos: a, MaxIngestedNanos: a}) + if h, p, lo := r.PublicationBounds(); h != 101 || p != 101 || lo != 100 { + t.Fatalf("bounds %d %d %d", h, p, lo) + } +} +func TestCommitRetryRestampsEverySignal(t *testing.T) { + r, err := Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + defer r.Close() + batch := testBatch() + path := r.Parquet.BatchPath(batch.ID) + if err := os.WriteFile(path, []byte("block rename"), 0600); err != nil { + t.Fatal(err) + } + if err := r.Commit(t.Context(), batch); err == nil { + t.Fatal("blocked rename succeeded") + } + if err := os.Remove(path); err != nil { + t.Fatal(err) + } + failed := batch.Spans[0].IngestedAt + if err := r.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } + stamp := batch.Spans[0].IngestedAt + if stamp <= failed || batch.Logs[0].IngestedAt != stamp || batch.Metrics[0].IngestedAt != stamp { + t.Fatalf("retry did not restamp all rows: %#v", batch) + } + h, p, lo := r.PublicationBounds() + if h != stamp || p != stamp || lo != failed { + t.Fatalf("bounds %d %d %d stamp %d", h, p, lo, stamp) + } + rows, err := traceAll(r, "trace-1") + if err != nil || len(rows) != 1 { + t.Fatalf("published retry: %#v %v", rows, err) + } +} +func TestPublicationStampsStayMonotonicAcrossRestart(t *testing.T) { + dir := t.TempDir() + r, err := Open(dir) + if err != nil { + t.Fatal(err) + } + // Simulate a clock ahead of wall time, then a backwards clock on reopen. + r.lastStamp = time.Now().Add(time.Hour).UnixNano() + batch := testBatch() + if err := r.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } + previous := batch.Spans[0].IngestedAt + if err := r.Close(); err != nil { + t.Fatal(err) + } + r, err = Open(dir) + if err != nil { + t.Fatal(err) + } + defer r.Close() + batch.ID = "after-restart" + if err := r.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } + if batch.Spans[0].IngestedAt != previous+1 { + t.Fatalf("stamp %d after %d", batch.Spans[0].IngestedAt, previous) + } +} + +func TestCommitAdoptsPriorAttemptStamp(t *testing.T) { + r, err := Open(t.TempDir()) + if err != nil { + t.Fatal(err) + } + defer r.Close() + batch := testBatch() + // A durable directory from an earlier attempt can be registered on retry. + normalizeBatch(&batch, 100) + if err := r.Parquet.CommitBatch(t.Context(), &telemetry.BatchMetadata{ID: batch.ID, MinIngestedNanos: 100, MaxIngestedNanos: 100}, batch.Spans, batch.Logs, batch.Metrics); err != nil { + t.Fatal(err) + } + if err := r.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } + _, published, minimum := r.PublicationBounds() + if published != 100 || minimum != 100 { + t.Fatalf("adopted bounds %d %d", published, minimum) + } +} + +func TestGenerationZeroInventorySurvivesRestartAndCompaction(t *testing.T) { + dir := t.TempDir() + r, err := Open(dir) + if err != nil { + t.Fatal(err) + } + for i := 0; i < 8; i++ { + batch := testBatch() + batch.ID = fmt.Sprint("batch-", i) + if err := r.Commit(t.Context(), batch); err != nil { + t.Fatal(err) + } + } + if r.Parquet.Generation0BatchCount() != 8 { + t.Fatal("commits not counted") + } + r.Close() + r, err = Open(dir) + if err != nil { + t.Fatal(err) + } + defer r.Close() + if r.Parquet.Generation0BatchCount() != 8 { + t.Fatal("restart lost inventory") + } + if n, err := r.CompactParquet(t.Context(), &testParquetCompactor{}, 8); err != nil || n != 8 { + t.Fatalf("compaction %d %v", n, err) + } + if r.Parquet.Generation0BatchCount() != 0 { + t.Fatal("compaction did not retire generation zero") + } +} + +func TestFailedFirstPublicationKeepsInitialMinimum(t *testing.T) { + r := &Repository{} + first := r.beginPublication(100) + r.finishPublication(first, telemetry.BatchMetadata{}) + second := r.beginPublication(200) + r.finishPublication(second, telemetry.BatchMetadata{MinIngestedNanos: second, MaxIngestedNanos: second}) + horizon, published, minimum := r.PublicationBounds() + if horizon != second || published != second || minimum != first { + t.Fatalf("bounds=%d %d %d want=%d %d %d", horizon, published, minimum, second, second, first) + } +} diff --git a/internal/telemetry/store/repository.go b/internal/telemetry/store/repository.go index 1e32eb29..06692273 100644 --- a/internal/telemetry/store/repository.go +++ b/internal/telemetry/store/repository.go @@ -6,13 +6,13 @@ import ( "errors" "fmt" "log/slog" - "math" "os" "path/filepath" "strings" "sync" "time" + "github.com/labstack/fanout/internal/metrics" "github.com/labstack/fanout/internal/telemetry" ) @@ -26,9 +26,15 @@ type Batch struct { // Repository publishes self-contained Parquet batch directories. The // directory rename is the transaction and the filesystem is the catalog. type Repository struct { - root string - Parquet *telemetry.ParquetStore - compactionMu sync.Mutex + releaseBacklogGauge func() + root string + Parquet *telemetry.ParquetStore + compactionMu sync.Mutex + publicationMu sync.Mutex + lastStamp int64 + lastPublished int64 + minimumStamp int64 + inFlight map[int64]struct{} } func Open(root string) (*Repository, error) { @@ -56,6 +62,14 @@ func Open(root string) (*Repository, error) { _ = r.Close() return nil, fmt.Errorf("clean retired Parquet batches: %w", err) } + for _, batch := range parquetStore.BatchMetadata() { + r.lastStamp = max(r.lastStamp, batch.MaxIngestedNanos) + r.lastPublished = max(r.lastPublished, batch.MaxIngestedNanos) + if batch.MinIngestedNanos > 0 && (r.minimumStamp == 0 || batch.MinIngestedNanos < r.minimumStamp) { + r.minimumStamp = batch.MinIngestedNanos + } + } + r.releaseBacklogGauge = metrics.SetCompactionBacklogSource(parquetStore.Generation0BatchCount) return r, nil } @@ -107,7 +121,18 @@ func (r *Repository) cleanupCompactionArtifacts() error { return syncDirectory(r.root) } -func (r *Repository) Close() error { return r.Parquet.Close() } +func (r *Repository) Close() error { + if r.releaseBacklogGauge != nil { + r.releaseBacklogGauge() + } + return r.Parquet.Close() +} + +func (r *Repository) WaitForCompaction(ctx context.Context) (time.Duration, error) { + return r.Parquet.WaitForCompaction(ctx) +} + +func (r *Repository) CompactionDebt() int { return r.Parquet.CompactionDebt() } // CleanupParquet removes retired inputs only while no retention or compaction // transaction can still need them for rollback. @@ -174,15 +199,67 @@ func (r *Repository) protectedRetiredSuffix() (string, error) { return ".retired-" + marker.Output.ID, nil } +// beginPublication reserves a strictly increasing attempt stamp before any row +// can become visible. The same mutex protects reservations and the horizon. +func (r *Repository) beginPublication(now int64) int64 { + r.publicationMu.Lock() + defer r.publicationMu.Unlock() + r.lastStamp = max(now, r.lastStamp+1) + // A renamed directory can remain visible after its final fsync fails. + // Keep its stamp in the initial scan even before a retry adopts it. + if r.minimumStamp == 0 { + r.minimumStamp = r.lastStamp + } + if r.inFlight == nil { + r.inFlight = make(map[int64]struct{}) + } + r.inFlight[r.lastStamp] = struct{}{} + return r.lastStamp +} + +func (r *Repository) finishPublication(stamp int64, published telemetry.BatchMetadata) { + r.publicationMu.Lock() + defer r.publicationMu.Unlock() + if published.MaxIngestedNanos > 0 { + r.lastPublished = max(r.lastPublished, published.MaxIngestedNanos) + if r.minimumStamp == 0 || published.MinIngestedNanos < r.minimumStamp { + r.minimumStamp = published.MinIngestedNanos + } + } + delete(r.inFlight, stamp) +} + +// PublicationBounds returns the exact completed-attempt horizon, the largest +// published stamp (for lag), and the minimum opened or reserved stamp (for initial catch-up). +// Compaction/recovery only republish existing stamps and do not reserve attempts. +func (r *Repository) PublicationBounds() (horizon, published, minimum int64) { + r.publicationMu.Lock() + defer r.publicationMu.Unlock() + horizon = r.lastStamp + for stamp := range r.inFlight { + horizon = min(horizon, stamp-1) + } + return horizon, r.lastPublished, r.minimumStamp +} + func (r *Repository) Commit(ctx context.Context, batch Batch) error { - normalizeBatch(&batch) if err := validateBatch(batch); err != nil { return err } + stamp := r.beginPublication(time.Now().UnixNano()) + var published telemetry.BatchMetadata + defer func() { r.finishPublication(stamp, published) }() + normalizeBatch(&batch, stamp) metadata := telemetry.BatchMetadata{ - ID: batch.ID, MinIngestedNanos: batchMinIngestedNanos(batch), MaxIngestedNanos: batchMaxIngestedNanos(batch), + ID: batch.ID, MinIngestedNanos: stamp, MaxIngestedNanos: stamp, + } + err := r.Parquet.CommitBatch(ctx, &metadata, batch.Spans, batch.Logs, batch.Metrics) + if err == nil { + // An idempotent retry can adopt a directory from a previous attempt + // whose final fsync failed. Its durable rows retain that older stamp. + published = metadata } - return r.Parquet.CommitBatch(ctx, metadata, batch.Spans, batch.Logs, batch.Metrics) + return err } func (r *Repository) RowCount() uint64 { return r.Parquet.RowCount() } @@ -223,69 +300,26 @@ func validateBatch(batch Batch) error { return nil } -func normalizeBatch(batch *Batch) { - ingestedAt := time.Now().UnixNano() +func normalizeBatch(batch *Batch, ingestedAt int64) { for i := range batch.Spans { batch.Spans[i].Namespace = telemetry.NormalizeNamespace(batch.Spans[i].Namespace) - if batch.Spans[i].IngestedAt == 0 { - batch.Spans[i].IngestedAt = ingestedAt - } + batch.Spans[i].IngestedAt = ingestedAt if batch.Spans[i].StartUnixNanos == 0 { batch.Spans[i].StartUnixNanos = batch.Spans[i].IngestedAt } } for i := range batch.Logs { batch.Logs[i].Namespace = telemetry.NormalizeNamespace(batch.Logs[i].Namespace) - if batch.Logs[i].IngestedAt == 0 { - batch.Logs[i].IngestedAt = ingestedAt - } + batch.Logs[i].IngestedAt = ingestedAt if batch.Logs[i].EventUnixNanos == 0 { batch.Logs[i].EventUnixNanos = telemetry.FirstPositiveNanos(batch.Logs[i].TimeUnixNanos, batch.Logs[i].ObservedTimeNanos, batch.Logs[i].IngestedAt) } } for i := range batch.Metrics { batch.Metrics[i].Namespace = telemetry.NormalizeNamespace(batch.Metrics[i].Namespace) - if batch.Metrics[i].IngestedAt == 0 { - batch.Metrics[i].IngestedAt = ingestedAt - } + batch.Metrics[i].IngestedAt = ingestedAt if batch.Metrics[i].EventUnixNanos == 0 { batch.Metrics[i].EventUnixNanos = telemetry.FirstPositiveNanos(batch.Metrics[i].TimeUnixNanos, batch.Metrics[i].IngestedAt) } } } - -func batchMaxIngestedNanos(batch Batch) int64 { - var value int64 - for _, row := range batch.Spans { - value = max(value, row.IngestedAt) - } - for _, row := range batch.Logs { - value = max(value, row.IngestedAt) - } - for _, row := range batch.Metrics { - value = max(value, row.IngestedAt) - } - return value -} - -func batchMinIngestedNanos(batch Batch) int64 { - value := int64(math.MaxInt64) - include := func(candidate int64) { - if candidate > 0 { - value = min(value, candidate) - } - } - for _, row := range batch.Spans { - include(row.IngestedAt) - } - for _, row := range batch.Logs { - include(row.IngestedAt) - } - for _, row := range batch.Metrics { - include(row.IngestedAt) - } - if value == math.MaxInt64 { - return 0 - } - return value -} diff --git a/internal/telemetry/store/repository_test.go b/internal/telemetry/store/repository_test.go index d26d54f5..b67b4c6b 100644 --- a/internal/telemetry/store/repository_test.go +++ b/internal/telemetry/store/repository_test.go @@ -182,10 +182,10 @@ func TestRepositoryPrunesOnlyExpiredBatches(t *testing.T) { newer.Spans[0].StartUnixNanos, newer.Spans[0].IngestedAt = 1_000, 1_000 newer.Logs[0].TimeUnixNanos, newer.Logs[0].IngestedAt = 1_000, 1_000 newer.Metrics[0].TimeUnixNanos, newer.Metrics[0].IngestedAt = 1_000, 1_000 - if err := repository.Commit(context.Background(), old); err != nil { + if err := commitRestoredFixture(repository, context.Background(), old); err != nil { t.Fatal(err) } - if err := repository.Commit(context.Background(), newer); err != nil { + if err := commitRestoredFixture(repository, context.Background(), newer); err != nil { t.Fatal(err) } publisher := &testParquetCompactor{afterSwap: func() error { @@ -326,7 +326,7 @@ func TestRepositoryPrunePassDrainsWithinBudgetAndOldestFirst(t *testing.T) { batch.Spans[0].IngestedAt = int64(i + 1) batch.Logs[0].IngestedAt = int64(i + 1) batch.Metrics[0].IngestedAt = int64(i + 1) - if err := repository.Commit(context.Background(), batch); err != nil { + if err := commitRestoredFixture(repository, context.Background(), batch); err != nil { t.Fatal(err) } } @@ -360,7 +360,7 @@ func TestRepositoryPrunePassFinishesPublicationAfterBudget(t *testing.T) { batch.Spans[0].IngestedAt = int64(i + 1) batch.Logs[0].IngestedAt = int64(i + 1) batch.Metrics[0].IngestedAt = int64(i + 1) - if err := repository.Commit(context.Background(), batch); err != nil { + if err := commitRestoredFixture(repository, context.Background(), batch); err != nil { t.Fatal(err) } } @@ -417,7 +417,7 @@ func TestRepositoryRetentionUsesIngestTimeNotEventTime(t *testing.T) { batch.Spans[0].IngestedAt = 100 batch.Logs[0].IngestedAt = 100 batch.Metrics[0].IngestedAt = 100 - if err := repository.Commit(context.Background(), batch); err != nil { + if err := commitRestoredFixture(repository, context.Background(), batch); err != nil { t.Fatal(err) } removed, err := repository.PruneParquet(context.Background(), &testParquetCompactor{}, 500, 64) @@ -494,10 +494,10 @@ func TestSelectCompactionBatchesRequiresFullSmallFileGroup(t *testing.T) { for i := range batches { batches[i] = telemetry.BatchMetadata{ID: fmt.Sprintf("batch-%d", i), MaxIngestedNanos: 1, Spans: 1} } - if selected := selectCompactionBatches(batches[:groupSize-1], groupSize); len(selected) != 0 { + if selected := selectCompactionBatches(batches[:groupSize-1], groupSize, 0); len(selected) != 0 { t.Fatalf("selected partial group of %d batches", len(selected)) } - if selected := selectCompactionBatches(batches, groupSize); len(selected) != groupSize { + if selected := selectCompactionBatches(batches, groupSize, 0); len(selected) != groupSize { t.Fatalf("selected full group = %d, want %d", len(selected), groupSize) } } @@ -514,7 +514,7 @@ func TestSelectCompactionBatchesBuildsRowBoundedGroup(t *testing.T) { Bytes: 1 << 20, } } - selected := selectCompactionBatches(batches, maxBatches) + selected := selectCompactionBatches(batches, maxBatches, 0) if len(selected) != 12 { t.Fatalf("selected %d batches, want 12 below row limit", len(selected)) } @@ -539,7 +539,7 @@ func TestSelectCompactionBatchesCombinesSaturatedLargeFiles(t *testing.T) { Bytes: 1 << 20, } } - selected := selectCompactionBatches(batches, maxBatches) + selected := selectCompactionBatches(batches, maxBatches, 0) if len(selected) != len(batches) { t.Fatalf("selected %d saturated large batches, want %d", len(selected), len(batches)) } @@ -559,7 +559,7 @@ func TestSelectCompactionBatchesSkipsUncompactableOlderGroup(t *testing.T) { Spans: 1, } } - selected := selectCompactionBatches(batches, minCompactionInputs) + selected := selectCompactionBatches(batches, minCompactionInputs, 0) if len(selected) != minCompactionInputs || !strings.HasPrefix(selected[0].ID, "newer-") { t.Fatalf("selection did not skip uncompactable older group: %#v", selected) } @@ -912,3 +912,40 @@ func (f testParquetPublisherFunc) PublishParquetReplacement(ctx context.Context, func (c *testParquetCompactor) PublishParquetReplacement(ctx context.Context, _ telemetry.BatchMetadata, _ []string, publish func(context.Context) error) error { return c.PublishParquet(ctx, publish) } + +// commitRestoredFixture seeds already-stamped historical inputs, as recovery +// does. Normal ingest tests use Repository.Commit and its fresh attempt stamp. +func commitRestoredFixture(repo *Repository, ctx context.Context, batch Batch) error { + var lo, hi int64 + include := func(n int64) { + if n > 0 && (lo == 0 || n < lo) { + lo = n + } + hi = max(hi, n) + } + for i := range batch.Spans { + row := &batch.Spans[i] + row.Namespace = telemetry.NormalizeNamespace(row.Namespace) + include(row.IngestedAt) + if row.StartUnixNanos == 0 { + row.StartUnixNanos = row.IngestedAt + } + } + for i := range batch.Logs { + row := &batch.Logs[i] + row.Namespace = telemetry.NormalizeNamespace(row.Namespace) + include(row.IngestedAt) + if row.EventUnixNanos == 0 { + row.EventUnixNanos = telemetry.FirstPositiveNanos(row.TimeUnixNanos, row.ObservedTimeNanos, row.IngestedAt) + } + } + for i := range batch.Metrics { + row := &batch.Metrics[i] + row.Namespace = telemetry.NormalizeNamespace(row.Namespace) + include(row.IngestedAt) + if row.EventUnixNanos == 0 { + row.EventUnixNanos = telemetry.FirstPositiveNanos(row.TimeUnixNanos, row.IngestedAt) + } + } + return repo.Parquet.CommitBatch(ctx, &telemetry.BatchMetadata{ID: batch.ID, MinIngestedNanos: lo, MaxIngestedNanos: hi}, batch.Spans, batch.Logs, batch.Metrics) +} diff --git a/internal/telemetry/store/writer.go b/internal/telemetry/store/writer.go index 860a831c..9fd95802 100644 --- a/internal/telemetry/store/writer.go +++ b/internal/telemetry/store/writer.go @@ -22,22 +22,29 @@ const ( // Bound group admission independently of encode time. Ten milliseconds // coalesces concurrent exports without imposing a 20ms floor on every // durable acknowledgement when the row target is not reached. - groupAdmissionWindow = 10 * time.Millisecond - maxAdmissionRequests = 512 - maxGroupBatchRows = 50_000 - maxCommitWorkers = 4 - submissionQueueDepth = 256 - writerShutdownGrace = 30 * time.Second + groupAdmissionWindow = 10 * time.Millisecond + pressureAdmissionWindow = 250 * time.Millisecond + maxAdmissionRequests = 512 + maxGroupBatchRows = 50_000 + maxCommitWorkers = 4 + submissionQueueDepth = 256 + writerShutdownGrace = 30 * time.Second ) type batchCommitter interface { Commit(context.Context, Batch) error } +type compactionPressure interface { + WaitForCompaction(context.Context) (time.Duration, error) + CompactionDebt() int +} + type Writer struct { inFlightBudget int inFlightBytes atomic.Int64 repository batchCommitter + compaction compactionPressure batchSize int retryDelay func(int) time.Duration groupWindow time.Duration @@ -149,6 +156,7 @@ func (w *Writer) Submit(ctx context.Context, batch Batch) error { func (w *Writer) Run(ctx context.Context) error { defer close(w.done) defer metrics.UpdateQueueDepth("batch", 0) + w.compaction, _ = w.repository.(compactionPressure) jobs := make(chan commitJob, commitQueueDepth) workerCtx, cancelWorkers := context.WithCancel(context.Background()) defer cancelWorkers() @@ -184,6 +192,15 @@ func (w *Writer) Run(ctx context.Context) error { } for { + if w.compaction != nil { + waited, err := w.compaction.WaitForCompaction(ctx) + if waited > 0 { + metrics.IngestBackpressureSeconds.Add(waited.Seconds()) + } + if err != nil { + return finish(true) + } + } select { case request := <-w.submissions: metrics.UpdateQueueDepth("batch", len(w.submissions)) @@ -200,20 +217,28 @@ func (w *Writer) enqueueSubmissions(ctx context.Context, request submission, out requests := make([]submission, 1, maxAdmissionRequests) requests[0] = request rows := batchRows(request.batch) + bytes := request.bytes limit := w.batchLimit() - if rows < limit { + if rows < limit && bytes < maxGroupBatchBytes { window := w.groupWindow if window <= 0 { window = groupAdmissionWindow } + // Coalesce more exports before the hard debt stop is needed. Read + // reclaimable debt once per group; low-load acknowledgements keep + // their short window as soon as compaction relieves the pressure. + if w.compaction != nil && w.compaction.CompactionDebt() >= telemetry.CompactionDebtLimit/2 { + window = pressureAdmissionWindow + } timer := time.NewTimer(window) defer timer.Stop() admit: - for len(requests) < maxAdmissionRequests && rows < limit { + for len(requests) < maxAdmissionRequests && rows < limit && bytes < maxGroupBatchBytes { select { case next := <-w.submissions: requests = append(requests, next) rows += batchRows(next.batch) + bytes += next.bytes case <-timer.C: break admit case <-ctx.Done(): diff --git a/internal/telemetry/variant_test.go b/internal/telemetry/variant_test.go index 82629a14..013acd3e 100644 --- a/internal/telemetry/variant_test.go +++ b/internal/telemetry/variant_test.go @@ -123,7 +123,7 @@ func testUnsupportedFormatLeavesStoreUntouched(t *testing.T, suffix string) { if err != nil { t.Fatal(err) } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "old"}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "old"}, []Span{{TraceID: "trace"}}, nil, nil); err != nil { t.Fatal(err) } metadata := filepath.Join(store.BatchPath("old"), "metadata.json") diff --git a/internal/telemetry/verify_test.go b/internal/telemetry/verify_test.go index 89a187d8..b30c1f8c 100644 --- a/internal/telemetry/verify_test.go +++ b/internal/telemetry/verify_test.go @@ -26,7 +26,7 @@ func verificationFixture(t *testing.T) (string, []spanParquetRow) { {TraceID: "trace", SpanID: "c", StartUnixNanos: 30}, {TraceID: "trace", SpanID: "d", StartUnixNanos: 40, Attributes: map[string]any{"other": []byte{0, 255}}, Resource: map[string]any{"service.name": "last", "extra": []any{int64(2), false}}}, } - if err := store.CommitBatch(context.Background(), BatchMetadata{ID: "verify"}, spans, nil, nil); err != nil { + if err := store.CommitBatch(context.Background(), &BatchMetadata{ID: "verify"}, spans, nil, nil); err != nil { t.Fatal(err) } dir := store.BatchPath("verify") diff --git a/site/src/content/docs/explanation/storage-model.mdx b/site/src/content/docs/explanation/storage-model.mdx index 36239b9c..0c8ff315 100644 --- a/site/src/content/docs/explanation/storage-model.mdx +++ b/site/src/content/docs/explanation/storage-model.mdx @@ -167,7 +167,9 @@ A semantic version covers the cache schema and aggregation rules; a version change atomically discards all private read tables and rebuilds from authoritative format-4 Parquet. The background worker processes bounded groups; `fanout_read_cache_pending_batches` reports its -trace backlog independently of the service and edge rollups' safety window. +trace backlog independently of the service and edge rollups' publication horizon. +Version history drains on its own worker, so an analytical-gate wait cannot +delay the completed-batch worker. Completed-batch and analytical writers use separate gates and two connections outside the read pool. They modify disjoint tables; maintenance holds both gates for checkpointing. Trace reads avoid materializing every retained candidate into @@ -182,12 +184,33 @@ snapshot capture. Only signals referenced by a query are bound. Completed-batch trace caches still rebuild retained history in bounded passes; uncached files remain immediately queryable. -## Rollups lag deliberately - -Overview and alert queries read rebuildable DuckDB rollups. Their watermark -trails committed telemetry by a fixed safety window so out-of-order events from -bounded commit retries are not skipped. Raw committed telemetry is queryable -before it appears in a rollup. +## Rollups follow durable publication + +Overview and alert queries read rebuildable DuckDB rollups. Each commit attempt +receives a strictly increasing ingestion stamp; a retry receives a new stamp. +The repository tracks unfinished attempts and advances the publication horizon +only past attempts that have published durably or failed. Service and edge +rollups process disjoint ingestion windows up to that horizon, recomputing each +affected event-time bucket in full. Raw committed telemetry remains queryable +before its next rollup pass. + +Error-rate, latency, and volume detectors read service-rollup minutes through +the last completed minute before the service watermark. The baseline has the +same length as the current period. Latency uses the span-weighted mean of the +rollup's served-span minute p95 values; log-pattern detection still reads logs. + +The ingest writer waits when reclaimable generation-0 compaction debt reaches +1,024 batches. Already admitted commits finish and requests wait in the bounded +submission queue, honoring their own deadlines. Debt excludes batches above half +the merge row ceiling and reserves 127 smaller inputs per ingestion day: those +inputs can otherwise be stranded by the compaction eligibility rules. +At 512 batches of reclaimable debt, compaction prioritizes eligible generation-0 +groups across all days. Below that threshold, it selects the oldest eligible day +and then the highest eligible generation within that day. +The exact count of all live generation-0 batches, including those exclusions, +is exported as `fanout_compaction_backlog_batches`. Time spent waiting is +`fanout_ingest_backpressure_seconds_total`. This bounds reclaimable debt rather +than imposing an absolute limit on retained batch count. Service dependency traversal reads the complete edge rollup within the selected window, including edges outside the topology view's displayed page. It follows