Skip to content

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

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 24 commits into from
Aug 21, 2024
Merged

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

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
24 commits
Select commit Hold shift + click to select a range
7e36010
Initial implementation
dannykopping Aug 7, 2024
45b7fb4
More hacking, now including a job-wide view of timings
dannykopping Aug 13, 2024
38c4197
API
dannykopping Aug 13, 2024
803a9d4
Smol refactor
dannykopping Aug 14, 2024
973ec6d
Capture dependency graph timings
dannykopping Aug 14, 2024
a070e07
Expand hash to include span category so multiple operations on the sa…
dannykopping Aug 14, 2024
4a29b96
Tests
dannykopping Aug 15, 2024
275bfca
lint/fmt
dannykopping Aug 15, 2024
73bac3f
Moar tests
dannykopping Aug 15, 2024
3d77c63
Improve coverage
dannykopping Aug 15, 2024
c0ae1ba
Remove stats API call, will follow up in another PR
dannykopping Aug 15, 2024
28fa2f7
Fixing tests
dannykopping Aug 15, 2024
68b16ff
Use max(end)-min(start) as stage timings, not local maximum
dannykopping Aug 15, 2024
6f0b8f8
make fmt
dannykopping Aug 15, 2024
724f139
Minor fix-ups
dannykopping Aug 15, 2024
c30a900
Pls god let this work
dannykopping Aug 15, 2024
0d68e69
Move terraform test helpers into internal package
dannykopping Aug 19, 2024
15282bb
Review comments
dannykopping Aug 19, 2024
82ca13e
Merge branch 'main' of github.com:coder/coder into dk/provision-detai…
dannykopping Aug 19, 2024
597ec85
More CI happiness
dannykopping Aug 19, 2024
805c0f2
Restrict timings tests to non-Windows
dannykopping Aug 19, 2024
46f3318
Give CI exactly what it wants FFS (see https://github.com/coder/coder…
dannykopping Aug 19, 2024
ebbaf31
@mtojek you legend :)
dannykopping Aug 19, 2024
eb5ec5c
Merge branch 'main' of https://github.com/coder/coder into dk/provisi…
dannykopping Aug 20, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Prev Previous commit
Next Next commit
Tests 
Signed-off-by: Danny Kopping <danny@coder.com>
  • Loading branch information
@dannykopping
dannykopping committed Aug 15, 2024
commit 4a29b964dbcc92b2f3c8d71c894e03bdd3b1d36b
73 changes: 44 additions & 29 deletions provisioner/terraform/executor.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -565,41 +565,27 @@ func (e *executor) provisionLogWriter(sink logSink) (io.WriteCloser, <-chan any)

