feat: add provisioning timings to understand slow build times #14274

dannykopping · 2024-08-15T12:56:28Z

This PR productionizes a spike I conducted during coder/internal#22.

Terraform exposes discrete timing information for each resource when planning and applying, and we're now using this to build up a view of which resources or stages take the most time. I'm hooking into our existing parsing of the Terraform log lines and expanding it a bit; there were some necessary refactors but I've tried to keep it as low-touch as possible.

This PR does not contain any HTTP APIs or UIs. Those will have to be added in subsequent PRs; this one is already fairly large.

There are tests, and they cover the majority of the new code added, but they're incomplete. I had to do some fairly nasty business in provisioner/terraform/timings_test.go since we don't have a seam in front of calls to os/exec which makes it difficult to mock. There's some precedent for this though in provisioner/terraform/provision_test.go from which I took heavy inspiration.

We also don't have any active e2e tests which use terraform, which I think is something worth addressing.

I also included txtar after watching Russ Cox's excellent talk on Go testing recently, and it made the tests quite readable - at least I think so. If you disagree, let me know.

Using this information, we'll be able to add cool graphs like this to workspace detail pages and probably also expose some aggregated data in Prometheus metrics.

Signed-off-by: Danny Kopping <danny@coder.com>

…me resource are captured Signed-off-by: Danny Kopping <danny@coder.com>

Signed-off-by: Danny Kopping <danny@coder.com>

alwaysmeticulous · 2024-08-15T12:58:05Z

✅ Meticulous spotted zero visual differences across 1408 screens tested: view results.

Meticulous tested none of the executable lines edited in this PR. If this PR does not modify your frontend this is expected. If this is a new feature or Meticulous was recently introduced then Meticulous will generate tests to cover your code in the coming days¹.

_{1. If you wish to increase coverage immediately you can do so by interacting with your feature on localhost.}

_{Expected differences? Click here. Last updated for commit eb5ec5c. This comment will update as new commits are pushed.}

Signed-off-by: Danny Kopping <danny@coder.com>

dannykopping · 2024-08-15T13:40:23Z

coderd/database/dbauthz/dbauthz.go

@@ -2787,6 +2787,14 @@ func (q *querier) InsertProvisionerJobLogs(ctx context.Context, arg database.Ins
 	return q.db.InsertProvisionerJobLogs(ctx, arg)
 }

+// TODO: We need to create a ProvisionerJob resource type


See InsertProvisionerJobLogs and InsertProvisionerJob above

dannykopping · 2024-08-15T13:40:46Z

coderd/database/dbauthz/dbauthz_test.go

@@ -2463,6 +2463,13 @@ func (s *MethodTestSuite) TestSystemFunctions() {
 			JobID: j.ID,
 		}).Asserts( /*rbac.ResourceSystem, policy.ActionCreate*/ )
 	}))
