Capture dependency graph timings

Signed-off-by: Danny Kopping <danny@coder.com>
coder · dannykopping · Aug 21, 2024 · Aug 7, 2024 · Aug 13, 2024 · Aug 13, 2024
commit 973ec6d0aa106366a9ca04d49f54c2929bee2d48
diff --git a/coderd/database/dump.sql b/coderd/database/dump.sql
diff --git a/coderd/database/migrations/000244_provisioner_job_timings.up.sql b/coderd/database/migrations/000244_provisioner_job_timings.up.sql
@@ -1,6 +1,7 @@
 CREATE TYPE provisioner_job_timing_stage AS ENUM (
     'init',
     'plan',
+    'graph',
     'apply'
     );
 
@@ -16,20 +17,29 @@ CREATE TABLE provisioner_job_timings
 );
 
 CREATE VIEW provisioner_job_stats AS
-SELECT pj.id AS job_id,
+SELECT pj.id                                                                                  AS job_id,
        pj.job_status,
        wb.workspace_id,
        pj.worker_id,
        pj.error,
        pj.error_code,
        pj.updated_at,
-       GREATEST(EXTRACT(EPOCH FROM (pj.started_at - pj.created_at)), 0)                                             AS queued_secs,
-       GREATEST(EXTRACT(EPOCH FROM (pj.completed_at - pj.started_at)), 0)                                           AS completion_secs,
-       GREATEST(EXTRACT(EPOCH FROM (pj.canceled_at - pj.started_at)), 0)                                            AS canceled_secs,
-       GREATEST(MAX(CASE WHEN pjt.stage = 'init' THEN EXTRACT(EPOCH FROM (pjt.ended_at - pjt.started_at)) END), 0)  AS init_secs,
-       GREATEST(MAX(CASE WHEN pjt.stage = 'plan' THEN EXTRACT(EPOCH FROM (pjt.ended_at - pjt.started_at)) END), 0)  AS plan_secs,
-       GREATEST(MAX(CASE WHEN pjt.stage = 'apply' THEN EXTRACT(EPOCH FROM (pjt.ended_at - pjt.started_at)) END), 0) AS apply_secs
+       GREATEST(EXTRACT(EPOCH FROM (pj.started_at - pj.created_at)), 0)                       AS queued_secs,
+       GREATEST(EXTRACT(EPOCH FROM (pj.completed_at - pj.started_at)), 0)                     AS completion_secs,
+       GREATEST(EXTRACT(EPOCH FROM (pj.canceled_at - pj.started_at)), 0)                      AS canceled_secs,
+       GREATEST(MAX(CASE
+                        WHEN pjt.stage = 'init'::provisioner_job_timing_stage
+                            THEN EXTRACT(EPOCH FROM (pjt.ended_at - pjt.started_at)) END), 0) AS init_secs,
+       GREATEST(MAX(CASE
+                        WHEN pjt.stage = 'plan'::provisioner_job_timing_stage
+                            THEN EXTRACT(EPOCH FROM (pjt.ended_at - pjt.started_at)) END), 0) AS plan_secs,
+       GREATEST(MAX(CASE
+                        WHEN pjt.stage = 'graph'::provisioner_job_timing_stage
+                            THEN EXTRACT(EPOCH FROM (pjt.ended_at - pjt.started_at)) END), 0) AS graph_secs,
+       GREATEST(MAX(CASE
+                        WHEN pjt.stage = 'apply'::provisioner_job_timing_stage
+                            THEN EXTRACT(EPOCH FROM (pjt.ended_at - pjt.started_at)) END), 0) AS apply_secs
 FROM provisioner_jobs pj
-       JOIN workspace_builds wb ON wb.job_id = pj.id
-       LEFT JOIN provisioner_job_timings pjt ON pjt.job_id = pj.id
+         JOIN workspace_builds wb ON wb.job_id = pj.id
+         LEFT JOIN provisioner_job_timings pjt ON pjt.job_id = pj.id
 GROUP BY pj.id, wb.workspace_id;
diff --git a/coderd/database/models.go b/coderd/database/models.go
diff --git a/coderd/database/queries.sql.go b/coderd/database/queries.sql.go
diff --git a/provisioner/terraform/executor.go b/provisioner/terraform/executor.go
@@ -21,6 +21,7 @@ import (
 	"go.opentelemetry.io/otel/attribute"
 	"golang.org/x/xerrors"
 
+	"github.com/coder/coder/v2/coderd/database"
 	"github.com/coder/coder/v2/coderd/tracing"
 	"github.com/coder/coder/v2/provisionersdk/proto"
 )