func (e *executor) provisionReadAndLog(sink logSink, r io.Reader, done chan<- any) {
defer close(done)

errCount := 0

scanner := bufio.NewScanner(r)
for scanner.Scan() {
var log terraformProvisionLog
err := json.Unmarshal(scanner.Bytes(), &log)
if err != nil {
// Sometimes terraform doesn't log JSON, even though we asked it to.
// The terraform maintainers have said on the issue tracker that
// they don't guarantee that non-JSON lines won't get printed.
// https://github.com/hashicorp/terraform/issues/29252#issuecomment-887710001
//
// > I think as a practical matter it isn't possible for us to
// > promise that the output will always be entirely JSON, because
// > there's plenty of code that runs before command line arguments
// > are parsed and thus before we even know we're in JSON mode.
// > Given that, I'd suggest writing code that consumes streaming
// > JSON output from Terraform in such a way that it can tolerate
// > the output not having JSON in it at all.
//
// Log lines such as:
// - Acquiring state lock. This may take a few moments...
// - Releasing state lock. This may take a few moments...
if strings.TrimSpace(scanner.Text()) == "" {
continue
}
log.Level = "info"
log.Message = scanner.Text()
log := parseTerraformLogLine(scanner.Bytes())
if log == nil {
continue
}

logLevel := convertTerraformLogLevel(log.Level, sink)
sink.ProvisionLog(logLevel, log.Message)

ts, span, err := extractTimingSpan(log)
if err != nil {
e.logger.Debug(context.Background(), "failed to extract timings entry from log line",
slog.F("line", log.Message), slog.Error(err))
// It's too noisy to log all of these as timings are not an essential feature, but we do need to log *some*.
if errCount%10 == 0 {
e.logger.Warn(context.Background(), "(sampled) failed to extract timings entry from log line",
slog.F("line", log.Message), slog.Error(err))
}
errCount++
} else {
// Only ingest valid timings.
e.timings.ingest(ts, span)
Expand All @@ -616,15 +602,44 @@ func (e *executor) provisionReadAndLog(sink logSink, r io.Reader, done chan<- an
}
}

func extractTimingSpan(log terraformProvisionLog) (time.Time, *timingSpan, error) {
func parseTerraformLogLine(line []byte) *terraformProvisionLog {
var log terraformProvisionLog
err := json.Unmarshal(line, &log)
if err != nil {
// Sometimes terraform doesn't log JSON, even though we asked it to.
// The terraform maintainers have said on the issue tracker that
// they don't guarantee that non-JSON lines won't get printed.
// https://github.com/hashicorp/terraform/issues/29252#issuecomment-887710001
//
// > I think as a practical matter it isn't possible for us to
// > promise that the output will always be entirely JSON, because
// > there's plenty of code that runs before command line arguments
// > are parsed and thus before we even know we're in JSON mode.
// > Given that, I'd suggest writing code that consumes streaming
// > JSON output from Terraform in such a way that it can tolerate
// > the output not having JSON in it at all.
//
// Log lines such as:
// - Acquiring state lock. This may take a few moments...
// - Releasing state lock. This may take a few moments...
if len(bytes.TrimSpace(line)) == 0 {
return nil
}
log.Level = "info"
log.Message = string(line)
}
return &log
}

func extractTimingSpan(log *terraformProvisionLog) (time.Time, *timingSpan, error) {
// Input is not well-formed, bail out.
if log.Type == "" {
return time.Time{}, nil, xerrors.Errorf("invalid type: %q", log.Type)
return time.Time{}, nil, xerrors.Errorf("invalid timing kind: %q", log.Type)
}

typ := timingKind(log.Type)
if !typ.Valid() {
return time.Time{}, nil, xerrors.Errorf("invalid type: %q", log.Type)
return time.Time{}, nil, xerrors.Errorf("unexpected timing kind: %q", log.Type)
}

ts, err := time.Parse("2006-01-02T15:04:05.000000Z07:00", log.Timestamp)
Expand Down
39 changes: 39 additions & 0 deletions provisioner/terraform/testdata/timings-aggregation/complete.txtar
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -0,0 +1,39 @@
A successful build which results in successful plan and apply timings.

-- plan --
{"@level":"info","@message":"Terraform 1.9.2","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:38.097648+02:00","terraform":"1.9.2","type":"version","ui":"1.2"}
{"@level":"info","@message":"data.coder_workspace.me: Refreshing...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.194726+02:00","hook":{"resource":{"addr":"data.coder_workspace.me","module":"","resource":"data.coder_workspace.me","implied_provider":"coder","resource_type":"coder_workspace","resource_name":"me","resource_key":null},"action":"read"},"type":"apply_start"}
{"@level":"info","@message":"data.coder_parameter.memory_size: Refreshing...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.194726+02:00","hook":{"resource":{"addr":"data.coder_parameter.memory_size","module":"","resource":"data.coder_parameter.memory_size","implied_provider":"coder","resource_type":"coder_parameter","resource_name":"memory_size","resource_key":null},"action":"read"},"type":"apply_start"}
{"@level":"info","@message":"data.coder_provisioner.me: Refreshing...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.194726+02:00","hook":{"resource":{"addr":"data.coder_provisioner.me","module":"","resource":"data.coder_provisioner.me","implied_provider":"coder","resource_type":"coder_provisioner","resource_name":"me","resource_key":null},"action":"read"},"type":"apply_start"}
{"@level":"info","@message":"data.coder_provisioner.me: Refresh complete after 0s [id=2470b3d2-32f4-4f95-ac70-0971efdb8338]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.195712+02:00","hook":{"resource":{"addr":"data.coder_provisioner.me","module":"","resource":"data.coder_provisioner.me","implied_provider":"coder","resource_type":"coder_provisioner","resource_name":"me","resource_key":null},"action":"read","id_key":"id","id_value":"2470b3d2-32f4-4f95-ac70-0971efdb8338","elapsed_seconds":0},"type":"apply_complete"}
{"@level":"info","@message":"data.coder_workspace.me: Refresh complete after 0s [id=feb06d32-3252-4cd8-b7db-ea0c5145747f]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.195820+02:00","hook":{"resource":{"addr":"data.coder_workspace.me","module":"","resource":"data.coder_workspace.me","implied_provider":"coder","resource_type":"coder_workspace","resource_name":"me","resource_key":null},"action":"read","id_key":"id","id_value":"feb06d32-3252-4cd8-b7db-ea0c5145747f","elapsed_seconds":0},"type":"apply_complete"}
{"@level":"info","@message":"data.coder_parameter.memory_size: Refresh complete after 0s [id=b136c86c-1be0-43b4-9d78-e492918c5de0]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.195836+02:00","hook":{"resource":{"addr":"data.coder_parameter.memory_size","module":"","resource":"data.coder_parameter.memory_size","implied_provider":"coder","resource_type":"coder_parameter","resource_name":"memory_size","resource_key":null},"action":"read","id_key":"id","id_value":"b136c86c-1be0-43b4-9d78-e492918c5de0","elapsed_seconds":0},"type":"apply_complete"}
{"@level":"info","@message":"coder_agent.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221555+02:00","change":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"docker_image.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221574+02:00","change":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"docker_volume.home_volume: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221580+02:00","change":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"docker_container.workspace[0]: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221584+02:00","change":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"Plan: 4 to add, 0 to change, 0 to destroy.","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.221589+02:00","changes":{"add":4,"change":0,"import":0,"remove":0,"operation":"plan"},"type":"change_summary"}
-- apply --
{"@level":"info","@message":"Terraform 1.9.2","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.507006+02:00","terraform":"1.9.2","type":"version","ui":"1.2"}
{"@level":"info","@message":"coder_agent.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572335+02:00","change":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"docker_image.main: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572411+02:00","change":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"docker_volume.home_volume: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572416+02:00","change":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"docker_container.workspace[0]: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.572424+02:00","change":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create"},"type":"planned_change"}
{"@level":"info","@message":"coder_agent.main: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.616546+02:00","hook":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create"},"type":"apply_start"}
{"@level":"info","@message":"coder_agent.main: Creation complete after 0s [id=a23083da-4679-4396-a306-f7b466237883]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.618045+02:00","hook":{"resource":{"addr":"coder_agent.main","module":"","resource":"coder_agent.main","implied_provider":"coder","resource_type":"coder_agent","resource_name":"main","resource_key":null},"action":"create","id_key":"id","id_value":"a23083da-4679-4396-a306-f7b466237883","elapsed_seconds":0},"type":"apply_complete"}
{"@level":"info","@message":"docker_image.main: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.626722+02:00","hook":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create"},"type":"apply_start"}
{"@level":"info","@message":"docker_volume.home_volume: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.627335+02:00","hook":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create"},"type":"apply_start"}
{"@level":"info","@message":"docker_volume.home_volume: Creation complete after 0s [id=coder-feb06d32-3252-4cd8-b7db-ea0c5145747f-home]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.660616+02:00","hook":{"resource":{"addr":"docker_volume.home_volume","module":"","resource":"docker_volume.home_volume","implied_provider":"docker","resource_type":"docker_volume","resource_name":"home_volume","resource_key":null},"action":"create","id_key":"id","id_value":"coder-feb06d32-3252-4cd8-b7db-ea0c5145747f-home","elapsed_seconds":0},"type":"apply_complete"}
{"@level":"info","@message":"docker_image.main: Creation complete after 0s [id=sha256:443d199e8bfcce69c2aa494b36b5f8b04c3b183277cd19190e9589fd8552d618nginx:latest]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.669954+02:00","hook":{"resource":{"addr":"docker_image.main","module":"","resource":"docker_image.main","implied_provider":"docker","resource_type":"docker_image","resource_name":"main","resource_key":null},"action":"create","id_key":"id","id_value":"sha256:443d199e8bfcce69c2aa494b36b5f8b04c3b183277cd19190e9589fd8552d618nginx:latest","elapsed_seconds":0},"type":"apply_complete"}
{"@level":"info","@message":"docker_container.workspace[0]: Creating...","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:39.682223+02:00","hook":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create"},"type":"apply_start"}
{"@level":"info","@message":"docker_container.workspace[0]: Creation complete after 0s [id=e39f34233fe1f6d18a33eaed8ad47ef1ae19ccf8cf6841858d5f2dafe4e3c8c9]","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.186482+02:00","hook":{"resource":{"addr":"docker_container.workspace[0]","module":"","resource":"docker_container.workspace[0]","implied_provider":"docker","resource_type":"docker_container","resource_name":"workspace","resource_key":0},"action":"create","id_key":"id","id_value":"e39f34233fe1f6d18a33eaed8ad47ef1ae19ccf8cf6841858d5f2dafe4e3c8c9","elapsed_seconds":0},"type":"apply_complete"}
{"@level":"info","@message":"Apply complete! Resources: 4 added, 0 changed, 0 destroyed.","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.204593+02:00","changes":{"add":4,"change":0,"import":0,"remove":0,"operation":"apply"},"type":"change_summary"}
{"@level":"info","@message":"Outputs: 0","@module":"terraform.ui","@timestamp":"2024-08-15T10:26:40.205051+02:00","outputs":{},"type":"outputs"}
-- timings --
{"start":"2024-08-15T08:26:39.194726Z","end":"2024-08-15T08:26:39.195820Z","action":"read","source":"coder","resource":"data.coder_workspace.me","stage":"plan","state":"COMPLETED"}
{"start":"2024-08-15T08:26:39.194726Z","end":"2024-08-15T08:26:39.195712Z","action":"read","source":"coder","resource":"data.coder_provisioner.me","stage":"plan","state":"COMPLETED"}
{"start":"2024-08-15T08:26:39.194726Z","end":"2024-08-15T08:26:39.195836Z","action":"read","source":"coder","resource":"data.coder_parameter.memory_size","stage":"plan","state":"COMPLETED"}
{"start":"2024-08-15T08:26:39.616546Z","end":"2024-08-15T08:26:39.618045Z","action":"create","source":"coder","resource":"coder_agent.main","stage":"apply","state":"COMPLETED"}
{"start":"2024-08-15T08:26:39.626722Z","end":"2024-08-15T08:26:39.669954Z","action":"create","source":"docker","resource":"docker_image.main","stage":"apply","state":"COMPLETED"}
{"start":"2024-08-15T08:26:39.627335Z","end":"2024-08-15T08:26:39.660616Z","action":"create","source":"docker","resource":"docker_volume.home_volume","stage":"apply","state":"COMPLETED"}
{"start":"2024-08-15T08:26:39.682223Z","end":"2024-08-15T08:26:40.186482Z","action":"create","source":"docker","resource":"docker_container.workspace[0]","stage":"apply","state":"COMPLETED"}
Loading