A progress update:

I've knocked together https://github.com/coder/coder/compare/dk/provision-detailed-apply, which is a quick-and-dirty implementation to capture and store terraform plan & apply timings. This will help us determine which resources slow workspace builds down.

This does not cover Terraform init timings, which is another source of startup latency.

Findings

Here are my findings of the last couple days' research. I spent the first 2 days looking through the source to understand how all the pieces fit together and identify possible areas for improvement.

Provisioning Speed

Workspace provisioning comprises at least 3 distinct stages during which latency can creep in.

• Initialization (terraform init: download of providers, modules)
• Build (terraform apply)
• Agent registration & setup

Our workspace builds on dogfood are inconsistent and often slow. This has been documented previously in coder/coder#13691, and also maps to my experience. We do implement terraform caching, but:

• caches are local to each provisionerd/coderd pod
• we deploy updates to dogfood often - restarting these pods & obliterating the cache
• each provisioner has to build up its own cache
• we only fully cache about half of workspace builds! ¹

We need an external cache which will not be lost on every deploy, and so do our customers (arguably the community at large needs it too).

To this end I quickly hacked up https://github.com/coder/terracache which is a TLS-intercepting and caching proxy which we can stand up alongside our coderd/provisionerd pods. It's just an in-memory cache for now, but it should speed up builds significantly.

Observability

Even if we make our builds as fast as possible, they're only as fast as the slowest provider's API.

When terraform apply runs, it can produce JSON logs of each step in the build process like follows:

{"@level":"info","@message":"docker_container.workspace[0]: Plan to create","@module":"terraform.ui","@timestamp":"2024-08-06T17:16:24.111417+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":"docker_container.workspace[0]: Creating...","@module":"terraform.ui","@timestamp":"2024-08-06T17:16:24.233404+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 errored after 0s","@module":"terraform.ui","@timestamp":"2024-08-06T17:16:24.245458+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","elapsed_seconds":0},"type":"apply_errored"}
{"@level":"error","@message":"Error: Unable to create container: Error response from daemon: Conflict. The container name \"/coder-default-default\" is already in use by container \"2a0e1298adb8fe63d2ed0cb9ab0a1c85a135043518696866c89d767ce9b9a28f\". You have to remove (or rename) that container to be able to reuse that name.","@module":"terraform.ui","@timestamp":"2024-08-06T17:16:24.256653+02:00","diagnostic":{"severity":"error","summary":"Unable to create container: Error response from daemon: Conflict. The container name \"/coder-default-default\" is already in use by container \"2a0e1298adb8fe63d2ed0cb9ab0a1c85a135043518696866c89d767ce9b9a28f\". You have to remove (or rename) that container to be able to reuse that name.","detail":"","address":"docker_container.workspace[0]","range":{"filename":"main.tf","start":{"line":148,"column":41,"byte":4695},"end":{"line":148,"column":42,"byte":4696}},"snippet":{"context":"resource \"docker_container\" \"workspace\"","code":"resource \"docker_container\" \"workspace\" {","start_line":148,"highlight_start_offset":40,"highlight_end_offset":41,"values":[]}},"type":"diagnostic"}

Using these JSON logs, we could provider users and operators with a waterfall chart of all the stages in the terraform apply and how long each took.

I've implemented the basic framework for this feature (backend only, lol) in https://github.com/coder/coder/compare/dk/provision-detailed-apply. See #22 (comment) above for a view of the data in a new table named provisioner_job_timings.

We could also turn this data into per-provider Prometheus metrics so operators could see which providers are the slowest and consider alternatives if provisioning speed is very important to them.

Additionally, we could incorporate the timings from the other stages into this graph to visualize the full process including time spent waiting to be scheduled on a provisioner, etc.

¹

WITH no_cache_cte AS (
  SELECT COUNT(no_cache.*) AS no_cache FROM (
    SELECT job_id FROM provisioner_job_logs WHERE (
      output LIKE '%Downloading https://registry%'  -- modules
      OR output LIKE '%- Installing%'               -- providers
    )
    GROUP BY job_id
  ) AS no_cache
),
total_cte AS (
  SELECT COUNT(*) AS total FROM (
    SELECT job_id FROM provisioner_job_logs
    GROUP BY job_id
  ) AS all_entries
)
SELECT 
  (1 - (CAST(no_cache_cte.no_cache AS DECIMAL(10,2)) / CAST(total_cte.total AS DECIMAL(10,2)))) * 100 AS cached
FROM 
  no_cache_cte, 
  total_cte;

I've noticed dogfood executes Terraform slower than other deployments (e.g. my local deployment). For example, it often hangs on "Terraform"

Any idea why?

Lemme know if the above comment doesn't answer that question for ya; looks like we posted at the same time @bpmct

Ah whoops, reading now. terracache and the visualization looks extremely promising!

we deploy updates to dogfood often - restarting these pods & obliterating the cache

Have you explored whether it is also a resource/db utilization problem? Admittedly, this is not a perfect comparison (the dev build fails), but I notice in general there are more "hangs" from provisioning in dev (e.g. "at the Terraform" step).

This could be for a number of reasons, which might be difficult to isolate.
Are you able to replicate the problem reliably?
It could be a resource contention problem, insufficient provisioners or compute resources assigned to them, a slow provider API, or something else.

In any case, we should see this problem exacerbated once we make provisioning faster, which would make it easier to solve if there is indeed an issue within our scope.

I'll look at getting terracache into dogfood next week, and we can touch base. Sound good?

Are you able to replicate the problem reliably?

Yeah, pretty much every build I do on dev feels slower than by builds on any other deployment.

I'll look at getting terracache into dogfood next week, and we can touch base. Sound good?

🫡

coder/coder#14452 is required for us to deploy terracache to dogfood.