more logging

internal/tasks/aggregationBenchmark.go

@@ -44,29 +44,46 @@ func (c *CronTask) RunCanonicalAggregationBenchmark(ctx context.Context, runs in
 	}
 	report := AggregationBenchmarkReport{Runs: runs}
 	dbConn := c.Database.DB()
+	logger := loggerFromCtx(ctx, c.Logger)
 
 	hourlyStart, hourlyEnd, err := latestDailyWindowFromHourlyCache(ctx, dbConn)
 	if err != nil {
 		return report, err
 	}
 	if !hourlyStart.IsZero() {
+		if logger != nil {
+			logger.Info("canonical benchmark phase starting", "phase", "daily", "window_start", hourlyStart.Format(time.RFC3339), "window_end", hourlyEnd.Format(time.RFC3339), "runs", runs)
+		}
 		report.DailyWindowStart = hourlyStart
 		report.DailyWindowEnd = hourlyEnd
 		goDurations := make([]time.Duration, 0, runs)
 		sqlDurations := make([]time.Duration, 0, runs)
 		var goRows, sqlRows int64
 		for i := 0; i < runs; i++ {
+			run := i + 1
+			if logger != nil {
+				logger.Info("canonical benchmark run starting", "phase", "daily", "mode", "go", "run", run, "runs", runs)
+			}
 			dur, rows, runErr := c.benchmarkDailyGoCore(ctx, hourlyStart, hourlyEnd)
 			if runErr != nil {
 				return report, fmt.Errorf("daily go benchmark run %d failed: %w", i+1, runErr)
 			}
+			if logger != nil {
+				logger.Info("canonical benchmark run complete", "phase", "daily", "mode", "go", "run", run, "runs", runs, "duration", dur, "rows", rows)
+			}
 			goDurations = append(goDurations, dur)
 			goRows = rows
 
+			if logger != nil {
+				logger.Info("canonical benchmark run starting", "phase", "daily", "mode", "sql", "run", run, "runs", runs)
+			}
 			dur, rows, runErr = c.benchmarkDailySQLCore(ctx, hourlyStart, hourlyEnd)
 			if runErr != nil {
 				return report, fmt.Errorf("daily sql benchmark run %d failed: %w", i+1, runErr)
 			}
+			if logger != nil {
+				logger.Info("canonical benchmark run complete", "phase", "daily", "mode", "sql", "run", run, "runs", runs, "duration", dur, "rows", rows)
+			}
 			sqlDurations = append(sqlDurations, dur)
 			sqlRows = rows
 		}
@@ -74,6 +91,11 @@ func (c *CronTask) RunCanonicalAggregationBenchmark(ctx context.Context, runs in
 		report.DailySQL = summarizeDurations(sqlDurations)
 		report.DailyGoRowsWritten = goRows
 		report.DailySQLRowsWritten = sqlRows
+		if logger != nil {
+			logger.Info("canonical benchmark phase complete", "phase", "daily", "runs", runs)
+		}
+	} else if logger != nil {
+		logger.Info("canonical benchmark phase skipped", "phase", "daily", "reason", "no benchmarkable window found in vm_hourly_stats")
 	}
 
 	monthlyStart, monthlyEnd, err := latestMonthlyWindowFromDailyRollup(ctx, dbConn)
@@ -81,23 +103,39 @@ func (c *CronTask) RunCanonicalAggregationBenchmark(ctx context.Context, runs in
 		return report, err
 	}
 	if !monthlyStart.IsZero() {
+		if logger != nil {
+			logger.Info("canonical benchmark phase starting", "phase", "monthly", "window_start", monthlyStart.Format(time.RFC3339), "window_end", monthlyEnd.Format(time.RFC3339), "runs", runs)
+		}
 		report.MonthlyWindowStart = monthlyStart
 		report.MonthlyWindowEnd = monthlyEnd
 		goDurations := make([]time.Duration, 0, runs)
 		sqlDurations := make([]time.Duration, 0, runs)
 		var goRows, sqlRows int64
 		for i := 0; i < runs; i++ {
+			run := i + 1
+			if logger != nil {
+				logger.Info("canonical benchmark run starting", "phase", "monthly", "mode", "go", "run", run, "runs", runs)
+			}
 			dur, rows, runErr := c.benchmarkMonthlyGoCore(ctx, monthlyStart, monthlyEnd)
 			if runErr != nil {
 				return report, fmt.Errorf("monthly go benchmark run %d failed: %w", i+1, runErr)
 			}
+			if logger != nil {
+				logger.Info("canonical benchmark run complete", "phase", "monthly", "mode", "go", "run", run, "runs", runs, "duration", dur, "rows", rows)
+			}
 			goDurations = append(goDurations, dur)
 			goRows = rows
 
+			if logger != nil {
+				logger.Info("canonical benchmark run starting", "phase", "monthly", "mode", "sql", "run", run, "runs", runs)
+			}
 			dur, rows, runErr = c.benchmarkMonthlySQLCore(ctx, monthlyStart, monthlyEnd)
 			if runErr != nil {
 				return report, fmt.Errorf("monthly sql benchmark run %d failed: %w", i+1, runErr)
 			}
+			if logger != nil {
+				logger.Info("canonical benchmark run complete", "phase", "monthly", "mode", "sql", "run", run, "runs", runs, "duration", dur, "rows", rows)
+			}
 			sqlDurations = append(sqlDurations, dur)
 			sqlRows = rows
 		}
@@ -105,6 +143,11 @@ func (c *CronTask) RunCanonicalAggregationBenchmark(ctx context.Context, runs in
 		report.MonthlySQL = summarizeDurations(sqlDurations)
 		report.MonthlyGoRowsWritten = goRows
 		report.MonthlySQLRowsWritten = sqlRows
+		if logger != nil {
+			logger.Info("canonical benchmark phase complete", "phase", "monthly", "runs", runs)
+		}
+	} else if logger != nil {
+		logger.Info("canonical benchmark phase skipped", "phase", "monthly", "reason", "no benchmarkable window found in vm_daily_rollup")
 	}
 
 	if report.DailyWindowStart.IsZero() && report.MonthlyWindowStart.IsZero() {