@@ -268,16 +269,24 @@ func (e *executor) plan(ctx, killCtx context.Context, env, vars []string, logr l
 	if err != nil {
 		return nil, xerrors.Errorf("terraform plan: %w", err)
 	}
+
+	// Capture the duration of the call to `terraform graph`.
+	graphTimings := newTimingAggregator(database.ProvisionerJobTimingStageGraph)
+	graphTimings.ingest(createGraphTimingsEvent(graphStart))
+
 	state, err := e.planResources(ctx, killCtx, planfilePath)
 	if err != nil {
+		graphTimings.ingest(createGraphTimingsEvent(graphErrored))
 		return nil, err
 	}
 
+	graphTimings.ingest(createGraphTimingsEvent(graphComplete))
+
 	return &proto.PlanComplete{
 		Parameters:            state.Parameters,
 		Resources:             state.Resources,
 		ExternalAuthProviders: state.ExternalAuthProviders,
-		Timings:               e.timings.aggregate(),
+		Timings:               append(e.timings.aggregate(), graphTimings.aggregate()...),
 	}, nil
 }
 

diff --git a/provisioner/terraform/provision.go b/provisioner/terraform/provision.go
@@ -15,7 +15,6 @@ import (
 	"github.com/coder/terraform-provider-coder/provider"
 
 	"github.com/coder/coder/v2/coderd/database"
-	"github.com/coder/coder/v2/coderd/database/dbtime"
 	"github.com/coder/coder/v2/coderd/tracing"
 	"github.com/coder/coder/v2/provisionersdk"
 	"github.com/coder/coder/v2/provisionersdk/proto"
@@ -139,19 +138,12 @@ func (s *server) Plan(
 		return provisionersdk.PlanErrorf(err.Error())
 	}
 
-	resp.Timings = append(resp.Timings, initTimings.aggregate()...)
+	// Prepend init timings since they occur prior to plan timings.
+	// Order is irrelevant; this is merely indicative.
+	resp.Timings = append(initTimings.aggregate(), resp.Timings...)
 	return resp
 }
 
-func createInitTimingsEvent(event timingKind) (time.Time, *timingSpan) {
-	return dbtime.Now(), &timingSpan{
-		kind:     event,
-		action:   "initialize terraform",
-		provider: "terraform",
-		resource: "state file",
-	}
-}
-
 func (s *server) Apply(
 	sess *provisionersdk.Session, request *proto.ApplyRequest, canceledOrComplete <-chan struct{},
 ) *proto.ApplyComplete {

diff --git a/provisioner/terraform/timings.go b/provisioner/terraform/timings.go
@@ -29,10 +29,13 @@ const (
 	provisionErrored  timingKind = "provision_errored"
 	refreshStart      timingKind = "refresh_start"
 	refreshComplete   timingKind = "refresh_complete"
-	// These are not part of message_types, but we want to track init timings as well.
+	// These are not part of message_types, but we want to track init/graph timings as well.
 	initStart    timingKind = "init_start"
 	initComplete timingKind = "init_complete"
 	initErrored  timingKind = "init_errored"
+	graphStart    timingKind = "graph_start"
+	graphComplete timingKind = "graph_complete"
+	graphErrored  timingKind = "graph_errored"
 )
 
 type timingAggregator struct {
@@ -71,13 +74,13 @@ func (t *timingAggregator) ingest(ts time.Time, s *timingSpan) {
 	ts = dbtime.Time(ts)
 
 	switch s.kind {
-	case applyStart, provisionStart, refreshStart, initStart:
+	case applyStart, provisionStart, refreshStart, initStart, graphStart:
 		s.start = ts
 		s.state = proto.TimingState_STARTED
-	case applyComplete, provisionComplete, refreshComplete, initComplete:
+	case applyComplete, provisionComplete, refreshComplete, initComplete, graphComplete:
 		s.end = ts
 		s.state = proto.TimingState_COMPLETED
-	case applyErrored, provisionErrored, initErrored:
+	case applyErrored, provisionErrored, initErrored, graphErrored:
 		s.end = ts
 		s.state = proto.TimingState_FAILED
 	default:
@@ -147,6 +150,9 @@ func (l timingKind) Valid() bool {
 		initStart,
 		initComplete,
 		initErrored,
+		graphStart,
+		graphComplete,
+		graphErrored,
 	}, l)
 }
 
@@ -168,3 +174,21 @@ func (e *timingSpan) toProto() *proto.Timing {
 		State:    e.state,
 	}
 }
+
+func createInitTimingsEvent(event timingKind) (time.Time, *timingSpan) {
+	return dbtime.Now(), &timingSpan{
+		kind:     event,
+		action:   "initializing terraform",
+		provider: "terraform",
+		resource: "state file",
+	}
+}
+
+func createGraphTimingsEvent(event timingKind) (time.Time, *timingSpan) {
+	return dbtime.Now(), &timingSpan{
+		kind:     event,
+		action:   "building terraform dependency graph",
+		provider: "terraform",
+		resource: "state file",
+	}
+}