Track and display R2 upload duration in build timings

Author: retlehs

cmd/wpcomposer/cmd/deploy.go

@@ -10,14 +10,35 @@ import (
 	"github.com/spf13/cobra"
 )
 
+// deployR2SyncSeconds captures the last SyncToR2 duration for the current deploy run.
+var deployR2SyncSeconds *int
+
 var deployCmd = &cobra.Command{
 	Use:   "deploy [build-id]",
 	Short: "Promote a build, rollback, or cleanup old builds",
 	Args:  cobra.MaximumNArgs(1),
 	RunE:  runDeploy,
 }
 
+func secondsPtrSince(start time.Time) *int {
+	v := int(time.Since(start).Seconds())
+	return &v
+}
+
+func syncToR2Timed(cmd *cobra.Command, buildDir, buildID, previousBuildID string) error {
+	started := time.Now()
+	err := deploy.SyncToR2(cmd.Context(), application.Config.R2, buildDir, buildID, previousBuildID, application.Logger)
+	deployR2SyncSeconds = secondsPtrSince(started)
+	if err != nil {
+		return fmt.Errorf("R2 sync failed: %w", err)
+	}
+	recordR2Sync(cmd, buildID)
+	return nil
+}
+
 func runDeploy(cmd *cobra.Command, args []string) error {
+	deployR2SyncSeconds = nil
+
 	repoDir := filepath.Join("storage", "repository")
 	cleanup, _ := cmd.Flags().GetBool("cleanup")
 	toR2, _ := cmd.Flags().GetBool("to-r2")
@@ -78,10 +99,9 @@ func runDeploy(cmd *cobra.Command, args []string) error {
 
 		// Sync to R2 first, then promote locally
 		if toR2 || application.Config.R2.Enabled {
-			if err := deploy.SyncToR2(cmd.Context(), application.Config.R2, buildDir, target, previousBuildID, application.Logger); err != nil {
-				return fmt.Errorf("R2 sync failed: %w", err)
+			if err := syncToR2Timed(cmd, buildDir, target, previousBuildID); err != nil {
+				return err
 			}
-			recordR2Sync(cmd, target)
 		}
 
 		if _, err := deploy.Rollback(repoDir, target, application.Logger); err != nil {
@@ -110,10 +130,9 @@ func runDeploy(cmd *cobra.Command, args []string) error {
 
 	// Sync to R2 first, then promote locally
 	if toR2 || application.Config.R2.Enabled {
-		if err := deploy.SyncToR2(cmd.Context(), application.Config.R2, buildDir, buildID, previousBuildID, application.Logger); err != nil {
-			return fmt.Errorf("R2 sync failed: %w", err)
+		if err := syncToR2Timed(cmd, buildDir, buildID, previousBuildID); err != nil {
+			return err
 		}
-		recordR2Sync(cmd, buildID)
 	}
 
 	if err := deploy.Promote(repoDir, buildID, application.Logger); err != nil {

cmd/wpcomposer/cmd/pipeline.go

@@ -108,11 +108,12 @@ func runPipeline(cmd *cobra.Command, args []string) error {
 	d := pipelineStepDurations
 	_, dbErr := application.DB.ExecContext(ctx, `
 		UPDATE builds SET status = 'completed', finished_at = ?, duration_seconds = ?,
-			discover_seconds = ?, update_seconds = ?, build_seconds = ?, deploy_seconds = ?
+			discover_seconds = ?, update_seconds = ?, build_seconds = ?, deploy_seconds = ?,
+			r2_upload_seconds = ?
 		WHERE id = ?`,
 		now.Format(time.RFC3339),
 		int(now.Sub(started).Seconds()),
-		d.Discover, d.Update, d.Build, d.Deploy,
+		d.Discover, d.Update, d.Build, d.Deploy, d.R2Upload,
 		buildID,
 	)
 	if dbErr != nil {
@@ -129,6 +130,7 @@ type stepDurations struct {
 	Update   *int
 	Build    *int
 	Deploy   *int
+	R2Upload *int
 }
 
 // pipelineStepDurations is set by executePipelineSteps so that recordFailedBuild
@@ -171,10 +173,12 @@ func executePipelineSteps(cmd *cobra.Command, ctx context.Context, skipDiscover,
 		application.Logger.Info("pipeline: running deploy")
 		deployCmd.SetContext(ctx)
 		stepStart = time.Now()
-		if err := runDeploy(deployCmd, nil); err != nil {
+		err := runDeploy(deployCmd, nil)
+		pipelineStepDurations.Deploy = intPtr(int(time.Since(stepStart).Seconds()))
+		pipelineStepDurations.R2Upload = deployR2SyncSeconds
+		if err != nil {
 			return fmt.Errorf("deploy: %w", err)
 		}
-		pipelineStepDurations.Deploy = intPtr(int(time.Since(stepStart).Seconds()))
 
 		// Clean up old builds after a successful deploy.
 		repoDir := filepath.Join("storage", "repository")
@@ -202,12 +206,12 @@ func recordFailedBuild(cmd *cobra.Command, started time.Time, pipelineErr error)
 	_, dbErr := application.DB.ExecContext(cmd.Context(), `
 		UPDATE builds SET status = 'failed', finished_at = ?, duration_seconds = ?,
 			error_message = ?, discover_seconds = ?, update_seconds = ?,
-			build_seconds = ?, deploy_seconds = ?
+			build_seconds = ?, deploy_seconds = ?, r2_upload_seconds = ?
 		WHERE id = ?`,
 		now.Format(time.RFC3339),
 		int(now.Sub(started).Seconds()),
 		pipelineErr.Error(),
-		d.Discover, d.Update, d.Build, d.Deploy,
+		d.Discover, d.Update, d.Build, d.Deploy, d.R2Upload,
 		pipelineBuildID,
 	)
 	if dbErr != nil {

internal/http/handlers.go

@@ -959,12 +959,13 @@ type buildRow struct {
 	UpdateSeconds   *int
 	BuildSeconds    *int
 	DeploySeconds   *int
+	R2UploadSeconds *int
 }
 
 func queryBuilds(ctx context.Context, db *sql.DB) ([]buildRow, error) {
 	rows, err := db.QueryContext(ctx, `SELECT id, started_at, packages_total, packages_changed,
 		artifact_count, status, COALESCE(r2_synced_at, ''), COALESCE(error_message, ''),
-		duration_seconds, discover_seconds, update_seconds, build_seconds, deploy_seconds
+		duration_seconds, discover_seconds, update_seconds, build_seconds, deploy_seconds, r2_upload_seconds
 		FROM builds ORDER BY started_at DESC LIMIT 50`)
 	if err != nil {
 		return nil, err
@@ -976,7 +977,7 @@ func queryBuilds(ctx context.Context, db *sql.DB) ([]buildRow, error) {
 		var b buildRow
 		_ = rows.Scan(&b.ID, &b.StartedAt, &b.PackagesTotal, &b.PackagesChanged,
 			&b.ArtifactCount, &b.Status, &b.R2SyncedAt, &b.ErrorMessage,
-			&b.DurationSeconds, &b.DiscoverSeconds, &b.UpdateSeconds, &b.BuildSeconds, &b.DeploySeconds)
+			&b.DurationSeconds, &b.DiscoverSeconds, &b.UpdateSeconds, &b.BuildSeconds, &b.DeploySeconds, &b.R2UploadSeconds)
 		builds = append(builds, b)
 	}
 	return builds, rows.Err()

internal/http/templates/admin_builds.html

@@ -46,8 +46,8 @@ <h1 class="text-xl font-bold">Build History</h1>
 </td>
 <td class="px-4 py-2 text-xs font-mono whitespace-nowrap">
 {{if .DurationSeconds}}<span class="text-gray-700">{{formatDuration .DurationSeconds}}</span>{{end}}
-{{if or .DiscoverSeconds .UpdateSeconds .BuildSeconds .DeploySeconds}}
-<span class="text-gray-400 block mt-0.5">{{- if .DiscoverSeconds}}D:{{formatDuration .DiscoverSeconds}} {{end}}{{- if .UpdateSeconds}}U:{{formatDuration .UpdateSeconds}} {{end}}{{- if .BuildSeconds}}B:{{formatDuration .BuildSeconds}} {{end}}{{- if .DeploySeconds}}Dp:{{formatDuration .DeploySeconds}}{{end}}</span>
+{{if or .DiscoverSeconds .UpdateSeconds .BuildSeconds .DeploySeconds .R2UploadSeconds}}
+<span class="text-gray-400 block mt-0.5">{{- if .DiscoverSeconds}}D:{{formatDuration .DiscoverSeconds}} {{end}}{{- if .UpdateSeconds}}U:{{formatDuration .UpdateSeconds}} {{end}}{{- if .BuildSeconds}}B:{{formatDuration .BuildSeconds}} {{end}}{{- if .DeploySeconds}}Dp:{{formatDuration .DeploySeconds}} {{end}}{{- if .R2UploadSeconds}}R2:{{formatDuration .R2UploadSeconds}}{{end}}</span>
 {{end}}
 </td>
 <td class="px-4 py-2">

migrations/016_add_r2_upload_duration_to_builds.sql

@@ -0,0 +1,5 @@
+-- +goose Up
+ALTER TABLE builds ADD COLUMN r2_upload_seconds INTEGER;
+
+-- +goose Down
+ALTER TABLE builds DROP COLUMN r2_upload_seconds;