+	s.Run("InsertProvisionerJobTimings", s.Subtest(func(db database.Store, check *expects) {
+		// TODO: we need to create a ProvisionerJob resource


coderd/database/dbtime/dbtime.go

coderd/database/migrations/000245_provisioner_job_timings.up.sql

dannykopping · 2024-08-15T13:48:28Z

coderd/database/migrations/000245_provisioner_job_timings.up.sql

+       pj.worker_id,
+       pj.error,
+       pj.error_code,


These are extraneous right now, but when we slap an API on top of this we'll likely need this info and can save ourselves another database call.

dannykopping · 2024-08-15T14:02:45Z

coderd/database/migrations/000245_provisioner_job_timings.up.sql

+       GREATEST(EXTRACT(EPOCH FROM (
+           MAX(CASE WHEN pjt.stage = 'init'::provisioner_job_timing_stage THEN pjt.ended_at END) -
+           MIN(CASE WHEN pjt.stage = 'init'::provisioner_job_timing_stage THEN pjt.started_at END))), 0)  AS init_secs,
+       GREATEST(EXTRACT(EPOCH FROM (
+           MAX(CASE WHEN pjt.stage = 'plan'::provisioner_job_timing_stage THEN pjt.ended_at END) -
+           MIN(CASE WHEN pjt.stage = 'plan'::provisioner_job_timing_stage THEN pjt.started_at END))), 0)  AS plan_secs,
+       GREATEST(EXTRACT(EPOCH FROM (
+           MAX(CASE WHEN pjt.stage = 'graph'::provisioner_job_timing_stage THEN pjt.ended_at END) -
+           MIN(CASE WHEN pjt.stage = 'graph'::provisioner_job_timing_stage THEN pjt.started_at END))), 0) AS graph_secs,
+       GREATEST(EXTRACT(EPOCH FROM (
+           MAX(CASE WHEN pjt.stage = 'apply'::provisioner_job_timing_stage THEN pjt.ended_at END) -
+           MIN(CASE WHEN pjt.stage = 'apply'::provisioner_job_timing_stage THEN pjt.started_at END))), 0) AS apply_secs


Use the max(ended_at)-min(started_at) of each stage to determine stage timings.

coderd/workspacebuilds.go

dannykopping · 2024-08-15T14:08:09Z

provisioner/terraform/executor.go

@@ -539,46 +556,42 @@ func readAndLog(sink logSink, r io.Reader, done chan<- any, level proto.LogLevel
 // provisionLogWriter creates a WriteCloser that will log each JSON formatted terraform log.  The WriteCloser must be
 // closed by the caller to end logging, after which the returned channel will be closed to indicate that logging of the
 // written data has finished.  Failure to close the WriteCloser will leak a goroutine.
-func provisionLogWriter(sink logSink) (io.WriteCloser, <-chan any) {
+func (e *executor) provisionLogWriter(sink logSink) (io.WriteCloser, <-chan any) {


Moved these under the executor receiver to get access to the logger.

dannykopping · 2024-08-15T14:08:56Z

provisioner/terraform/executor.go

@@ -609,12 +676,25 @@ func convertTerraformLogLevel(logLevel string, sink logSink) proto.LogLevel {
 }

 type terraformProvisionLog struct {
-	Level   string `json:"@level"`
-	Message string `json:"@message"`
+	Level     string                    `json:"@level"`


I expanded this type to unmarshal additional fields from the existing JSON logs.

Signed-off-by: Danny Kopping <danny@coder.com>

site/e2e/google/protobuf/timestampGenerated.ts

Signed-off-by: Danny Kopping <danny@coder.com>

mafredri

Nice work, some minor nits and comments but looks good in general 👍🏻

coderd/database/migrations/000245_provisioner_job_timings.up.sql

coderd/database/sqlc.yaml

coderd/provisionerdserver/provisionerdserver.go

provisioner/terraform/executor.go

provisioner/terraform/testutil.go

provisioner/terraform/timings.go

provisioner/terraform/timings_internal_test.go

coderd/database/dbmem/dbmem.go

coderd/database/dbtime/dbtime.go

coderd/database/migrations/000245_provisioner_job_timings.up.sql

coderd/database/queries/provisionerjobs.sql

coderd/workspacebuilds.go

coderd/database/queries/provisionerjobs.sql

johnstcn · 2024-08-15T16:16:21Z

provisionerd/proto/provisionerd.pb.go

-// 	protoc-gen-go v1.30.0
-// 	protoc        v4.23.3
+// 	protoc-gen-go v1.34.2
+// 	protoc        v4.25.3


was this intentional?

Nope! Good catch.

Actually, we don't lock these versions.
In my dogfood workspace running nix, i've got:

$ protoc-gen-go --version protoc-gen-go v1.34.2 $ protoc --version libprotoc 25.3 $ which protoc protoc-gen-go /nix/var/nix/profiles/default/bin/protoc /nix/var/nix/profiles/default/bin/protoc-gen-go

I think CI uses the 'regular' dogfood image as opposed to 'nix'. This probably isn't a huge issue tbh but just wanted to double-check.

I would beg to differ.

If our dev environments' and our CI environment's dependencies are not in lock-step, this could lead not only to CI frustrations like the one above but to something more pernicious. We're either getting false-positives or false-negatives: any alignment is temporary/incidental, and we have no source of truth.

Added #14343 as a follow-up.

provisionerd/proto/provisionerd_drpc.pb.go

provisioner/terraform/timings.go

Signed-off-by: Danny Kopping <danny@coder.com>

…led-apply

Signed-off-by: Danny Kopping <danny@coder.com>

…on-detailed-apply

coderd/provisionerdserver/provisionerdserver.go

provisioner/terraform/internal/timings_test_utils.go

provisionersdk/proto/provisioner.proto

provisioner/terraform/testdata/timings-aggregation/fake-terraform.sh

johnstcn

I don't have any blocking changes here, but it would be good to verify the situation with external provisioners on upgrade.

dannykopping added 10 commits August 15, 2024 11:10

Initial implementation

7e36010

Signed-off-by: Danny Kopping <danny@coder.com>

More hacking, now including a job-wide view of timings

45b7fb4

Signed-off-by: Danny Kopping <danny@coder.com>

API

38c4197

Signed-off-by: Danny Kopping <danny@coder.com>

Smol refactor

803a9d4

Signed-off-by: Danny Kopping <danny@coder.com>

Capture dependency graph timings

973ec6d

Signed-off-by: Danny Kopping <danny@coder.com>

Expand hash to include span category so multiple operations on the sa…

a070e07

…me resource are captured Signed-off-by: Danny Kopping <danny@coder.com>

Tests

4a29b96

Signed-off-by: Danny Kopping <danny@coder.com>

lint/fmt

275bfca

Signed-off-by: Danny Kopping <danny@coder.com>

Moar tests

73bac3f

Signed-off-by: Danny Kopping <danny@coder.com>

Improve coverage

3d77c63

Signed-off-by: Danny Kopping <danny@coder.com>

github-actions bot assigned dannykopping Aug 15, 2024

dannykopping added 2 commits August 15, 2024 15:19

Remove stats API call, will follow up in another PR

c0ae1ba

Signed-off-by: Danny Kopping <danny@coder.com>

Fixing tests

28fa2f7

Signed-off-by: Danny Kopping <danny@coder.com>

dannykopping force-pushed the dk/provision-detailed-apply branch from 24477d6 to 28fa2f7 Compare August 15, 2024 13:36

dannykopping added 2 commits August 15, 2024 16:01

Use max(end)-min(start) as stage timings, not local maximum

68b16ff

Signed-off-by: Danny Kopping <danny@coder.com>

make fmt

6f0b8f8

Signed-off-by: Danny Kopping <danny@coder.com>

dannykopping commented Aug 15, 2024

View reviewed changes

Minor fix-ups

724f139

Signed-off-by: Danny Kopping <danny@coder.com>

dannykopping changed the title ~~Dk/provision detailed apply~~ feat: add provisioning timings to understand slow build times Aug 15, 2024

dannykopping commented Aug 15, 2024

View reviewed changes

site/e2e/google/protobuf/timestampGenerated.ts Show resolved Hide resolved

Pls god let this work

c30a900

Signed-off-by: Danny Kopping <danny@coder.com>

dannykopping requested review from mafredri, johnstcn and spikecurtis August 15, 2024 15:21

mafredri reviewed Aug 15, 2024

View reviewed changes

johnstcn reviewed Aug 15, 2024

View reviewed changes

dannykopping marked this pull request as ready for review August 15, 2024 18:22

dannykopping added 2 commits August 19, 2024 10:34

Move terraform test helpers into internal package

0d68e69

Signed-off-by: Danny Kopping <danny@coder.com>

Review comments

15282bb

Signed-off-by: Danny Kopping <danny@coder.com>

dannykopping added 2 commits August 19, 2024 11:15

Merge branch 'main' of github.com:coder/coder into dk/provision-detai…

82ca13e

…led-apply

More CI happiness

597ec85

Signed-off-by: Danny Kopping <danny@coder.com>

dannykopping force-pushed the dk/provision-detailed-apply branch from b5218be to 597ec85 Compare August 19, 2024 10:24

dannykopping added 4 commits August 19, 2024 10:48

Restrict timings tests to non-Windows

805c0f2

Signed-off-by: Danny Kopping <danny@coder.com>

Give CI exactly what it wants FFS (see #14343)

46f3318

Signed-off-by: Danny Kopping <danny@coder.com>

@mtojek you legend :)

ebbaf31

Signed-off-by: Danny Kopping <danny@coder.com>

Merge branch 'main' of https://github.com/coder/coder into dk/provisi…

eb5ec5c

…on-detailed-apply

johnstcn reviewed Aug 20, 2024

View reviewed changes

coderd/provisionerdserver/provisionerdserver.go Show resolved Hide resolved

johnstcn reviewed Aug 20, 2024

View reviewed changes

provisioner/terraform/internal/timings_test_utils.go Show resolved Hide resolved

johnstcn reviewed Aug 20, 2024

View reviewed changes

provisionersdk/proto/provisioner.proto Show resolved Hide resolved

johnstcn reviewed Aug 20, 2024

View reviewed changes

provisioner/terraform/testdata/timings-aggregation/fake-terraform.sh Show resolved Hide resolved

johnstcn approved these changes Aug 20, 2024

View reviewed changes

dannykopping merged commit 6960d19 into main Aug 21, 2024
34 checks passed

dannykopping deleted the dk/provision-detailed-apply branch August 21, 2024 12:19

github-actions bot locked and limited conversation to collaborators Aug 21, 2024

This was referenced Aug 21, 2024

fix: add missing commit for provisioner timings PR #14380

Merged

improve observability of provisionerd metrics #12474

Open

This was referenced Aug 29, 2024

Create an API which exposes provisioning timings coder/internal#43

Closed

Create a UI which visualizes workspace timings coder/internal#44

Closed

dannykopping mentioned this pull request Sep 10, 2024

Add agent script timings #14630

Closed

stirby mentioned this pull request Oct 2, 2024

Notifications: Report template build times #14939

Open

matifali added the roadmap https://coder.com/roadmap. Only humans may set this. label Oct 22, 2024

johnstcn mentioned this pull request Oct 30, 2024

feature: expose provisioner job timings in prometheus #15284

Closed

coder unlocked this conversation Nov 14, 2024

coder locked as resolved and limited conversation to collaborators Nov 14, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

feat: add provisioning timings to understand slow build times #14274

feat: add provisioning timings to understand slow build times #14274

dannykopping commented Aug 15, 2024 •

edited

Loading

alwaysmeticulous bot commented Aug 15, 2024 •

edited

Loading

dannykopping Aug 15, 2024

dannykopping Aug 15, 2024

dannykopping Aug 15, 2024

dannykopping Aug 15, 2024

dannykopping Aug 15, 2024

dannykopping Aug 15, 2024

mafredri left a comment

johnstcn Aug 15, 2024

dannykopping Aug 19, 2024

dannykopping Aug 19, 2024

johnstcn Aug 20, 2024

dannykopping Aug 20, 2024

dannykopping Aug 21, 2024

johnstcn left a comment

feat: add provisioning timings to understand slow build times #14274

feat: add provisioning timings to understand slow build times #14274

Conversation

dannykopping commented Aug 15, 2024 • edited Loading

alwaysmeticulous bot commented Aug 15, 2024 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

mafredri left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

johnstcn left a comment

Choose a reason for hiding this comment

dannykopping commented Aug 15, 2024 •

edited

Loading

alwaysmeticulous bot commented Aug 15, 2024 •

edited

Loading