09df1ab Merge branch 'perf/p1-timing' into perf/job-timing-and-caches · ermite-runner

M docs/development.md +25 -0


@@ -63,3 +63,28 @@ ERMITE_RUNNER_IT_E2E=1 ERMITE_RUNNER_TEST_IMAGE=ermite-runner-ubuntu-26.04:dev G
63	63		- Docker API. Production `container` mode supports Docker Engine and sysbox. Podman's compatibility API is not a drop-in: it cannot disable DNS on the network that the runner creates.
64	64		- Jailer. The jailer needs `--chroot-base-dir` to exist. The driver creates `<state dir>/jail`. It leaves `<state dir>/jail/<exec name>` and `/sys/fs/cgroup/firecracker` behind.
65	65		- Host firewalls. A firewall that rejects `53` on `ertap` or `erbr` breaks guest DNS. The symptom is `dns silent` in `TestVMNetworkPolicy`.
	66	+
	67	+	## Measuring start-up on a small host
	68	+
	69	+	Build and register the [runner container](container.md) as usual, then constrain
	70	+	its CPU budget to reproduce a small host without changing the boot sequence:
	71	+
	72	+	```sh
	73	+	docker run --name runner-timing --cpus=1 \
	74	+	--device /dev/kvm --device /dev/net/tun --cap-add NET_ADMIN \
	75	+	-v runner-timing-state:/var/lib/ermite-runner \
	76	+	--env-file runner.env -e ERMITE_RUNNER_LOG_FORMAT=json ermite-runner:<tag>
	77	+	```
	78	+
	79	+	Use a registered state volume or supply the registration settings in
	80	+	`runner.env`; never put tokens in shared shell history. Podman accepts the same
	81	+	CPU limit (device access may need the CDI setup described in the container
	82	+	guide). Submit representative jobs, then extract completed-job measurements:
	83	+
	84	+	```sh
	85	+	docker logs runner-timing 2>&1 \| jq 'select(.message=="job finished")'
	86	+	```
	87	+
	88	+	Compare `sandbox_ms`, the `sb_` stages and `guest_` boot stages across jobs.
	89	+	`run_ms` includes action downloads and step execution; archive misses have their
	90	+	own counters. See [Job timing](service.md#job-timing) for the full field table.


@@ -63,3 +63,28 @@ ERMITE_RUNNER_IT_E2E=1 ERMITE_RUNNER_TEST_IMAGE=ermite-runner-ubuntu-26.04:dev G
63	- Docker API. Production `container` mode supports Docker Engine and sysbox. Podman's compatibility API is not a drop-in: it cannot disable DNS on the network that the runner creates.	63		- Docker API. Production `container` mode supports Docker Engine and sysbox. Podman's compatibility API is not a drop-in: it cannot disable DNS on the network that the runner creates.
64	- Jailer. The jailer needs `--chroot-base-dir` to exist. The driver creates `<state dir>/jail`. It leaves `<state dir>/jail/<exec name>` and `/sys/fs/cgroup/firecracker` behind.	64		- Jailer. The jailer needs `--chroot-base-dir` to exist. The driver creates `<state dir>/jail`. It leaves `<state dir>/jail/<exec name>` and `/sys/fs/cgroup/firecracker` behind.
65	- Host firewalls. A firewall that rejects `53` on `ertap` or `erbr` breaks guest DNS. The symptom is `dns silent` in `TestVMNetworkPolicy`.	65		- Host firewalls. A firewall that rejects `53` on `ertap` or `erbr` breaks guest DNS. The symptom is `dns silent` in `TestVMNetworkPolicy`.
		66	+
		67	+	## Measuring start-up on a small host
		68	+
		69	+	Build and register the [runner container](container.md) as usual, then constrain
		70	+	its CPU budget to reproduce a small host without changing the boot sequence:
		71	+
		72	+	```sh
		73	+	docker run --name runner-timing --cpus=1 \
		74	+	--device /dev/kvm --device /dev/net/tun --cap-add NET_ADMIN \
		75	+	-v runner-timing-state:/var/lib/ermite-runner \
		76	+	--env-file runner.env -e ERMITE_RUNNER_LOG_FORMAT=json ermite-runner:<tag>
		77	+	```
		78	+
		79	+	Use a registered state volume or supply the registration settings in
		80	+	`runner.env`; never put tokens in shared shell history. Podman accepts the same
		81	+	CPU limit (device access may need the CDI setup described in the container
		82	+	guide). Submit representative jobs, then extract completed-job measurements:
		83	+
		84	+	```sh
		85	+	docker logs runner-timing 2>&1 \| jq 'select(.message=="job finished")'
		86	+	```
		87	+
		88	+	Compare `sandbox_ms`, the `sb_` stages and `guest_` boot stages across jobs.
		89	+	`run_ms` includes action downloads and step execution; archive misses have their
		90	+	own counters. See [Job timing](service.md#job-timing) for the full field table.

M docs/service.md +30 -0


@@ -64,3 +64,33 @@ Do not add:
64	64		- `Delegate` and `UMask`: not needed.
65	65
66	66		The security boundary of a job is its microVM or container, not the unit.
	67	+
	68	+	## Job timing
	69	+
	70	+	The existing `job finished` line carries integer milliseconds (all `*_ms`
	71	+	fields). Phases that did not run are omitted; driver timings are available only
	72	+	when sandbox start succeeds. Guest phases are omitted when they did not run.
	73	+
	74	+	\| Fields \| Meaning \|
	75	+	\| --- \| --- \|
	76	+	\| `ack_ms` \| Assignment received to successful first heartbeat acknowledgement \|
	77	+	\| `sandbox_ms` \| Host `startSandbox` call \|
	78	+	\| `run_ms` \| Executor session (`drive`) \|
	79	+	\| `stop_ms` \| Sandbox `Stop` call \|
	80	+	\| `complete_ms` \| Completion call, including retries \|
	81	+	\| `total_ms` \| Assignment received to this log line, including log flushing \|
	82	+	\| `resolve_calls`, `resolve_ms` \| Number and summed duration of action resolution requests \|
	83	+	\| `archive_misses`, `archive_miss_ms`, `archive_miss_bytes` \| Archive misses and their summed fetch duration and bytes \|
	84	+	\| `sb_tap_ms`, `sb_net_ms` (VM) \| TAP creation and the rest of network setup \|
	85	+	\| `sb_vmm_ms`, `sb_files_ms`, `sb_scratch_ms` (VM) \| VMM launch/API readiness, shared files excluding scratch, scratch creation \|
	86	+	\| `sb_vsock_ms`, `sb_configure_ms`, `sb_connect_ms` (VM) \| Executor/cache sockets, VM configuration/start, executor connection wait \|
	87	+	\| `sb_socket_ms`, `sb_cache_ms`, `sb_scratch_ms` (container) \| Executor socket, cache socket, scratch setup \|
	88	+	\| `sb_net_ms`, `sb_container_ms`, `sb_connect_ms` (container) \| Network setup, container creation/start, executor connection wait \|
	89	+	\| `guest_kernel_ms`, `guest_setup_ms` (VM only) \| Kernel uptime at init entry, VM filesystem/system setup \|
	90	+	\| `guest_containerd_ms`, `guest_dockerd_ms` \| Containerd start/readiness, dockerd spawn through readiness wait \|
	91	+
	92	+	Guest boot overlaps the driver's executor connection wait: do not sum those
	93	+	fields with `sandbox_ms`. Driver `container running` and `micro-VM running`
	94	+	lines also carry unprefixed phase fields and `total_ms` for their boot sequence.
	95	+	The `action archive cache` line carries `verify_ms` for integrity verification;
	96	+	a miss also carries `fetch_ms` and `bytes`. Archive verification is never skipped.


@@ -64,3 +64,33 @@ Do not add:
64	- `Delegate` and `UMask`: not needed.	64		- `Delegate` and `UMask`: not needed.
65		65
66	The security boundary of a job is its microVM or container, not the unit.	66		The security boundary of a job is its microVM or container, not the unit.
		67	+
		68	+	## Job timing
		69	+
		70	+	The existing `job finished` line carries integer milliseconds (all `*_ms`
		71	+	fields). Phases that did not run are omitted; driver timings are available only
		72	+	when sandbox start succeeds. Guest phases are omitted when they did not run.
		73	+
		74	+	\| Fields \| Meaning \|
		75	+	\| --- \| --- \|
		76	+	\| `ack_ms` \| Assignment received to successful first heartbeat acknowledgement \|
		77	+	\| `sandbox_ms` \| Host `startSandbox` call \|
		78	+	\| `run_ms` \| Executor session (`drive`) \|
		79	+	\| `stop_ms` \| Sandbox `Stop` call \|
		80	+	\| `complete_ms` \| Completion call, including retries \|
		81	+	\| `total_ms` \| Assignment received to this log line, including log flushing \|
		82	+	\| `resolve_calls`, `resolve_ms` \| Number and summed duration of action resolution requests \|
		83	+	\| `archive_misses`, `archive_miss_ms`, `archive_miss_bytes` \| Archive misses and their summed fetch duration and bytes \|
		84	+	\| `sb_tap_ms`, `sb_net_ms` (VM) \| TAP creation and the rest of network setup \|
		85	+	\| `sb_vmm_ms`, `sb_files_ms`, `sb_scratch_ms` (VM) \| VMM launch/API readiness, shared files excluding scratch, scratch creation \|
		86	+	\| `sb_vsock_ms`, `sb_configure_ms`, `sb_connect_ms` (VM) \| Executor/cache sockets, VM configuration/start, executor connection wait \|
		87	+	\| `sb_socket_ms`, `sb_cache_ms`, `sb_scratch_ms` (container) \| Executor socket, cache socket, scratch setup \|
		88	+	\| `sb_net_ms`, `sb_container_ms`, `sb_connect_ms` (container) \| Network setup, container creation/start, executor connection wait \|
		89	+	\| `guest_kernel_ms`, `guest_setup_ms` (VM only) \| Kernel uptime at init entry, VM filesystem/system setup \|
		90	+	\| `guest_containerd_ms`, `guest_dockerd_ms` \| Containerd start/readiness, dockerd spawn through readiness wait \|
		91	+
		92	+	Guest boot overlaps the driver's executor connection wait: do not sum those
		93	+	fields with `sandbox_ms`. Driver `container running` and `micro-VM running`
		94	+	lines also carry unprefixed phase fields and `total_ms` for their boot sequence.
		95	+	The `action archive cache` line carries `verify_ms` for integrity verification;
		96	+	a miss also carries `fetch_ms` and `bytes`. Archive verification is never skipped.

M internal/actionscache/cache.go +18 -14


@@ -184,14 +184,16 @@ type Fetch func(ctx context.Context, w io.Writer) error
184	184		// download it when it does not (a miss: hit is false). Concurrent calls for the
185	185		// same key share one download; the others report a hit once it is in place. The
186	186		// entry is pinned for PinFor.
187		-	func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool, err error) {
	187	+	func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool, verify time.Duration, err error) {
188	188		if !validKey(key) {
189		-	return false, ErrNotFound
	189	+	return false, verify, ErrNotFound
190	190		}
191	191		for {
192		-	if c.verify(key) == nil {
	192	+	duration, err := c.verify(key)
	193	+	verify += duration
	194	+	if err == nil {
193	195		c.touch(key, true)
194		-	return true, nil
	196	+	return true, verify, nil
195	197		}
196	198		c.mu.Lock()
197	199		if f, ok := c.flights[key]; ok {

@@ -199,10 +201,10 @@ func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool,
199	201		select {
200	202		case <-f.done:
201	203		case <-ctx.Done():
202		-	return false, ctx.Err()
	204	+	return false, verify, ctx.Err()
203	205		}
204	206		if f.err != nil {
205		-	return false, f.err
	207	+	return false, verify, f.err
206	208		}
207	209		continue
208	210		}

@@ -215,10 +217,10 @@ func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool,
215	217		c.mu.Unlock()
216	218		close(f.done)
217	219		if f.err != nil {
218		-	return false, f.err
	220	+	return false, verify, f.err
219	221		}
220	222		c.touch(key, true)
221		-	return false, nil
	223	+	return false, verify, nil
222	224		}
223	225		}
224	226

@@ -314,11 +316,13 @@ func (w *countWriter) Write(p []byte) (int, error) {
314	316
315	317		// verify re-hashes the archive of key against its sum. Any mismatch (or a
316	318		// missing file) drops the entry and returns ErrNotFound.
317		-	func (c *Cache) verify(key string) error {
	319	+	func (c *Cache) verify(key string) (duration time.Duration, err error) {
	320	+	start := time.Now()
	321	+	defer func() { duration = time.Since(start) }()
318	322		sb, err := os.ReadFile(c.sumPath(key))
319	323		if err != nil {
320	324		c.drop(key)
321		-	return ErrNotFound
	325	+	return 0, ErrNotFound
322	326		}
323	327		want, sizeS, _ := strings.Cut(strings.TrimSpace(string(sb)), " ")
324	328		size, perr := strconv.ParseInt(sizeS, 10, 64)

@@ -328,7 +332,7 @@ func (c *Cache) verify(key string) error {
328	332		_ = f.Close()
329	333		}
330	334		c.drop(key)
331		-	return ErrNotFound
	335	+	return 0, ErrNotFound
332	336		}
333	337		defer func() { _ = f.Close() }()
334	338		h := sha256.New()

@@ -336,9 +340,9 @@ func (c *Cache) verify(key string) error {
336	340		if err != nil \|\| n != size \|\| hex.EncodeToString(h.Sum(nil)) != want {
337	341		c.log.Warn().Str("key", key).Msg("action archive failed its integrity check; dropped")
338	342		c.drop(key)
339		-	return ErrNotFound
	343	+	return 0, ErrNotFound
340	344		}
341		-	return nil
	345	+	return 0, nil
342	346		}
343	347
344	348		func (c *Cache) drop(key string) {

@@ -396,7 +400,7 @@ func (c Cache) Open(key string) (os.File, error) {
396	400		if !validKey(key) {
397	401		return nil, ErrNotFound
398	402		}
399		-	if err := c.verify(key); err != nil {
	403	+	if _, err := c.verify(key); err != nil {
400	404		return nil, err
401	405		}
402	406		f, err := os.Open(c.archivePath(key))

 // download it when it does not (a miss: hit is false). Concurrent calls for the
 // same key share one download; the others report a hit once it is in place. The
 // entry is pinned for PinFor.
-func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool, err error) {
+func (c *Cache) Ensure(ctx context.Context, key string, fetch Fetch) (hit bool, verify time.Duration, err error) {
 	if !validKey(key) {
-		return false, ErrNotFound
+		return false, verify, ErrNotFound
 	}
 	for {
-		if c.verify(key) == nil {
+		duration, err := c.verify(key)
+		verify += duration
+		if err == nil {
 			c.touch(key, true)
-			return true, nil
+			return true, verify, nil
 		}
 		c.mu.Lock()
 		if f, ok := c.flights[key]; ok {
 			select {
 			case <-f.done:
 			case <-ctx.Done():
-				return false, ctx.Err()
+				return false, verify, ctx.Err()
 			}
 			if f.err != nil {
-				return false, f.err
+				return false, verify, f.err
 			}
 			continue
 		}
 		c.mu.Unlock()
 		close(f.done)
 		if f.err != nil {
-			return false, f.err
+			return false, verify, f.err
 		}
 		c.touch(key, true)
-		return false, nil
+		return false, verify, nil
 	}
 }
 // verify re-hashes the archive of key against its sum. Any mismatch (or a
 // missing file) drops the entry and returns ErrNotFound.
-func (c *Cache) verify(key string) error {
+func (c *Cache) verify(key string) (duration time.Duration, err error) {
+	start := time.Now()
+	defer func() { duration = time.Since(start) }()
 	sb, err := os.ReadFile(c.sumPath(key))
 	if err != nil {
 		c.drop(key)
-		return ErrNotFound
+		return 0, ErrNotFound
 	}
 	want, sizeS, _ := strings.Cut(strings.TrimSpace(string(sb)), " ")
 	size, perr := strconv.ParseInt(sizeS, 10, 64)
 			_ = f.Close()
 		}
 		c.drop(key)
-		return ErrNotFound
+		return 0, ErrNotFound
 	}
 	defer func() { _ = f.Close() }()
 	h := sha256.New()
 	if err != nil || n != size || hex.EncodeToString(h.Sum(nil)) != want {
 		c.log.Warn().Str("key", key).Msg("action archive failed its integrity check; dropped")
 		c.drop(key)
-		return ErrNotFound
+		return 0, ErrNotFound
 	}
-	return nil
+	return 0, nil
 }
 func (c *Cache) drop(key string) {
 	if !validKey(key) {
 		return nil, ErrNotFound
 	}
-	if err := c.verify(key); err != nil {
+	if _, err := c.verify(key); err != nil {
 		return nil, err
 	}
 	f, err := os.Open(c.archivePath(key))

M internal/actionscache/cache_test.go +17 -17


@@ -55,10 +55,10 @@ func TestHitMiss(t *testing.T) {
55	55		k := keyOf(t, 0)
56	56		var fetches int
57	57		f := func(ctx context.Context, w io.Writer) error { fetches++; return body("archive")(ctx, w) }
58		-	if hit, err := c.Ensure(context.Background(), k, f); err != nil \|\| hit {
	58	+	if hit, _, err := c.Ensure(context.Background(), k, f); err != nil \|\| hit {
59	59		t.Fatalf("first: hit=%v err=%v", hit, err)
60	60		}
61		-	if hit, err := c.Ensure(context.Background(), k, f); err != nil \|\| !hit {
	61	+	if hit, verify, err := c.Ensure(context.Background(), k, f); err != nil \|\| !hit \|\| verify <= 0 {
62	62		t.Fatalf("second: hit=%v err=%v", hit, err)
63	63		}
64	64		if fetches != 1 \|\| read(t, c, k) != "archive" {

@@ -69,7 +69,7 @@ func TestHitMiss(t *testing.T) {
69	69		if err != nil {
70	70		t.Fatal(err)
71	71		}
72		-	if hit, _ := c2.Ensure(context.Background(), k, f); !hit \|\| fetches != 1 {
	72	+	if hit, _, _ := c2.Ensure(context.Background(), k, f); !hit \|\| fetches != 1 {
73	73		t.Fatalf("restart: hit=%v fetches=%d", hit, fetches)
74	74		}
75	75		}

@@ -78,7 +78,7 @@ func TestFailedFetchLeavesNothing(t *testing.T) {
78	78		c, _ := newCache(t, 1<<20)
79	79		k := keyOf(t, 0)
80	80		boom := errors.New("429")
81		-	_, err := c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error { _, _ = io.WriteString(w, "part"); return boom })
	81	+	_, _, err := c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error { _, _ = io.WriteString(w, "part"); return boom })
82	82		if !errors.Is(err, boom) {
83	83		t.Fatal(err)
84	84		}

@@ -107,7 +107,7 @@ func TestConcurrentSingleFlight(t *testing.T) {
107	107		wg.Add(1)
108	108		go func() {
109	109		defer wg.Done()
110		-	hit, err := c.Ensure(context.Background(), k, f)
	110	+	hit, _, err := c.Ensure(context.Background(), k, f)
111	111		if err != nil {
112	112		t.Error(err)
113	113		}

@@ -130,7 +130,7 @@ func TestConcurrentSingleFlight(t *testing.T) {
130	130		func TestCorruptEntryIsDroppedAndRefetched(t *testing.T) {
131	131		c, _ := newCache(t, 1<<20)
132	132		k := keyOf(t, 0)
133		-	if _, err := c.Ensure(context.Background(), k, body("good bytes")); err != nil {
	133	+	if _, _, err := c.Ensure(context.Background(), k, body("good bytes")); err != nil {
134	134		t.Fatal(err)
135	135		}
136	136		// Same size, other content: only the hash can tell.

@@ -143,7 +143,7 @@ func TestCorruptEntryIsDroppedAndRefetched(t *testing.T) {
143	143		if c.Size() != 0 {
144	144		t.Errorf("size %d after the drop", c.Size())
145	145		}
146		-	hit, err := c.Ensure(context.Background(), k, body("good bytes"))
	146	+	hit, _, err := c.Ensure(context.Background(), k, body("good bytes"))
147	147		if err != nil \|\| hit {
148	148		t.Fatalf("hit=%v err=%v", hit, err)
149	149		}

@@ -165,17 +165,17 @@ func TestLRUEviction(t *testing.T) {
165	165		step := func() { *now = now.Add(time.Hour + PinFor) } // past every pin
166	166		a, b, d := keyOf(t, 0), keyOf(t, 1), keyOf(t, 2)
167	167		for _, k := range []string{a, b} {
168		-	if _, err := c.Ensure(ctx, k, body(strings.Repeat("x", 10))); err != nil {
	168	+	if _, _, err := c.Ensure(ctx, k, body(strings.Repeat("x", 10))); err != nil {
169	169		t.Fatal(err)
170	170		}
171	171		step()
172	172		}
173	173		// Use a again: b is now the least recently used.
174		-	if hit, _ := c.Ensure(ctx, a, body("unused")); !hit {
	174	+	if hit, _, _ := c.Ensure(ctx, a, body("unused")); !hit {
175	175		t.Fatal("a should hit")
176	176		}
177	177		step()
178		-	if _, err := c.Ensure(ctx, d, body(strings.Repeat("y", 10))); err != nil {
	178	+	if _, _, err := c.Ensure(ctx, d, body(strings.Repeat("y", 10))); err != nil {
179	179		t.Fatal(err)
180	180		}
181	181		if _, err := c.Open(b); !errors.Is(err, ErrNotFound) {

@@ -197,10 +197,10 @@ func TestPinnedEntryIsNotEvicted(t *testing.T) {
197	197		c, _ := newCache(t, 15)
198	198		ctx := context.Background()
199	199		a, b := keyOf(t, 0), keyOf(t, 1)
200		-	if _, err := c.Ensure(ctx, a, body(strings.Repeat("x", 10))); err != nil {
	200	+	if _, _, err := c.Ensure(ctx, a, body(strings.Repeat("x", 10))); err != nil {
201	201		t.Fatal(err)
202	202		}
203		-	if _, err := c.Ensure(ctx, b, body(strings.Repeat("y", 10))); !errors.Is(err, ErrTooLarge) {
	203	+	if _, _, err := c.Ensure(ctx, b, body(strings.Repeat("y", 10))); !errors.Is(err, ErrTooLarge) {
204	204		t.Fatalf("got %v", err)
205	205		}
206	206		if _, err := c.Open(a); err != nil {

@@ -257,7 +257,7 @@ func TestConcurrentDownloadsStayUnderTheCap(t *testing.T) {
257	257		go func() {
258	258		defer wg.Done()
259	259		k := keyOf(t, i)
260		-	_, _ = c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error {
	260	+	_, _, _ = c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error {
261	261		for range 6 { // 6 x 10 bytes, in pieces
262	262		if _, err := w.Write([]byte(strings.Repeat("z", 10))); err != nil {
263	263		return err

@@ -307,7 +307,7 @@ func TestConcurrentDownloadsStayUnderTheCap(t *testing.T) {
307	307		func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
308	308		c, _ := newCache(t, 50)
309	309		seen := int64(-1)
310		-	_, err := c.Ensure(context.Background(), keyOf(t, 0), func(_ context.Context, w io.Writer) error {
	310	+	_, _, err := c.Ensure(context.Background(), keyOf(t, 0), func(_ context.Context, w io.Writer) error {
311	311		_, _ = io.WriteString(w, strings.Repeat("a", 30))
312	312		c.mu.Lock()
313	313		seen = c.pending

@@ -318,7 +318,7 @@ func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
318	318		t.Fatalf("err=%v pending during=%d", err, seen)
319	319		}
320	320		// Refused midway for size: the part already written is released too.
321		-	_, err = c.Ensure(context.Background(), keyOf(t, 1), body(strings.Repeat("b", 60)))
	321	+	_, _, err = c.Ensure(context.Background(), keyOf(t, 1), body(strings.Repeat("b", 60)))
322	322		if !errors.Is(err, ErrTooLarge) {
323	323		t.Fatalf("got %v", err)
324	324		}

@@ -326,7 +326,7 @@ func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
326	326		t.Fatalf("pending=%d size=%d disk=%d", c.pending, c.Size(), diskUse(t, c))
327	327		}
328	328		// The size is what was written, whatever the server announced.
329		-	if _, err := c.Ensure(context.Background(), keyOf(t, 2), body(strings.Repeat("c", 50))); err != nil {
	329	+	if _, _, err := c.Ensure(context.Background(), keyOf(t, 2), body(strings.Repeat("c", 50))); err != nil {
330	330		t.Fatal(err)
331	331		}
332	332		if c.Size() != 50 {

@@ -336,7 +336,7 @@ func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
336	336
337	337		func TestTooLarge(t *testing.T) {
338	338		c, _ := newCache(t, 10)
339		-	_, err := c.Ensure(context.Background(), keyOf(t, 0), body(strings.Repeat("x", 11)))
	339	+	_, _, err := c.Ensure(context.Background(), keyOf(t, 0), body(strings.Repeat("x", 11)))
340	340		if !errors.Is(err, ErrTooLarge) {
341	341		t.Fatalf("got %v", err)
342	342		}


@@ -55,10 +55,10 @@ func TestHitMiss(t *testing.T) {
55		k := keyOf(t, 0)	55		k := keyOf(t, 0)
56		var fetches int	56		var fetches int
57		f := func(ctx context.Context, w io.Writer) error { fetches++; return body("archive")(ctx, w) }	57		f := func(ctx context.Context, w io.Writer) error { fetches++; return body("archive")(ctx, w) }
58	-	if hit, err := c.Ensure(context.Background(), k, f); err != nil \|\| hit {	58	+	if hit, _, err := c.Ensure(context.Background(), k, f); err != nil \|\| hit {
59		t.Fatalf("first: hit=%v err=%v", hit, err)	59		t.Fatalf("first: hit=%v err=%v", hit, err)
60		}	60		}
61	-	if hit, err := c.Ensure(context.Background(), k, f); err != nil \|\| !hit {	61	+	if hit, verify, err := c.Ensure(context.Background(), k, f); err != nil \|\| !hit \|\| verify <= 0 {
62		t.Fatalf("second: hit=%v err=%v", hit, err)	62		t.Fatalf("second: hit=%v err=%v", hit, err)
63		}	63		}
64		if fetches != 1 \|\| read(t, c, k) != "archive" {	64		if fetches != 1 \|\| read(t, c, k) != "archive" {

@@ -69,7 +69,7 @@ func TestHitMiss(t *testing.T) {
69		if err != nil {	69		if err != nil {
70		t.Fatal(err)	70		t.Fatal(err)
71		}	71		}
72	-	if hit, _ := c2.Ensure(context.Background(), k, f); !hit \|\| fetches != 1 {	72	+	if hit, _, _ := c2.Ensure(context.Background(), k, f); !hit \|\| fetches != 1 {
73		t.Fatalf("restart: hit=%v fetches=%d", hit, fetches)	73		t.Fatalf("restart: hit=%v fetches=%d", hit, fetches)
74		}	74		}
75		}	75		}

@@ -78,7 +78,7 @@ func TestFailedFetchLeavesNothing(t *testing.T) {
78		c, _ := newCache(t, 1<<20)	78		c, _ := newCache(t, 1<<20)
79		k := keyOf(t, 0)	79		k := keyOf(t, 0)
80		boom := errors.New("429")	80		boom := errors.New("429")
81	-	_, err := c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error { _, _ = io.WriteString(w, "part"); return boom })	81	+	_, _, err := c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error { _, _ = io.WriteString(w, "part"); return boom })
82		if !errors.Is(err, boom) {	82		if !errors.Is(err, boom) {
83		t.Fatal(err)	83		t.Fatal(err)
84		}	84		}

@@ -107,7 +107,7 @@ func TestConcurrentSingleFlight(t *testing.T) {
107		wg.Add(1)	107		wg.Add(1)
108		go func() {	108		go func() {
109		defer wg.Done()	109		defer wg.Done()
110	-	hit, err := c.Ensure(context.Background(), k, f)	110	+	hit, _, err := c.Ensure(context.Background(), k, f)
111		if err != nil {	111		if err != nil {
112		t.Error(err)	112		t.Error(err)
113		}	113		}

@@ -130,7 +130,7 @@ func TestConcurrentSingleFlight(t *testing.T) {
130		func TestCorruptEntryIsDroppedAndRefetched(t *testing.T) {	130		func TestCorruptEntryIsDroppedAndRefetched(t *testing.T) {
131		c, _ := newCache(t, 1<<20)	131		c, _ := newCache(t, 1<<20)
132		k := keyOf(t, 0)	132		k := keyOf(t, 0)
133	-	if _, err := c.Ensure(context.Background(), k, body("good bytes")); err != nil {	133	+	if _, _, err := c.Ensure(context.Background(), k, body("good bytes")); err != nil {
134		t.Fatal(err)	134		t.Fatal(err)
135		}	135		}
136		// Same size, other content: only the hash can tell.	136		// Same size, other content: only the hash can tell.

@@ -143,7 +143,7 @@ func TestCorruptEntryIsDroppedAndRefetched(t *testing.T) {
143		if c.Size() != 0 {	143		if c.Size() != 0 {
144		t.Errorf("size %d after the drop", c.Size())	144		t.Errorf("size %d after the drop", c.Size())
145		}	145		}
146	-	hit, err := c.Ensure(context.Background(), k, body("good bytes"))	146	+	hit, _, err := c.Ensure(context.Background(), k, body("good bytes"))
147		if err != nil \|\| hit {	147		if err != nil \|\| hit {
148		t.Fatalf("hit=%v err=%v", hit, err)	148		t.Fatalf("hit=%v err=%v", hit, err)
149		}	149		}

@@ -165,17 +165,17 @@ func TestLRUEviction(t *testing.T) {
165		step := func() { *now = now.Add(time.Hour + PinFor) } // past every pin	165		step := func() { *now = now.Add(time.Hour + PinFor) } // past every pin
166		a, b, d := keyOf(t, 0), keyOf(t, 1), keyOf(t, 2)	166		a, b, d := keyOf(t, 0), keyOf(t, 1), keyOf(t, 2)
167		for _, k := range []string{a, b} {	167		for _, k := range []string{a, b} {
168	-	if _, err := c.Ensure(ctx, k, body(strings.Repeat("x", 10))); err != nil {	168	+	if _, _, err := c.Ensure(ctx, k, body(strings.Repeat("x", 10))); err != nil {
169		t.Fatal(err)	169		t.Fatal(err)
170		}	170		}
171		step()	171		step()
172		}	172		}
173		// Use a again: b is now the least recently used.	173		// Use a again: b is now the least recently used.
174	-	if hit, _ := c.Ensure(ctx, a, body("unused")); !hit {	174	+	if hit, _, _ := c.Ensure(ctx, a, body("unused")); !hit {
175		t.Fatal("a should hit")	175		t.Fatal("a should hit")
176		}	176		}
177		step()	177		step()
178	-	if _, err := c.Ensure(ctx, d, body(strings.Repeat("y", 10))); err != nil {	178	+	if _, _, err := c.Ensure(ctx, d, body(strings.Repeat("y", 10))); err != nil {
179		t.Fatal(err)	179		t.Fatal(err)
180		}	180		}
181		if _, err := c.Open(b); !errors.Is(err, ErrNotFound) {	181		if _, err := c.Open(b); !errors.Is(err, ErrNotFound) {

@@ -197,10 +197,10 @@ func TestPinnedEntryIsNotEvicted(t *testing.T) {
197		c, _ := newCache(t, 15)	197		c, _ := newCache(t, 15)
198		ctx := context.Background()	198		ctx := context.Background()
199		a, b := keyOf(t, 0), keyOf(t, 1)	199		a, b := keyOf(t, 0), keyOf(t, 1)
200	-	if _, err := c.Ensure(ctx, a, body(strings.Repeat("x", 10))); err != nil {	200	+	if _, _, err := c.Ensure(ctx, a, body(strings.Repeat("x", 10))); err != nil {
201		t.Fatal(err)	201		t.Fatal(err)
202		}	202		}
203	-	if _, err := c.Ensure(ctx, b, body(strings.Repeat("y", 10))); !errors.Is(err, ErrTooLarge) {	203	+	if _, _, err := c.Ensure(ctx, b, body(strings.Repeat("y", 10))); !errors.Is(err, ErrTooLarge) {
204		t.Fatalf("got %v", err)	204		t.Fatalf("got %v", err)
205		}	205		}
206		if _, err := c.Open(a); err != nil {	206		if _, err := c.Open(a); err != nil {

@@ -257,7 +257,7 @@ func TestConcurrentDownloadsStayUnderTheCap(t *testing.T) {
257		go func() {	257		go func() {
258		defer wg.Done()	258		defer wg.Done()
259		k := keyOf(t, i)	259		k := keyOf(t, i)
260	-	_, _ = c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error {	260	+	_, _, _ = c.Ensure(context.Background(), k, func(_ context.Context, w io.Writer) error {
261		for range 6 { // 6 x 10 bytes, in pieces	261		for range 6 { // 6 x 10 bytes, in pieces
262		if _, err := w.Write([]byte(strings.Repeat("z", 10))); err != nil {	262		if _, err := w.Write([]byte(strings.Repeat("z", 10))); err != nil {
263		return err	263		return err

@@ -307,7 +307,7 @@ func TestConcurrentDownloadsStayUnderTheCap(t *testing.T) {
307		func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {	307		func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
308		c, _ := newCache(t, 50)	308		c, _ := newCache(t, 50)
309		seen := int64(-1)	309		seen := int64(-1)
310	-	_, err := c.Ensure(context.Background(), keyOf(t, 0), func(_ context.Context, w io.Writer) error {	310	+	_, _, err := c.Ensure(context.Background(), keyOf(t, 0), func(_ context.Context, w io.Writer) error {
311		_, _ = io.WriteString(w, strings.Repeat("a", 30))	311		_, _ = io.WriteString(w, strings.Repeat("a", 30))
312		c.mu.Lock()	312		c.mu.Lock()
313		seen = c.pending	313		seen = c.pending

@@ -318,7 +318,7 @@ func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
318		t.Fatalf("err=%v pending during=%d", err, seen)	318		t.Fatalf("err=%v pending during=%d", err, seen)
319		}	319		}
320		// Refused midway for size: the part already written is released too.	320		// Refused midway for size: the part already written is released too.
321	-	_, err = c.Ensure(context.Background(), keyOf(t, 1), body(strings.Repeat("b", 60)))	321	+	_, _, err = c.Ensure(context.Background(), keyOf(t, 1), body(strings.Repeat("b", 60)))
322		if !errors.Is(err, ErrTooLarge) {	322		if !errors.Is(err, ErrTooLarge) {
323		t.Fatalf("got %v", err)	323		t.Fatalf("got %v", err)
324		}	324		}

@@ -326,7 +326,7 @@ func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
326		t.Fatalf("pending=%d size=%d disk=%d", c.pending, c.Size(), diskUse(t, c))	326		t.Fatalf("pending=%d size=%d disk=%d", c.pending, c.Size(), diskUse(t, c))
327		}	327		}
328		// The size is what was written, whatever the server announced.	328		// The size is what was written, whatever the server announced.
329	-	if _, err := c.Ensure(context.Background(), keyOf(t, 2), body(strings.Repeat("c", 50))); err != nil {	329	+	if _, _, err := c.Ensure(context.Background(), keyOf(t, 2), body(strings.Repeat("c", 50))); err != nil {
330		t.Fatal(err)	330		t.Fatal(err)
331		}	331		}
332		if c.Size() != 50 {	332		if c.Size() != 50 {

@@ -336,7 +336,7 @@ func TestTemporaryFilesAreCountedAndCleaned(t *testing.T) {
336			336
337		func TestTooLarge(t *testing.T) {	337		func TestTooLarge(t *testing.T) {
338		c, _ := newCache(t, 10)	338		c, _ := newCache(t, 10)
339	-	_, err := c.Ensure(context.Background(), keyOf(t, 0), body(strings.Repeat("x", 11)))	339	+	_, _, err := c.Ensure(context.Background(), keyOf(t, 0), body(strings.Repeat("x", 11)))
340		if !errors.Is(err, ErrTooLarge) {	340		if !errors.Is(err, ErrTooLarge) {
341		t.Fatalf("got %v", err)	341		t.Fatalf("got %v", err)
342		}	342		}

M internal/cachesvc/archives_test.go +1 -1


@@ -24,7 +24,7 @@ func archiveRig(t testing.T) (rig, *actionscache.Cache, string) {
24	24		}
25	25		r := newRigWith(t, Config{Max: 1 << 20, MinCharge: 1, Archives: ac})
26	26		key, _ := actionscache.Key("https://github.com", "o/r", strings.Repeat("a", 40))
27		-	if _, err := ac.Ensure(context.Background(), key, func(_ context.Context, w io.Writer) error {
	27	+	if _, _, err := ac.Ensure(context.Background(), key, func(_ context.Context, w io.Writer) error {
28	28		_, err := io.WriteString(w, "tarball")
29	29		return err
30	30		}); err != nil {


@@ -24,7 +24,7 @@ func archiveRig(t testing.T) (rig, *actionscache.Cache, string) {
24		}	24		}
25		r := newRigWith(t, Config{Max: 1 << 20, MinCharge: 1, Archives: ac})	25		r := newRigWith(t, Config{Max: 1 << 20, MinCharge: 1, Archives: ac})
26		key, _ := actionscache.Key("https://github.com", "o/r", strings.Repeat("a", 40))	26		key, _ := actionscache.Key("https://github.com", "o/r", strings.Repeat("a", 40))
27	-	if _, err := ac.Ensure(context.Background(), key, func(_ context.Context, w io.Writer) error {	27	+	if _, _, err := ac.Ensure(context.Background(), key, func(_ context.Context, w io.Writer) error {
28		_, err := io.WriteString(w, "tarball")	28		_, err := io.WriteString(w, "tarball")
29		return err	29		return err
30		}); err != nil {	30		}); err != nil {

A internal/e2e/timing_test.go +81 -0

@@ -0,0 +1,81 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package e2e
	4	+
	5	+	import (
	6	+	"context"
	7	+	"encoding/json"
	8	+	"net/http"
	9	+	"sync"
	10	+	"testing"
	11	+	"time"
	12	+
	13	+	ermite "bnema.dev/ermite-api/gen/ermite"
	14	+	"bnema.dev/ermite-api/gen/ermite/ermiteconnect"
	15	+	"bnema.dev/ermite-runner/internal/host"
	16	+	"bnema.dev/ermite-runner/internal/host/hosttest"
	17	+	"github.com/bnema/zerowrap"
	18	+	)
	19	+
	20	+	type timingWriter struct {
	21	+	mu sync.Mutex
	22	+	lines [][]byte
	23	+	}
	24	+
	25	+	func (w *timingWriter) Write(p []byte) (int, error) {
	26	+	w.mu.Lock()
	27	+	defer w.mu.Unlock()
	28	+	w.lines = append(w.lines, append([]byte(nil), p...))
	29	+	return len(p), nil
	30	+	}
	31	+
	32	+	func TestJobTiming(t *testing.T) {
	33	+	image := needE2E(t)
	34	+	drv := newDriver(t, image)
	35	+	srv := hosttest.New()
	36	+	defer srv.Close()
	37	+	srv.Queue(&ermite.Job{JobId: "timing", RunId: 1, Attempt: 1, JobToken: "ermitejob_timing", WorkflowPath: ".github/workflows/ci.yml", WorkflowYaml: "name: timing\non: push\njobs:\n main:\n runs-on: ubuntu-latest\n steps:\n - run: echo timing\n", JobKey: "main", Matrix: "{}", Contexts: chainContexts("main"), Repo: "hello", TimeoutMinutes: 2})
	38	+	r := &host.Runner{
	39	+	Cfg: host.Config{URL: srv.URL, Name: "timing", Capacity: 1, Version: "test"}, Driver: drv,
	40	+	Poll: host.NewClient(srv.URL, hosttest.RunnerToken, http.DefaultTransport),
	41	+	Job: func(tok string) ermiteconnect.RunnerServiceClient {
	42	+	return host.NewClient(srv.URL, tok, http.DefaultTransport)
	43	+	},
	44	+	Timing: host.Timing{LogFlush: 20 * time.Millisecond, NoJobPause: 100 * time.Millisecond},
	45	+	}
	46	+	var logs timingWriter
	47	+	ctx, cancel := context.WithCancel(zerowrap.WithCtx(context.Background(), zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &logs})))
	48	+	done := make(chan error, 1)
	49	+	go func() { done <- r.Run(ctx) }()
	50	+	select {
	51	+	case <-srv.Done():
	52	+	case <-time.After(3 * time.Minute):
	53	+	cancel()
	54	+	t.Fatal("job did not complete")
	55	+	}
	56	+	cancel()
	57	+	select {
	58	+	case err := <-done:
	59	+	if err != nil {
	60	+	t.Fatal(err)
	61	+	}
	62	+	case <-time.After(time.Minute):
	63	+	t.Fatal("runner did not stop")
	64	+	}
	65	+	logs.mu.Lock()
	66	+	defer logs.mu.Unlock()
	67	+	for _, line := range logs.lines {
	68	+	var fields map[string]any
	69	+	if json.Unmarshal(line, &fields) != nil \|\| fields["message"] != "job finished" {
	70	+	continue
	71	+	}
	72	+	for _, key := range []string{"sandbox_ms", "guest_dockerd_ms"} {
	73	+	value, ok := fields[key].(float64)
	74	+	if !ok \|\| value < 0 {
	75	+	t.Errorf("%s missing or negative: %v", key, fields)
	76	+	}
	77	+	}
	78	+	return
	79	+	}
	80	+	t.Fatal("no job finished log")
	81	+	}

@@ -0,0 +1,81 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package e2e
	4	+
	5	+	import (
	6	+	"context"
	7	+	"encoding/json"
	8	+	"net/http"
	9	+	"sync"
	10	+	"testing"
	11	+	"time"
	12	+
	13	+	ermite "bnema.dev/ermite-api/gen/ermite"
	14	+	"bnema.dev/ermite-api/gen/ermite/ermiteconnect"
	15	+	"bnema.dev/ermite-runner/internal/host"
	16	+	"bnema.dev/ermite-runner/internal/host/hosttest"
	17	+	"github.com/bnema/zerowrap"
	18	+	)
	19	+
	20	+	type timingWriter struct {
	21	+	mu sync.Mutex
	22	+	lines [][]byte
	23	+	}
	24	+
	25	+	func (w *timingWriter) Write(p []byte) (int, error) {
	26	+	w.mu.Lock()
	27	+	defer w.mu.Unlock()
	28	+	w.lines = append(w.lines, append([]byte(nil), p...))
	29	+	return len(p), nil
	30	+	}
	31	+
	32	+	func TestJobTiming(t *testing.T) {
	33	+	image := needE2E(t)
	34	+	drv := newDriver(t, image)
	35	+	srv := hosttest.New()
	36	+	defer srv.Close()
	37	+	srv.Queue(&ermite.Job{JobId: "timing", RunId: 1, Attempt: 1, JobToken: "ermitejob_timing", WorkflowPath: ".github/workflows/ci.yml", WorkflowYaml: "name: timing\non: push\njobs:\n main:\n runs-on: ubuntu-latest\n steps:\n - run: echo timing\n", JobKey: "main", Matrix: "{}", Contexts: chainContexts("main"), Repo: "hello", TimeoutMinutes: 2})
	38	+	r := &host.Runner{
	39	+	Cfg: host.Config{URL: srv.URL, Name: "timing", Capacity: 1, Version: "test"}, Driver: drv,
	40	+	Poll: host.NewClient(srv.URL, hosttest.RunnerToken, http.DefaultTransport),
	41	+	Job: func(tok string) ermiteconnect.RunnerServiceClient {
	42	+	return host.NewClient(srv.URL, tok, http.DefaultTransport)
	43	+	},
	44	+	Timing: host.Timing{LogFlush: 20 * time.Millisecond, NoJobPause: 100 * time.Millisecond},
	45	+	}
	46	+	var logs timingWriter
	47	+	ctx, cancel := context.WithCancel(zerowrap.WithCtx(context.Background(), zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &logs})))
	48	+	done := make(chan error, 1)
	49	+	go func() { done <- r.Run(ctx) }()
	50	+	select {
	51	+	case <-srv.Done():
	52	+	case <-time.After(3 * time.Minute):
	53	+	cancel()
	54	+	t.Fatal("job did not complete")
	55	+	}
	56	+	cancel()
	57	+	select {
	58	+	case err := <-done:
	59	+	if err != nil {
	60	+	t.Fatal(err)
	61	+	}
	62	+	case <-time.After(time.Minute):
	63	+	t.Fatal("runner did not stop")
	64	+	}
	65	+	logs.mu.Lock()
	66	+	defer logs.mu.Unlock()
	67	+	for _, line := range logs.lines {
	68	+	var fields map[string]any
	69	+	if json.Unmarshal(line, &fields) != nil \|\| fields["message"] != "job finished" {
	70	+	continue
	71	+	}
	72	+	for _, key := range []string{"sandbox_ms", "guest_dockerd_ms"} {
	73	+	value, ok := fields[key].(float64)
	74	+	if !ok \|\| value < 0 {
	75	+	t.Errorf("%s missing or negative: %v", key, fields)
	76	+	}
	77	+	}
	78	+	return
	79	+	}
	80	+	t.Fatal("no job finished log")
	81	+	}

M internal/execstream/exec.proto +1 -0


@@ -48,6 +48,7 @@ message Hello {
48	48		string version = 1; // runner version of the executor
49	49		string sandbox = 2; // "vm" or "container"
50	50		string hostname = 3;
	51	+	map<string, int64> boot_ms = 4;
51	52		}
52	53
53	54		// Run asks the executor to run a script or a job. Without job it is the stub


@@ -48,6 +48,7 @@ message Hello {
48	string version = 1; // runner version of the executor	48		string version = 1; // runner version of the executor
49	string sandbox = 2; // "vm" or "container"	49		string sandbox = 2; // "vm" or "container"
50	string hostname = 3;	50		string hostname = 3;
		51	+	map<string, int64> boot_ms = 4;
51	}	52		}
52		53
53	// Run asks the executor to run a script or a job. Without job it is the stub	54		// Run asks the executor to run a script or a job. Without job it is the stub

M internal/execstream/execpb/exec.pb.go +39 -25 generated file: collapsed

load diff

M internal/guest/exec.go +2 -1


@@ -33,6 +33,7 @@ const (
33	33
34	34		// ExecConfig configures the executor.
35	35		type ExecConfig struct {
	36	+	BootMs map[string]int64
36	37		Target Target
37	38		Sandbox string // "vm" or "container", reported in Hello
38	39		Version string

@@ -189,7 +190,7 @@ func serve(ctx context.Context, rw io.ReadWriteCloser, cfg ExecConfig) (int, err
189	190		conn := execstream.NewConn(rw)
190	191		host, _ := os.Hostname()
191	192		if err := conn.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{
192		-	Version: cfg.Version, Sandbox: cfg.Sandbox, Hostname: host,
	193	+	Version: cfg.Version, Sandbox: cfg.Sandbox, Hostname: host, BootMs: cfg.BootMs,
193	194		}}}); err != nil {
194	195		return 1, fmt.Errorf("send hello: %w", err)
195	196		}

 // ExecConfig configures the executor.
 type ExecConfig struct {
+	BootMs  map[string]int64
 	Target  Target
 	Sandbox string // "vm" or "container", reported in Hello
 	Version string
 	conn := execstream.NewConn(rw)
 	host, _ := os.Hostname()
 	if err := conn.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{
-		Version: cfg.Version, Sandbox: cfg.Sandbox, Hostname: host,
+		Version: cfg.Version, Sandbox: cfg.Sandbox, Hostname: host, BootMs: cfg.BootMs,
 	}}}); err != nil {
 		return 1, fmt.Errorf("send hello: %w", err)
 	}

M internal/guest/init.go +28 -2


@@ -11,6 +11,7 @@ import (
11	11		"net/http"
12	12		"os"
13	13		"os/signal"
	14	+	"strconv"
14	15		"strings"
15	16		"syscall"
16	17		"time"

@@ -25,6 +26,7 @@ import (
25	26		// replace the fields.
26	27		type InitConfig struct {
27	28		Version string
	29	+	bootMs map[string]int64
28	30		// Cmdline is the kernel command line; empty reads /proc/cmdline.
29	31		Cmdline string
30	32		// Getpid reports the process id; Init only acts as a VM's PID 1 when it is 1.

@@ -62,6 +64,8 @@ type InitConfig struct {
62	64		// (`ermite-runner exec`) as a child, reap orphans, stop dockerd, and finish by
63	65		// powering the VM off, or exiting with the executor's code in a container.
64	66		func Init(ctx context.Context, cfg InitConfig) int {
	67	+	entry := time.Now()
	68	+	cfg.bootMs = make(map[string]int64)
65	69		log := zerowrap.FromCtx(ctx)
66	70		// The kernel starts a VM's init with umask 0, which dockerd, the executor
67	71		// and every step would inherit: files and t.TempDir() directories would be

@@ -93,11 +97,20 @@ func Init(ctx context.Context, cfg InitConfig) int {
93	97		mode := string(sandbox.Container)
94	98		if inVM {
95	99		mode = string(sandbox.VM)
	100	+	if b, err := os.ReadFile("/proc/uptime"); err == nil {
	101	+	if fields := strings.Fields(string(b)); len(fields) > 0 {
	102	+	if seconds, err := strconv.ParseFloat(fields[0], 64); err == nil && seconds >= 0 {
	103	+	cfg.bootMs["kernel"] = max(0, int64(seconds*1000)-time.Since(entry).Milliseconds())
	104	+	}
	105	+	}
	106	+	}
	107	+	start := time.Now()
96	108		if err := setupVM(log, args); err != nil {
97	109		log.Error().Err(err).Msg("init: vm setup failed")
98	110		powerOff()
99	111		return 1
100	112		}
	113	+	cfg.bootMs["setup"] = time.Since(start).Milliseconds()
101	114		}
102	115		code := runPayload(ctx, cfg, mode, args)
103	116		if inVM {

@@ -136,6 +149,10 @@ func runPayload(ctx context.Context, cfg InitConfig, mode string, args map[strin
136	149		return 1
137	150		}
138	151
	152	+	if cfg.bootMs == nil {
	153	+	cfg.bootMs = make(map[string]int64)
	154	+	}
	155	+	var dockerStart time.Time
139	156		var dockerPid, containerdPid int
140	157		_, statErr := os.Stat("/usr/bin/dockerd")
141	158		if !cfg.SkipDocker && (statErr == nil \|\| cfg.DockerdArgs != nil) {

@@ -148,11 +165,19 @@ func runPayload(ctx context.Context, cfg InitConfig, mode string, args map[strin
148	165		// inherits it, then every `docker exec` (the steps of a job
149	166		// container): their files would be world-writable. Start containerd
150	167		// here with our umask instead, as systemd does on GitHub's runners.
151		-	if pid, ok := startContainerd(ctx, log); ok {
	168	+	start := time.Now()
	169	+	pid, ok := startContainerd(ctx, log)
	170	+	// A containerd that never came up still cost its wait: keep it in the
	171	+	// breakdown. A missing binary returns at once (0 ms) and is omitted.
	172	+	if ms := time.Since(start).Milliseconds(); ok \|\| ms > 0 {
	173	+	cfg.bootMs["containerd"] = ms
	174	+	}
	175	+	if ok {
152	176		containerdPid = pid
153	177		argv = append(argv, "--containerd", containerdSocket)
154	178		}
155	179		}
	180	+	dockerStart = time.Now()
156	181		pid, err := spawn(argv, nil)
157	182		if err != nil {
158	183		log.Error().Err(err).Msg("init: start dockerd")

@@ -186,6 +211,7 @@ func runPayload(ctx context.Context, cfg InitConfig, mode string, args map[strin
186	211		timeout = dockerReadyTimeout
187	212		}
188	213		err := waitDockerReady(ctx, log, sock, dockerPid, timeout, sigs)
	214	+	cfg.bootMs["dockerd"] = time.Since(dockerStart).Milliseconds()
189	215		var exited *dockerdExitError
190	216		var abort *abortBootError
191	217		switch {

@@ -198,7 +224,7 @@ func runPayload(ctx context.Context, cfg InitConfig, mode string, args map[strin
198	224		}
199	225		}
200	226
201		-	execEnv := append(os.Environ(), "ERMITE_CONNECT="+target, "ERMITE_SANDBOX="+mode, "ERMITE_VERSION="+cfg.Version)
	227	+	execEnv := append(os.Environ(), "ERMITE_CONNECT="+target, "ERMITE_SANDBOX="+mode, "ERMITE_VERSION="+cfg.Version, "ERMITE_BOOT_MS="+formatBootMs(cfg.bootMs))
202	228		execPid, err := spawn(cfg.ExecArgs, execEnv)
203	229		if err != nil {
204	230		log.Error().Err(err).Msg("init: start executor")

 	"net/http"
 	"os"
 	"os/signal"
+	"strconv"
 	"strings"
 	"syscall"
 	"time"
 // replace the fields.
 type InitConfig struct {
 	Version string
+	bootMs  map[string]int64
 	// Cmdline is the kernel command line; empty reads /proc/cmdline.
 	Cmdline string
 	// Getpid reports the process id; Init only acts as a VM's PID 1 when it is 1.
 // (`ermite-runner exec`) as a child, reap orphans, stop dockerd, and finish by
 // powering the VM off, or exiting with the executor's code in a container.
 func Init(ctx context.Context, cfg InitConfig) int {
+	entry := time.Now()
+	cfg.bootMs = make(map[string]int64)
 	log := zerowrap.FromCtx(ctx)
 	// The kernel starts a VM's init with umask 0, which dockerd, the executor
 	// and every step would inherit: files and t.TempDir() directories would be
 	mode := string(sandbox.Container)
 	if inVM {
 		mode = string(sandbox.VM)
+		if b, err := os.ReadFile("/proc/uptime"); err == nil {
+			if fields := strings.Fields(string(b)); len(fields) > 0 {
+				if seconds, err := strconv.ParseFloat(fields[0], 64); err == nil && seconds >= 0 {
+					cfg.bootMs["kernel"] = max(0, int64(seconds*1000)-time.Since(entry).Milliseconds())
+				}
+			}
+		}
+		start := time.Now()
 		if err := setupVM(log, args); err != nil {
 			log.Error().Err(err).Msg("init: vm setup failed")
 			powerOff()
 			return 1
 		}
+		cfg.bootMs["setup"] = time.Since(start).Milliseconds()
 	}
 	code := runPayload(ctx, cfg, mode, args)
 	if inVM {
 		return 1
 	}
+	if cfg.bootMs == nil {
+		cfg.bootMs = make(map[string]int64)
+	}
+	var dockerStart time.Time
 	var dockerPid, containerdPid int
 	_, statErr := os.Stat("/usr/bin/dockerd")
 	if !cfg.SkipDocker && (statErr == nil || cfg.DockerdArgs != nil) {
 			// inherits it, then every `docker exec` (the steps of a job
 			// container): their files would be world-writable. Start containerd
 			// here with our umask instead, as systemd does on GitHub's runners.
-			if pid, ok := startContainerd(ctx, log); ok {
+			start := time.Now()
+			pid, ok := startContainerd(ctx, log)
+			// A containerd that never came up still cost its wait: keep it in the
+			// breakdown. A missing binary returns at once (0 ms) and is omitted.
+			if ms := time.Since(start).Milliseconds(); ok || ms > 0 {
+				cfg.bootMs["containerd"] = ms
+			}
+			if ok {
 				containerdPid = pid
 				argv = append(argv, "--containerd", containerdSocket)
 			}
 		}
+		dockerStart = time.Now()
 		pid, err := spawn(argv, nil)
 		if err != nil {
 			log.Error().Err(err).Msg("init: start dockerd")
 			timeout = dockerReadyTimeout
 		}
 		err := waitDockerReady(ctx, log, sock, dockerPid, timeout, sigs)
+		cfg.bootMs["dockerd"] = time.Since(dockerStart).Milliseconds()
 		var exited *dockerdExitError
 		var abort *abortBootError
 		switch {
 		}
 	}
-	execEnv := append(os.Environ(), "ERMITE_CONNECT="+target, "ERMITE_SANDBOX="+mode, "ERMITE_VERSION="+cfg.Version)
+	execEnv := append(os.Environ(), "ERMITE_CONNECT="+target, "ERMITE_SANDBOX="+mode, "ERMITE_VERSION="+cfg.Version, "ERMITE_BOOT_MS="+formatBootMs(cfg.bootMs))
 	execPid, err := spawn(cfg.ExecArgs, execEnv)
 	if err != nil {
 		log.Error().Err(err).Msg("init: start executor")

A internal/guest/timing.go +38 -0

@@ -0,0 +1,38 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"sort"
	7	+	"strconv"
	8	+	"strings"
	9	+	)
	10	+
	11	+	func formatBootMs(ms map[string]int64) string {
	12	+	keys := make([]string, 0, len(ms))
	13	+	for k := range ms {
	14	+	keys = append(keys, k)
	15	+	}
	16	+	sort.Strings(keys)
	17	+	pairs := make([]string, 0, len(keys))
	18	+	for _, k := range keys {
	19	+	pairs = append(pairs, k+"="+strconv.FormatInt(ms[k], 10))
	20	+	}
	21	+	return strings.Join(pairs, ",")
	22	+	}
	23	+
	24	+	// ParseBootMs reads init's boot timing environment, ignoring malformed pairs.
	25	+	func ParseBootMs(value string) map[string]int64 {
	26	+	ms := make(map[string]int64)
	27	+	for _, pair := range strings.Split(value, ",") {
	28	+	key, value, ok := strings.Cut(pair, "=")
	29	+	if !ok \|\| key == "" {
	30	+	continue
	31	+	}
	32	+	n, err := strconv.ParseInt(value, 10, 64)
	33	+	if err == nil && n >= 0 {
	34	+	ms[key] = n
	35	+	}
	36	+	}
	37	+	return ms
	38	+	}

@@ -0,0 +1,38 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"sort"
	7	+	"strconv"
	8	+	"strings"
	9	+	)
	10	+
	11	+	func formatBootMs(ms map[string]int64) string {
	12	+	keys := make([]string, 0, len(ms))
	13	+	for k := range ms {
	14	+	keys = append(keys, k)
	15	+	}
	16	+	sort.Strings(keys)
	17	+	pairs := make([]string, 0, len(keys))
	18	+	for _, k := range keys {
	19	+	pairs = append(pairs, k+"="+strconv.FormatInt(ms[k], 10))
	20	+	}
	21	+	return strings.Join(pairs, ",")
	22	+	}
	23	+
	24	+	// ParseBootMs reads init's boot timing environment, ignoring malformed pairs.
	25	+	func ParseBootMs(value string) map[string]int64 {
	26	+	ms := make(map[string]int64)
	27	+	for _, pair := range strings.Split(value, ",") {
	28	+	key, value, ok := strings.Cut(pair, "=")
	29	+	if !ok \|\| key == "" {
	30	+	continue
	31	+	}
	32	+	n, err := strconv.ParseInt(value, 10, 64)
	33	+	if err == nil && n >= 0 {
	34	+	ms[key] = n
	35	+	}
	36	+	}
	37	+	return ms
	38	+	}

A internal/guest/timing_test.go +33 -0

@@ -0,0 +1,33 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"reflect"
	7	+	"testing"
	8	+	)
	9	+
	10	+	func TestBootMs(t *testing.T) {
	11	+	want := map[string]int64{"setup": 40, "dockerd": 2300, "kernel": 812}
	12	+	encoded := formatBootMs(want)
	13	+	if encoded != "dockerd=2300,kernel=812,setup=40" {
	14	+	t.Fatal(encoded)
	15	+	}
	16	+	if got := ParseBootMs(encoded); !reflect.DeepEqual(got, want) {
	17	+	t.Fatal(got)
	18	+	}
	19	+	if got := ParseBootMs("a=x,b,=3,c=-1,d=5"); !reflect.DeepEqual(got, map[string]int64{"d": 5}) {
	20	+	t.Fatal(got)
	21	+	}
	22	+	}
	23	+
	24	+	func TestHelloBootMs(t *testing.T) {
	25	+	want := map[string]int64{"dockerd": 23}
	26	+	_, _, _, hello, _, err := host(t, "true", 0, func(cfg *ExecConfig) { cfg.BootMs = want })
	27	+	if err != nil {
	28	+	t.Fatal(err)
	29	+	}
	30	+	if !reflect.DeepEqual(hello.BootMs, want) {
	31	+	t.Fatalf("Hello boot_ms = %v", hello.BootMs)
	32	+	}
	33	+	}

@@ -0,0 +1,33 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package guest
	4	+
	5	+	import (
	6	+	"reflect"
	7	+	"testing"
	8	+	)
	9	+
	10	+	func TestBootMs(t *testing.T) {
	11	+	want := map[string]int64{"setup": 40, "dockerd": 2300, "kernel": 812}
	12	+	encoded := formatBootMs(want)
	13	+	if encoded != "dockerd=2300,kernel=812,setup=40" {
	14	+	t.Fatal(encoded)
	15	+	}
	16	+	if got := ParseBootMs(encoded); !reflect.DeepEqual(got, want) {
	17	+	t.Fatal(got)
	18	+	}
	19	+	if got := ParseBootMs("a=x,b,=3,c=-1,d=5"); !reflect.DeepEqual(got, map[string]int64{"d": 5}) {
	20	+	t.Fatal(got)
	21	+	}
	22	+	}
	23	+
	24	+	func TestHelloBootMs(t *testing.T) {
	25	+	want := map[string]int64{"dockerd": 23}
	26	+	_, _, _, hello, _, err := host(t, "true", 0, func(cfg *ExecConfig) { cfg.BootMs = want })
	27	+	if err != nil {
	28	+	t.Fatal(err)
	29	+	}
	30	+	if !reflect.DeepEqual(hello.BootMs, want) {
	31	+	t.Fatalf("Hello boot_ms = %v", hello.BootMs)
	32	+	}
	33	+	}

M internal/host/archives.go +33 -3


@@ -54,9 +54,23 @@ func (j jobRun) cacheArchives(ctx context.Context, orig []ermite.ResolvedActio
54	54		if !ok {
55	55		continue
56	56		}
57		-	hit, err := rt.Archives.Ensure(ctx, key, func(ctx context.Context, w io.Writer) error {
58		-	return j.fetchArchive(ctx, a, origin, w)
	57	+	var fetchTime time.Duration
	58	+	var bytes int64
	59	+	hit, verify, err := rt.Archives.Ensure(ctx, key, func(ctx context.Context, w io.Writer) error {
	60	+	start := time.Now()
	61	+	cw := &archiveCountWriter{Writer: w}
	62	+	err := j.fetchArchive(ctx, a, origin, cw)
	63	+	fetchTime += time.Since(start)
	64	+	bytes += cw.n
	65	+	return err
59	66		})
	67	+	if !hit {
	68	+	j.mu.Lock()
	69	+	j.timeline.add("archive_miss_ms", fetchTime)
	70	+	j.timeline["archive_misses"]++
	71	+	j.timeline["archive_miss_bytes"] += bytes
	72	+	j.mu.Unlock()
	73	+	}
60	74		log := j.log.With().Str("action", a.NameWithOwner).Str("sha", a.ResolvedSha).Logger()
61	75		if err != nil {
62	76		log.Warn().Err(err).Msg("action archive not cached; the sandbox downloads it")

@@ -66,7 +80,11 @@ func (j jobRun) cacheArchives(ctx context.Context, orig []ermite.ResolvedActio
66	80		if u == "" {
67	81		continue
68	82		}
69		-	log.Info().Bool("hit", hit).Msg("action archive cache")
	83	+	event := log.Info().Bool("hit", hit).Int64("verify_ms", verify.Milliseconds())
	84	+	if !hit {
	85	+	event = event.Int64("fetch_ms", fetchTime.Milliseconds()).Int64("bytes", bytes)
	86	+	}
	87	+	event.Msg("action archive cache")
70	88		c.TarballUrl, c.Token, c.AuthOrigin = u, "", ""
71	89		}
72	90		}

@@ -102,3 +120,15 @@ func (j jobRun) fetchArchive(ctx context.Context, a ermite.ResolvedAction, ori
102	120		}
103	121		return err
104	122		}
	123	+
	124	+	// archiveCountWriter counts bytes accepted by the cache.
	125	+	type archiveCountWriter struct {
	126	+	io.Writer
	127	+	n int64
	128	+	}
	129	+
	130	+	func (w *archiveCountWriter) Write(p []byte) (int, error) {
	131	+	n, err := w.Writer.Write(p)
	132	+	w.n += int64(n)
	133	+	return n, err
	134	+	}


@@ -54,9 +54,23 @@ func (j jobRun) cacheArchives(ctx context.Context, orig []ermite.ResolvedActio
54		if !ok {	54		if !ok {
55		continue	55		continue
56		}	56		}
57	-	hit, err := rt.Archives.Ensure(ctx, key, func(ctx context.Context, w io.Writer) error {	57	+	var fetchTime time.Duration
58	-	return j.fetchArchive(ctx, a, origin, w)	58	+	var bytes int64
			59	+	hit, verify, err := rt.Archives.Ensure(ctx, key, func(ctx context.Context, w io.Writer) error {
			60	+	start := time.Now()
			61	+	cw := &archiveCountWriter{Writer: w}
			62	+	err := j.fetchArchive(ctx, a, origin, cw)
			63	+	fetchTime += time.Since(start)
			64	+	bytes += cw.n
			65	+	return err
59		})	66		})
			67	+	if !hit {
			68	+	j.mu.Lock()
			69	+	j.timeline.add("archive_miss_ms", fetchTime)
			70	+	j.timeline["archive_misses"]++
			71	+	j.timeline["archive_miss_bytes"] += bytes
			72	+	j.mu.Unlock()
			73	+	}
60		log := j.log.With().Str("action", a.NameWithOwner).Str("sha", a.ResolvedSha).Logger()	74		log := j.log.With().Str("action", a.NameWithOwner).Str("sha", a.ResolvedSha).Logger()
61		if err != nil {	75		if err != nil {
62		log.Warn().Err(err).Msg("action archive not cached; the sandbox downloads it")	76		log.Warn().Err(err).Msg("action archive not cached; the sandbox downloads it")

@@ -66,7 +80,11 @@ func (j jobRun) cacheArchives(ctx context.Context, orig []ermite.ResolvedActio
66		if u == "" {	80		if u == "" {
67		continue	81		continue
68		}	82		}
69	-	log.Info().Bool("hit", hit).Msg("action archive cache")	83	+	event := log.Info().Bool("hit", hit).Int64("verify_ms", verify.Milliseconds())
			84	+	if !hit {
			85	+	event = event.Int64("fetch_ms", fetchTime.Milliseconds()).Int64("bytes", bytes)
			86	+	}
			87	+	event.Msg("action archive cache")
70		c.TarballUrl, c.Token, c.AuthOrigin = u, "", ""	88		c.TarballUrl, c.Token, c.AuthOrigin = u, "", ""
71		}	89		}
72		}	90		}

@@ -102,3 +120,15 @@ func (j jobRun) fetchArchive(ctx context.Context, a ermite.ResolvedAction, ori
102		}	120		}
103		return err	121		return err
104		}	122		}
			123	+
			124	+	// archiveCountWriter counts bytes accepted by the cache.
			125	+	type archiveCountWriter struct {
			126	+	io.Writer
			127	+	n int64
			128	+	}
			129	+
			130	+	func (w *archiveCountWriter) Write(p []byte) (int, error) {
			131	+	n, err := w.Writer.Write(p)
			132	+	w.n += int64(n)
			133	+	return n, err
			134	+	}

M internal/host/archives_test.go +37 -0


@@ -3,7 +3,9 @@
3	3		package host
4	4
5	5		import (
	6	+	"bytes"
6	7		"context"
	8	+	"encoding/json"
7	9		"net/http"
8	10		"net/http/httptest"
9	11		"path/filepath"

@@ -145,3 +147,38 @@ func TestCacheArchivesFallsBack(t *testing.T) {
145	147		t.Errorf("cache off: %+v", c)
146	148		}
147	149		}
	150	+
	151	+	func TestArchiveTimingLogs(t *testing.T) {
	152	+	a := newArchiveRig(t)
	153	+	var logs bytes.Buffer
	154	+	j := a.job("timing")
	155	+	j.log = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &logs})
	156	+	for i := 0; i < 2; i++ {
	157	+	logs.Reset()
	158	+	o, c := a.action(strings.Repeat("a", 40))
	159	+	j.cacheArchives(context.Background(), []ermite.ResolvedAction{o}, []execpb.ResolvedAction{c})
	160	+	var fields map[string]any
	161	+	if err := json.Unmarshal(logs.Bytes(), &fields); err != nil {
	162	+	t.Fatal(err, logs.String())
	163	+	}
	164	+	if value, ok := fields["verify_ms"].(float64); !ok \|\| value < 0 {
	165	+	t.Fatal(fields)
	166	+	}
	167	+	if fields["hit"] != (i == 1) {
	168	+	t.Fatal(fields)
	169	+	}
	170	+	if i == 0 {
	171	+	if value, ok := fields["fetch_ms"].(float64); !ok \|\| value < 0 {
	172	+	t.Fatal(fields)
	173	+	}
	174	+	if value, ok := fields["bytes"].(float64); !ok \|\| value <= 0 {
	175	+	t.Fatal(fields)
	176	+	}
	177	+	} else if _, ok := fields["fetch_ms"]; ok {
	178	+	t.Fatal("hit has fetch_ms", fields)
	179	+	}
	180	+	}
	181	+	if j.timeline["archive_misses"] != 1 \|\| j.timeline["archive_miss_bytes"] <= 0 {
	182	+	t.Fatal(j.timeline)
	183	+	}
	184	+	}


@@ -3,7 +3,9 @@
3	package host	3		package host
4		4
5	import (	5		import (
		6	+	"bytes"
6	"context"	7		"context"
		8	+	"encoding/json"
7	"net/http"	9		"net/http"
8	"net/http/httptest"	10		"net/http/httptest"
9	"path/filepath"	11		"path/filepath"

@@ -145,3 +147,38 @@ func TestCacheArchivesFallsBack(t *testing.T) {
145	t.Errorf("cache off: %+v", c)	147		t.Errorf("cache off: %+v", c)
146	}	148		}
147	}	149		}
		150	+
		151	+	func TestArchiveTimingLogs(t *testing.T) {
		152	+	a := newArchiveRig(t)
		153	+	var logs bytes.Buffer
		154	+	j := a.job("timing")
		155	+	j.log = zerowrap.New(zerowrap.Config{Level: "info", Format: "json", Output: &logs})
		156	+	for i := 0; i < 2; i++ {
		157	+	logs.Reset()
		158	+	o, c := a.action(strings.Repeat("a", 40))
		159	+	j.cacheArchives(context.Background(), []ermite.ResolvedAction{o}, []execpb.ResolvedAction{c})
		160	+	var fields map[string]any
		161	+	if err := json.Unmarshal(logs.Bytes(), &fields); err != nil {
		162	+	t.Fatal(err, logs.String())
		163	+	}
		164	+	if value, ok := fields["verify_ms"].(float64); !ok \|\| value < 0 {
		165	+	t.Fatal(fields)
		166	+	}
		167	+	if fields["hit"] != (i == 1) {
		168	+	t.Fatal(fields)
		169	+	}
		170	+	if i == 0 {
		171	+	if value, ok := fields["fetch_ms"].(float64); !ok \|\| value < 0 {
		172	+	t.Fatal(fields)
		173	+	}
		174	+	if value, ok := fields["bytes"].(float64); !ok \|\| value <= 0 {
		175	+	t.Fatal(fields)
		176	+	}
		177	+	} else if _, ok := fields["fetch_ms"]; ok {
		178	+	t.Fatal("hit has fetch_ms", fields)
		179	+	}
		180	+	}
		181	+	if j.timeline["archive_misses"] != 1 \|\| j.timeline["archive_miss_bytes"] <= 0 {
		182	+	t.Fatal(j.timeline)
		183	+	}
		184	+	}

M internal/host/fake_test.go +3 -2


@@ -380,7 +380,8 @@ type fakeSandbox struct {
380	380		stoped bool
381	381		}
382	382
383		-	func (s *fakeSandbox) ID() string { return "er00000000" }
	383	+	func (s *fakeSandbox) ID() string { return "er00000000" }
	384	+	func (s *fakeSandbox) StartTimings() map[string]int64 { return map[string]int64{"socket_ms": 1} }
384	385		func (s *fakeSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (sandbox.Conn, error) {
385	386		d := s.d
386	387		d.mu.Lock()

@@ -409,7 +410,7 @@ func (s *fakeSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (sandbox.
409	410		go func() {
410	411		defer func() { _ = guest.Close() }()
411	412		c := execstream.NewConn(guest)
412		-	_ = c.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{Version: "test", Sandbox: "container"}}})
	413	+	_ = c.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{Version: "test", Sandbox: "container", BootMs: map[string]int64{"dockerd": 2}}}})
413	414		// NamedValue frames (secrets, variables) come before Run.
414	415		vals := &seenValues{secrets: map[string]string{}, vars: map[string]string{}}
415	416		var f *execpb.Frame

 	stoped bool
 }
-func (s *fakeSandbox) ID() string { return "er00000000" }
+func (s *fakeSandbox) ID() string                     { return "er00000000" }
+func (s *fakeSandbox) StartTimings() map[string]int64 { return map[string]int64{"socket_ms": 1} }
 func (s *fakeSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (sandbox.Conn, error) {
 	d := s.d
 	d.mu.Lock()
 	go func() {
 		defer func() { _ = guest.Close() }()
 		c := execstream.NewConn(guest)
-		_ = c.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{Version: "test", Sandbox: "container"}}})
+		_ = c.Send(&execpb.Frame{Body: &execpb.Frame_Hello{Hello: &execpb.Hello{Version: "test", Sandbox: "container", BootMs: map[string]int64{"dockerd": 2}}}})
 		// NamedValue frames (secrets, variables) come before Run.
 		vals := &seenValues{secrets: map[string]string{}, vars: map[string]string{}}
 		var f *execpb.Frame

M internal/host/job.go +31 -2


@@ -60,8 +60,9 @@ type jobRun struct {
60	60		cancelKind execpb.CancelKind // kind of the first cancel request
61	61		stopping bool // the runner is shutting down
62	62
63		-	mu sync.Mutex
64		-	steps map[int32]*ermite.StepUpdate
	63	+	timeline timeline
	64	+	mu sync.Mutex
	65	+	steps map[int32]*ermite.StepUpdate
65	66		// What the guest has told us, for the validation of the next frame: the
66	67		// guest is untrusted code, its step numbers and lines are checked before
67	68		// they reach the server (see violate).

@@ -494,6 +495,7 @@ func (j *jobRun) acknowledge(ctx context.Context, shutdown <-chan struct{}) bool
494	495		}
495	496		}()
496	497		if j.ack(ackCtx) {
	498	+	j.timeSet("ack_ms", time.Since(j.receivedAt))
497	499		return true
498	500		}
499	501		select {

@@ -627,7 +629,16 @@ func (j jobRun) execute(ctx context.Context, rt Runner, stopHard <-chan struct
627	629		j.features = j.loadFeatures(ctx, rt)
628	630		j.results = j.resultsOn(rt)
629	631
	632	+	start := time.Now()
630	633		conn, err := j.startSandbox(ctx, rt, sb, stopHard)
	634	+	j.timeSet("sandbox_ms", time.Since(start))
	635	+	if timed, ok := sb.(sandbox.Timed); ok && err == nil {
	636	+	j.mu.Lock()
	637	+	for k, v := range timed.StartTimings() {
	638	+	j.timeline["sb_"+k] = max(0, v)
	639	+	}
	640	+	j.mu.Unlock()
	641	+	}
631	642		if err != nil {
632	643		if ctx.Err() != nil \|\| j.cancelRequested() {
633	644		return outcome{conclusion: ermite.CiConclusion_CI_CONCLUSION_CANCELLED, shutdown: j.isStopping()}

@@ -651,7 +662,9 @@ func (j jobRun) execute(ctx context.Context, rt Runner, stopHard <-chan struct
651	662		}
652	663		}()
653	664
	665	+	start = time.Now()
654	666		exit, err := j.drive(conn, rt)
	667	+	j.timeSet("run_ms", time.Since(start))
655	668		return j.outcomeOf(ctx, exit, err)
656	669		}
657	670

@@ -660,6 +673,8 @@ func (j jobRun) execute(ctx context.Context, rt Runner, stopHard <-chan struct
660	673		func (j jobRun) stopSandbox(ctx context.Context, rt Runner, sb sandbox.Sandbox) {
661	674		sctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), j.t.StopDeadline)
662	675		defer cancel()
	676	+	start := time.Now()
	677	+	defer func() { j.timeSet("stop_ms", time.Since(start)) }()
663	678		if err := sb.Stop(sctx); err != nil {
664	679		j.log.Error().Err(err).Msg("stopping the sandbox")
665	680		if errors.Is(err, sandbox.ErrLeaked) {

@@ -706,6 +721,18 @@ func (j jobRun) drive(conn sandbox.Conn, rt Runner) (*execpb.Exit, error) {
706	721		}
707	722		run.Job.CachePort, run.Job.CacheToken, run.Job.CacheMode, run.Job.Results = j.runtimeFor(rt)
708	723		_, exit, err := execstream.DriveJob(conn, run, j.cancelCh, execstream.JobHandler{
	724	+	Hello: func(h *execpb.Hello) {
	725	+	j.mu.Lock()
	726	+	defer j.mu.Unlock()
	727	+	if j.timeline == nil {
	728	+	j.timeline = make(timeline)
	729	+	}
	730	+	for k, v := range h.BootMs {
	731	+	if v >= 0 {
	732	+	j.timeline["guest_"+k+"_ms"] = v
	733	+	}
	734	+	}
	735	+	},
709	736		StepStarted: j.stepStarted, StepCompleted: j.stepCompleted,
710	737		Log: j.logLine,
711	738		JobResult: func(r *execpb.JobResult) { j.mu.Lock(); j.result = r; j.mu.Unlock() },

@@ -818,6 +845,8 @@ func (j *jobRun) sandboxError(msg string) {
818	845		// complete reports the end of the job. CompleteJob is idempotent, so a lost
819	846		// response is retried until it is answered (applied or not).
820	847		func (j *jobRun) complete(ctx context.Context, conclusion ermite.CiConclusion, outputs map[string]string, shutdown bool) {
	848	+	start := time.Now()
	849	+	defer func() { j.timeSet("complete_ms", time.Since(start)) }()
821	850		req := &ermite.CompleteJobRequest{
822	851		JobId: j.job.JobId, Conclusion: conclusion, Outputs: outputs,
823	852		RunnerShutdown: shutdown && conclusion == ermite.CiConclusion_CI_CONCLUSION_CANCELLED,

 	cancelKind execpb.CancelKind // kind of the first cancel request
 	stopping   bool              // the runner is shutting down
-	mu    sync.Mutex
+	timeline timeline
-	steps map[int32]*ermite.StepUpdate
+	mu       sync.Mutex
+	steps    map[int32]*ermite.StepUpdate
 	// What the guest has told us, for the validation of the next frame: the
 	// guest is untrusted code, its step numbers and lines are checked before
 	// they reach the server (see violate).
 		}
 	}()
 	if j.ack(ackCtx) {
+		j.timeSet("ack_ms", time.Since(j.receivedAt))
 		return true
 	}
 	select {
 	j.features = j.loadFeatures(ctx, rt)
 	j.results = j.resultsOn(rt)
+	start := time.Now()
 	conn, err := j.startSandbox(ctx, rt, sb, stopHard)
+	j.timeSet("sandbox_ms", time.Since(start))
+	if timed, ok := sb.(sandbox.Timed); ok && err == nil {
+		j.mu.Lock()
+		for k, v := range timed.StartTimings() {
+			j.timeline["sb_"+k] = max(0, v)
+		}
+		j.mu.Unlock()
+	}
 	if err != nil {
 		if ctx.Err() != nil || j.cancelRequested() {
 			return outcome{conclusion: ermite.CiConclusion_CI_CONCLUSION_CANCELLED, shutdown: j.isStopping()}
 		}
 	}()
+	start = time.Now()
 	exit, err := j.drive(conn, rt)
+	j.timeSet("run_ms", time.Since(start))
 	return j.outcomeOf(ctx, exit, err)
 }
 func (j *jobRun) stopSandbox(ctx context.Context, rt *Runner, sb sandbox.Sandbox) {
 	sctx, cancel := context.WithTimeout(context.WithoutCancel(ctx), j.t.StopDeadline)
 	defer cancel()
+	start := time.Now()
+	defer func() { j.timeSet("stop_ms", time.Since(start)) }()
 	if err := sb.Stop(sctx); err != nil {
 		j.log.Error().Err(err).Msg("stopping the sandbox")
 		if errors.Is(err, sandbox.ErrLeaked) {
 	}
 	run.Job.CachePort, run.Job.CacheToken, run.Job.CacheMode, run.Job.Results = j.runtimeFor(rt)
 	_, exit, err := execstream.DriveJob(conn, run, j.cancelCh, execstream.JobHandler{
+		Hello: func(h *execpb.Hello) {
+			j.mu.Lock()
+			defer j.mu.Unlock()
+			if j.timeline == nil {
+				j.timeline = make(timeline)
+			}
+			for k, v := range h.BootMs {
+				if v >= 0 {
+					j.timeline["guest_"+k+"_ms"] = v
+				}
+			}
+		},
 		StepStarted: j.stepStarted, StepCompleted: j.stepCompleted,
 		Log:             j.logLine,
 		JobResult:       func(r *execpb.JobResult) { j.mu.Lock(); j.result = r; j.mu.Unlock() },
 // complete reports the end of the job. CompleteJob is idempotent, so a lost
 // response is retried until it is answered (applied or not).
 func (j *jobRun) complete(ctx context.Context, conclusion ermite.CiConclusion, outputs map[string]string, shutdown bool) {
+	start := time.Now()
+	defer func() { j.timeSet("complete_ms", time.Since(start)) }()
 	req := &ermite.CompleteJobRequest{
 		JobId: j.job.JobId, Conclusion: conclusion, Outputs: outputs,
 		RunnerShutdown: shutdown && conclusion == ermite.CiConclusion_CI_CONCLUSION_CANCELLED,

M internal/host/resolve.go +8 -0


@@ -8,6 +8,7 @@ import (
8	8		"errors"
9	9		"fmt"
10	10		"strings"
	11	+	"time"
11	12		"unicode/utf8"
12	13
13	14		"connectrpc.com/connect"

@@ -111,6 +112,13 @@ func badRefRune(r rune) bool {
111	112		// (ActionManager: FailedToResolveActionDownloadInfoException). ctx ends with the
112	113		// session.
113	114		func (j jobRun) resolveActions(ctx context.Context, req execpb.ResolveRequest) *execpb.ResolveResponse {
	115	+	start := time.Now()
	116	+	defer func() {
	117	+	j.mu.Lock()
	118	+	defer j.mu.Unlock()
	119	+	j.timeline.add("resolve_ms", time.Since(start))
	120	+	j.timeline["resolve_calls"]++
	121	+	}()
114	122		fail := func(format string, a ...any) *execpb.ResolveResponse {
115	123		return &execpb.ResolveResponse{Error: fmt.Sprintf(format, a...)}
116	124		}


@@ -8,6 +8,7 @@ import (
8	"errors"	8		"errors"
9	"fmt"	9		"fmt"
10	"strings"	10		"strings"
		11	+	"time"
11	"unicode/utf8"	12		"unicode/utf8"
12		13
13	"connectrpc.com/connect"	14		"connectrpc.com/connect"

@@ -111,6 +112,13 @@ func badRefRune(r rune) bool {
111	// (ActionManager: FailedToResolveActionDownloadInfoException). ctx ends with the	112		// (ActionManager: FailedToResolveActionDownloadInfoException). ctx ends with the
112	// session.	113		// session.
113	func (j jobRun) resolveActions(ctx context.Context, req execpb.ResolveRequest) *execpb.ResolveResponse {	114		func (j jobRun) resolveActions(ctx context.Context, req execpb.ResolveRequest) *execpb.ResolveResponse {
		115	+	start := time.Now()
		116	+	defer func() {
		117	+	j.mu.Lock()
		118	+	defer j.mu.Unlock()
		119	+	j.timeline.add("resolve_ms", time.Since(start))
		120	+	j.timeline["resolve_calls"]++
		121	+	}()
114	fail := func(format string, a ...any) *execpb.ResolveResponse {	122		fail := func(format string, a ...any) *execpb.ResolveResponse {
115	return &execpb.ResolveResponse{Error: fmt.Sprintf(format, a...)}	123		return &execpb.ResolveResponse{Error: fmt.Sprintf(format, a...)}
116	}	124		}

M internal/host/runner.go +1 -1


@@ -219,7 +219,7 @@ func (r Runner) startJob(ctx context.Context, log zerowrap.Logger, job ermite.
219	219		defer r.active.Done()
220	220		defer func() { <-slots }()
221	221		jr.run(r, shutdown)
222		-	jr.log.Info().Msg("job finished")
	222	+	jr.log.Info().Fields(jr.timingFields()).Msg("job finished")
223	223		}()
224	224		}
225	225


@@ -219,7 +219,7 @@ func (r Runner) startJob(ctx context.Context, log zerowrap.Logger, job ermite.
219		defer r.active.Done()	219		defer r.active.Done()
220		defer func() { <-slots }()	220		defer func() { <-slots }()
221		jr.run(r, shutdown)	221		jr.run(r, shutdown)
222	-	jr.log.Info().Msg("job finished")	222	+	jr.log.Info().Fields(jr.timingFields()).Msg("job finished")
223		}()	223		}()
224		}	224		}
225			225

M internal/host/runner_test.go +18 -0


@@ -39,6 +39,24 @@ func TestJobRunsAndReports(t *testing.T) {
39	39		if err := stop(); err != nil {
40	40		t.Fatal(err)
41	41		}
	42	+	for _, line := range strings.Split(h.logs.String(), "\n") {
	43	+	var fields map[string]any
	44	+	if json.Unmarshal([]byte(line), &fields) != nil \|\| fields["message"] != "job finished" {
	45	+	continue
	46	+	}
	47	+	for _, key := range []string{"ack_ms", "sandbox_ms", "run_ms", "stop_ms", "complete_ms", "total_ms", "sb_socket_ms", "guest_dockerd_ms"} {
	48	+	value, ok := fields[key].(float64)
	49	+	if !ok \|\| value < 0 {
	50	+	t.Errorf("%s = %v", key, fields[key])
	51	+	}
	52	+	}
	53	+	if fields["total_ms"].(float64) < fields["sandbox_ms"].(float64)+fields["run_ms"].(float64) {
	54	+	t.Error("total shorter than sandbox + run")
	55	+	}
	56	+	}
	57	+	if !strings.Contains(h.logs.String(), `"message":"job finished"`) {
	58	+	t.Fatalf("no job finished log: %s", h.logs.String())
	59	+	}
42	60		s := h.srv
43	61		s.mu.Lock()
44	62		defer s.mu.Unlock()


@@ -39,6 +39,24 @@ func TestJobRunsAndReports(t *testing.T) {
39	if err := stop(); err != nil {	39		if err := stop(); err != nil {
40	t.Fatal(err)	40		t.Fatal(err)
41	}	41		}
		42	+	for _, line := range strings.Split(h.logs.String(), "\n") {
		43	+	var fields map[string]any
		44	+	if json.Unmarshal([]byte(line), &fields) != nil \|\| fields["message"] != "job finished" {
		45	+	continue
		46	+	}
		47	+	for _, key := range []string{"ack_ms", "sandbox_ms", "run_ms", "stop_ms", "complete_ms", "total_ms", "sb_socket_ms", "guest_dockerd_ms"} {
		48	+	value, ok := fields[key].(float64)
		49	+	if !ok \|\| value < 0 {
		50	+	t.Errorf("%s = %v", key, fields[key])
		51	+	}
		52	+	}
		53	+	if fields["total_ms"].(float64) < fields["sandbox_ms"].(float64)+fields["run_ms"].(float64) {
		54	+	t.Error("total shorter than sandbox + run")
		55	+	}
		56	+	}
		57	+	if !strings.Contains(h.logs.String(), `"message":"job finished"`) {
		58	+	t.Fatalf("no job finished log: %s", h.logs.String())
		59	+	}
42	s := h.srv	60		s := h.srv
43	s.mu.Lock()	61		s.mu.Lock()
44	defer s.mu.Unlock()	62		defer s.mu.Unlock()

A internal/host/timeline.go +39 -0

@@ -0,0 +1,39 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import "time"
	6	+
	7	+	// timeline is protected by jobRun.mu.
	8	+	type timeline map[string]int64
	9	+
	10	+	func (t *timeline) set(key string, d time.Duration) {
	11	+	if *t == nil {
	12	+	*t = make(timeline)
	13	+	}
	14	+	(*t)[key] = max(0, d.Milliseconds())
	15	+	}
	16	+	func (t *timeline) add(key string, d time.Duration) {
	17	+	if *t == nil {
	18	+	*t = make(timeline)
	19	+	}
	20	+	(*t)[key] += max(0, d.Milliseconds())
	21	+	}
	22	+	func (t timeline) fields() map[string]any {
	23	+	fields := make(map[string]any, len(t))
	24	+	for k, v := range t {
	25	+	fields[k] = v
	26	+	}
	27	+	return fields
	28	+	}
	29	+	func (j *jobRun) timeSet(key string, d time.Duration) {
	30	+	j.mu.Lock()
	31	+	defer j.mu.Unlock()
	32	+	j.timeline.set(key, d)
	33	+	}
	34	+	func (j *jobRun) timingFields() map[string]any {
	35	+	j.mu.Lock()
	36	+	defer j.mu.Unlock()
	37	+	j.timeline.set("total_ms", time.Since(j.receivedAt))
	38	+	return j.timeline.fields()
	39	+	}

@@ -0,0 +1,39 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import "time"
	6	+
	7	+	// timeline is protected by jobRun.mu.
	8	+	type timeline map[string]int64
	9	+
	10	+	func (t *timeline) set(key string, d time.Duration) {
	11	+	if *t == nil {
	12	+	*t = make(timeline)
	13	+	}
	14	+	(*t)[key] = max(0, d.Milliseconds())
	15	+	}
	16	+	func (t *timeline) add(key string, d time.Duration) {
	17	+	if *t == nil {
	18	+	*t = make(timeline)
	19	+	}
	20	+	(*t)[key] += max(0, d.Milliseconds())
	21	+	}
	22	+	func (t timeline) fields() map[string]any {
	23	+	fields := make(map[string]any, len(t))
	24	+	for k, v := range t {
	25	+	fields[k] = v
	26	+	}
	27	+	return fields
	28	+	}
	29	+	func (j *jobRun) timeSet(key string, d time.Duration) {
	30	+	j.mu.Lock()
	31	+	defer j.mu.Unlock()
	32	+	j.timeline.set(key, d)
	33	+	}
	34	+	func (j *jobRun) timingFields() map[string]any {
	35	+	j.mu.Lock()
	36	+	defer j.mu.Unlock()
	37	+	j.timeline.set("total_ms", time.Since(j.receivedAt))
	38	+	return j.timeline.fields()
	39	+	}

A internal/host/timeline_test.go +26 -0

@@ -0,0 +1,26 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import (
	6	+	"testing"
	7	+	"time"
	8	+	)
	9	+
	10	+	func TestTimeline(t *testing.T) {
	11	+	var timeline timeline
	12	+	timeline.set("run_ms", 3*time.Millisecond)
	13	+	timeline.add("run_ms", 2*time.Millisecond)
	14	+	fields := timeline.fields()
	15	+	if fields["run_ms"] != int64(5) {
	16	+	t.Fatal(fields)
	17	+	}
	18	+	fields["run_ms"] = int64(99)
	19	+	if timeline.fields()["run_ms"] != int64(5) {
	20	+	t.Fatal("shared fields")
	21	+	}
	22	+	timeline.set("run_ms", time.Millisecond)
	23	+	if timeline.fields()["run_ms"] != int64(1) {
	24	+	t.Fatal(timeline)
	25	+	}
	26	+	}

@@ -0,0 +1,26 @@
	1	+	// SPDX-License-Identifier: MIT
	2	+
	3	+	package host
	4	+
	5	+	import (
	6	+	"testing"
	7	+	"time"
	8	+	)
	9	+
	10	+	func TestTimeline(t *testing.T) {
	11	+	var timeline timeline
	12	+	timeline.set("run_ms", 3*time.Millisecond)
	13	+	timeline.add("run_ms", 2*time.Millisecond)
	14	+	fields := timeline.fields()
	15	+	if fields["run_ms"] != int64(5) {
	16	+	t.Fatal(fields)
	17	+	}
	18	+	fields["run_ms"] = int64(99)
	19	+	if timeline.fields()["run_ms"] != int64(5) {
	20	+	t.Fatal("shared fields")
	21	+	}
	22	+	timeline.set("run_ms", time.Millisecond)
	23	+	if timeline.fields()["run_ms"] != int64(1) {
	24	+	t.Fatal(timeline)
	25	+	}
	26	+	}

M internal/sandbox/container/container_test.go +11 -0


@@ -349,6 +349,17 @@ func TestStartRunStop(t *testing.T) {
349	349		if err != nil {
350	350		t.Fatal(err)
351	351		}
	352	+	timed := sb.(sandbox.Timed)
	353	+	timings := timed.StartTimings()
	354	+	for _, key := range []string{"socket_ms", "cache_ms", "scratch_ms", "net_ms", "container_ms", "connect_ms"} {
	355	+	if value, ok := timings[key]; !ok \|\| value < 0 {
	356	+	t.Errorf("StartTimings[%q] = %d, present=%v", key, value, ok)
	357	+	}
	358	+	}
	359	+	timings["socket_ms"] = -1
	360	+	if timed.StartTimings()["socket_ms"] < 0 {
	361	+	t.Error("StartTimings returned shared storage")
	362	+	}
352	363		out, code := stub(t, conn)
353	364		if out != "hello from fake container\n" \|\| code != 7 {
354	365		t.Fatalf("out=%q code=%d", out, code)


@@ -349,6 +349,17 @@ func TestStartRunStop(t *testing.T) {
349	if err != nil {	349		if err != nil {
350	t.Fatal(err)	350		t.Fatal(err)
351	}	351		}
		352	+	timed := sb.(sandbox.Timed)
		353	+	timings := timed.StartTimings()
		354	+	for _, key := range []string{"socket_ms", "cache_ms", "scratch_ms", "net_ms", "container_ms", "connect_ms"} {
		355	+	if value, ok := timings[key]; !ok \|\| value < 0 {
		356	+	t.Errorf("StartTimings[%q] = %d, present=%v", key, value, ok)
		357	+	}
		358	+	}
		359	+	timings["socket_ms"] = -1
		360	+	if timed.StartTimings()["socket_ms"] < 0 {
		361	+	t.Error("StartTimings returned shared storage")
		362	+	}
352	out, code := stub(t, conn)	363		out, code := stub(t, conn)
353	if out != "hello from fake container\n" \|\| code != 7 {	364		if out != "hello from fake container\n" \|\| code != 7 {
354	t.Fatalf("out=%q code=%d", out, code)	365		t.Fatalf("out=%q code=%d", out, code)

M internal/sandbox/container/driver.go +40 -6


@@ -285,10 +285,11 @@ const (
285	285		)
286	286
287	287		type containerSandbox struct {
288		-	d *Driver
289		-	slot int
290		-	id string
291		-	gate sandbox.BootGate
	288	+	d *Driver
	289	+	slot int
	290	+	id string
	291	+	gate sandbox.BootGate
	292	+	timings map[string]int64
292	293
293	294		mu sync.Mutex
294	295		started bool

@@ -305,6 +306,17 @@ type containerSandbox struct {
305	306		attached bool
306	307		}
307	308
	309	+	// StartTimings returns a copy of the successful start's phase durations.
	310	+	func (s *containerSandbox) StartTimings() map[string]int64 {
	311	+	s.mu.Lock()
	312	+	defer s.mu.Unlock()
	313	+	out := make(map[string]int64, len(s.timings))
	314	+	for k, v := range s.timings {
	315	+	out[k] = v
	316	+	}
	317	+	return out
	318	+	}
	319	+
308	320		// ID implements sandbox.Sandbox.
309	321		func (s *containerSandbox) ID() string { return s.id }
310	322

@@ -334,8 +346,11 @@ func (s *containerSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (san
334	346		if d.cfg.GuestForge != nil {
335	347		log.Warn().Str("job", spec.JobID).Str("container", s.id).Msg(d.cfg.GuestForge.Warning())
336	348		}
	349	+	start := time.Now()
	350	+	s.timings = make(map[string]int64)
337	351		conn, err := s.run(bootCtx, spec)
338	352		if err != nil {
	353	+	s.timings = nil
339	354		var tail string
340	355		if s.container != "" {
341	356		tail, _ = d.eng.LogsTail(context.WithoutCancel(ctx), s.container, 40)

@@ -346,7 +361,11 @@ func (s *containerSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (san
346	361		}
347	362		return nil, errors.Join(err, cerr)
348	363		}
349		-	log.Info().Str("container", s.container).Int("slot", s.slot).Str("job", spec.JobID).Bool("privileged", d.privileged).Msg("container running")
	364	+	fields := map[string]any{"total_ms": time.Since(start).Milliseconds()}
	365	+	for k, v := range s.timings {
	366	+	fields[k] = v
	367	+	}
	368	+	log.Info().Str("container", s.container).Int("slot", s.slot).Str("job", spec.JobID).Bool("privileged", d.privileged).Fields(fields).Msg("container running")
350	369		return conn, nil
351	370		}
352	371

@@ -356,25 +375,40 @@ func (s *containerSandbox) run(ctx context.Context, spec sandbox.JobSpec) (sandb
356	375		if err != nil {
357	376		return nil, err
358	377		}
	378	+	start := time.Now()
359	379		accepted, err := s.runSocket()
360	380		if err != nil {
361	381		return nil, err
362	382		}
	383	+	s.timings["socket_ms"] = time.Since(start).Milliseconds()
	384	+	start = time.Now()
363	385		if err := s.runCache(spec); err != nil {
364	386		return nil, err
365	387		}
	388	+	s.timings["cache_ms"] = time.Since(start).Milliseconds()
	389	+	start = time.Now()
366	390		if err := s.runScratch(ctx, spec); err != nil {
367	391		return nil, err
368	392		}
369	393		labels := map[string]string{sandbox.LabelJob: spec.JobID}
	394	+	s.timings["scratch_ms"] = time.Since(start).Milliseconds()
	395	+	start = time.Now()
370	396		if err := s.runNetwork(ctx, netw, labels); err != nil {
371	397		return nil, err
372	398		}
	399	+	s.timings["net_ms"] = time.Since(start).Milliseconds()
	400	+	start = time.Now()
373	401		exited, err := s.runContainer(ctx, spec, netw, labels)
374	402		if err != nil {
375	403		return nil, err
376	404		}
377		-	return s.waitExecutor(ctx, accepted, exited)
	405	+	s.timings["container_ms"] = time.Since(start).Milliseconds()
	406	+	start = time.Now()
	407	+	conn, err := s.waitExecutor(ctx, accepted, exited)
	408	+	if err == nil {
	409	+	s.timings["connect_ms"] = time.Since(start).Milliseconds()
	410	+	}
	411	+	return conn, err
378	412		}
379	413
380	414		type acceptResult struct {

 )
 type containerSandbox struct {
-	d    *Driver
+	d       *Driver
-	slot int
+	slot    int
-	id   string
+	id      string
-	gate sandbox.BootGate
+	gate    sandbox.BootGate
+	timings map[string]int64
 	mu        sync.Mutex
 	started   bool
 	attached  bool
 }
+// StartTimings returns a copy of the successful start's phase durations.
+func (s *containerSandbox) StartTimings() map[string]int64 {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	out := make(map[string]int64, len(s.timings))
+	for k, v := range s.timings {
+		out[k] = v
+	}
+	return out
+}
 // ID implements sandbox.Sandbox.
 func (s *containerSandbox) ID() string { return s.id }
 	if d.cfg.GuestForge != nil {
 		log.Warn().Str("job", spec.JobID).Str("container", s.id).Msg(d.cfg.GuestForge.Warning())
 	}
+	start := time.Now()
+	s.timings = make(map[string]int64)
 	conn, err := s.run(bootCtx, spec)
 	if err != nil {
+		s.timings = nil
 		var tail string
 		if s.container != "" {
 			tail, _ = d.eng.LogsTail(context.WithoutCancel(ctx), s.container, 40)
 		}
 		return nil, errors.Join(err, cerr)
 	}
-	log.Info().Str("container", s.container).Int("slot", s.slot).Str("job", spec.JobID).Bool("privileged", d.privileged).Msg("container running")
+	fields := map[string]any{"total_ms": time.Since(start).Milliseconds()}
+	for k, v := range s.timings {
+		fields[k] = v
+	}
+	log.Info().Str("container", s.container).Int("slot", s.slot).Str("job", spec.JobID).Bool("privileged", d.privileged).Fields(fields).Msg("container running")
 	return conn, nil
 }
 	if err != nil {
 		return nil, err
 	}
+	start := time.Now()
 	accepted, err := s.runSocket()
 	if err != nil {
 		return nil, err
 	}
+	s.timings["socket_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := s.runCache(spec); err != nil {
 		return nil, err
 	}
+	s.timings["cache_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := s.runScratch(ctx, spec); err != nil {
 		return nil, err
 	}
 	labels := map[string]string{sandbox.LabelJob: spec.JobID}
+	s.timings["scratch_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := s.runNetwork(ctx, netw, labels); err != nil {
 		return nil, err
 	}
+	s.timings["net_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	exited, err := s.runContainer(ctx, spec, netw, labels)
 	if err != nil {
 		return nil, err
 	}
-	return s.waitExecutor(ctx, accepted, exited)
+	s.timings["container_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
+	conn, err := s.waitExecutor(ctx, accepted, exited)
+	if err == nil {
+		s.timings["connect_ms"] = time.Since(start).Milliseconds()
+	}
+	return conn, err
 }
 type acceptResult struct {

M internal/sandbox/sandbox.go +5 -0


@@ -89,6 +89,11 @@ type Sandbox interface {
89	89		Stop(ctx context.Context) error
90	90		}
91	91
	92	+	// Timed is implemented by sandboxes that measure their start phases.
	93	+	type Timed interface {
	94	+	StartTimings() map[string]int64
	95	+	}
	96	+
92	97		// Driver creates sandboxes of one mode and reaps what a previous run left.
93	98		type Driver interface {
94	99		// Mode is VM or Container.


@@ -89,6 +89,11 @@ type Sandbox interface {
89	Stop(ctx context.Context) error	89		Stop(ctx context.Context) error
90	}	90		}
91		91
		92	+	// Timed is implemented by sandboxes that measure their start phases.
		93	+	type Timed interface {
		94	+	StartTimings() map[string]int64
		95	+	}
		96	+
92	// Driver creates sandboxes of one mode and reaps what a previous run left.	97		// Driver creates sandboxes of one mode and reaps what a previous run left.
93	type Driver interface {	98		type Driver interface {
94	// Mode is VM or Container.	99		// Mode is VM or Container.

M internal/sandbox/vm/driver.go +48 -7


@@ -232,10 +232,11 @@ func (d *Driver) markLeaked(slot int) {
232	232
233	233		// vmSandbox is one VM, single use.
234	234		type vmSandbox struct {
235		-	d *Driver
236		-	slot int
237		-	id string
238		-	gate sandbox.BootGate
	235	+	d *Driver
	236	+	slot int
	237	+	id string
	238	+	gate sandbox.BootGate
	239	+	timings map[string]int64
239	240
240	241		mu sync.Mutex
241	242		started bool

@@ -257,6 +258,17 @@ type vmSandbox struct {
257	258		attached bool
258	259		}
259	260
	261	+	// StartTimings returns a copy of the successful start's phase durations.
	262	+	func (s *vmSandbox) StartTimings() map[string]int64 {
	263	+	s.mu.Lock()
	264	+	defer s.mu.Unlock()
	265	+	out := make(map[string]int64, len(s.timings))
	266	+	for k, v := range s.timings {
	267	+	out[k] = v
	268	+	}
	269	+	return out
	270	+	}
	271	+
260	272		// ID implements sandbox.Sandbox.
261	273		func (s *vmSandbox) ID() string { return s.id }
262	274

@@ -299,8 +311,11 @@ func (s *vmSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (sandbox.Co
299	311		return nil, fmt.Errorf("write state record: %w", err)
300	312		}
301	313
	314	+	start := time.Now()
	315	+	s.timings = make(map[string]int64)
302	316		conn, err := s.boot(bootCtx, spec)
303	317		if err != nil {
	318	+	s.timings = nil
304	319		console := ""
305	320		if s.console != nil {
306	321		console = s.console.String()

@@ -311,7 +326,11 @@ func (s *vmSandbox) Start(ctx context.Context, spec sandbox.JobSpec) (sandbox.Co
311	326		}
312	327		return nil, errors.Join(err, cerr)
313	328		}
314		-	log.Info().Str("vm", s.id).Int("slot", s.slot).Str("job", spec.JobID).Msg("micro-VM running")
	329	+	fields := map[string]any{"total_ms": time.Since(start).Milliseconds()}
	330	+	for k, v := range s.timings {
	331	+	fields[k] = v
	332	+	}
	333	+	log.Info().Str("vm", s.id).Int("slot", s.slot).Str("job", spec.JobID).Fields(fields).Msg("micro-VM running")
315	334		return conn, nil
316	335		}
317	336

@@ -322,17 +341,24 @@ func (s *vmSandbox) boot(ctx context.Context, spec sandbox.JobSpec) (sandbox.Con
322	341		if err != nil {
323	342		return nil, err
324	343		}
	344	+	start := time.Now()
325	345		if err := s.bootNetwork(ctx, netw); err != nil {
326	346		return nil, err
327	347		}
	348	+	s.timings["net_ms"] = time.Since(start).Milliseconds() - s.timings["tap_ms"]
	349	+	start = time.Now()
328	350		api, err := s.bootVMM(ctx, spec)
329	351		if err != nil {
330	352		return nil, err
331	353		}
	354	+	s.timings["vmm_ms"] = time.Since(start).Milliseconds()
	355	+	start = time.Now()
332	356		files, err := s.bootFiles(ctx, spec)
333	357		if err != nil {
334	358		return nil, err
335	359		}
	360	+	s.timings["files_ms"] = time.Since(start).Milliseconds() - s.timings["scratch_ms"]
	361	+	start = time.Now()
336	362		accepted, err := s.bootVsock()
337	363		if err != nil {
338	364		return nil, err

@@ -340,10 +366,18 @@ func (s *vmSandbox) boot(ctx context.Context, spec sandbox.JobSpec) (sandbox.Con
340	366		if err := s.bootCache(spec); err != nil {
341	367		return nil, err
342	368		}
	369	+	s.timings["vsock_ms"] = time.Since(start).Milliseconds()
	370	+	start = time.Now()
343	371		if err := api.configure(ctx, s.vmConfig(spec, netw, files)); err != nil {
344	372		return nil, err
345	373		}
346		-	return s.waitExecutor(ctx, accepted)
	374	+	s.timings["configure_ms"] = time.Since(start).Milliseconds()
	375	+	start = time.Now()
	376	+	conn, err := s.waitExecutor(ctx, accepted)
	377	+	if err == nil {
	378	+	s.timings["connect_ms"] = time.Since(start).Milliseconds()
	379	+	}
	380	+	return conn, err
347	381		}
348	382
349	383		// bootNetwork creates the TAP (it must exist when Firecracker opens it) and

@@ -355,9 +389,11 @@ func (s *vmSandbox) bootNetwork(ctx context.Context, netw netpolicy.Net) error {
355	389		if err := d.store.save(s.rec); err != nil {
356	390		return err
357	391		}
	392	+	start := time.Now()
358	393		if err := createTap(ctx, d.opt.Run, s.tap, s.lay.uid, s.gateway); err != nil {
359	394		return err
360	395		}
	396	+	s.timings["tap_ms"] = time.Since(start).Milliseconds()
361	397		s.attached = true // from here Detach is idempotent and always safe
362	398		return d.net.Attach(ctx, netpolicy.Guest{Iface: s.tap, Gateway: netw.Gateway, Addr: netw.Guest, ForgePort: d.cfg.GuestForge.TCPPort()})
363	399		}

@@ -402,7 +438,12 @@ func (s *vmSandbox) bootFiles(ctx context.Context, spec sandbox.JobSpec) (vmFile
402	438		if s.lay.jailed {
403	439		owner = s.lay.uid
404	440		}
405		-	return f, disk.CreateScratch(ctx, d.opt.Run, s.lay.host("scratch.ext4"), spec.DiskMiB, owner)
	441	+	start := time.Now()
	442	+	err = disk.CreateScratch(ctx, d.opt.Run, s.lay.host("scratch.ext4"), spec.DiskMiB, owner)
	443	+	if err == nil {
	444	+	s.timings["scratch_ms"] = time.Since(start).Milliseconds()
	445	+	}
	446	+	return f, err
406	447		}
407	448
408	449		// shareExternals makes the read-only disk of the host's external tools available

 // vmSandbox is one VM, single use.
 type vmSandbox struct {
-	d    *Driver
+	d       *Driver
-	slot int
+	slot    int
-	id   string
+	id      string
-	gate sandbox.BootGate
+	gate    sandbox.BootGate
+	timings map[string]int64
 	mu      sync.Mutex
 	started bool
 	attached bool
 }
+// StartTimings returns a copy of the successful start's phase durations.
+func (s *vmSandbox) StartTimings() map[string]int64 {
+	s.mu.Lock()
+	defer s.mu.Unlock()
+	out := make(map[string]int64, len(s.timings))
+	for k, v := range s.timings {
+		out[k] = v
+	}
+	return out
+}
 // ID implements sandbox.Sandbox.
 func (s *vmSandbox) ID() string { return s.id }
 		return nil, fmt.Errorf("write state record: %w", err)
 	}
+	start := time.Now()
+	s.timings = make(map[string]int64)
 	conn, err := s.boot(bootCtx, spec)
 	if err != nil {
+		s.timings = nil
 		console := ""
 		if s.console != nil {
 			console = s.console.String()
 		}
 		return nil, errors.Join(err, cerr)
 	}
-	log.Info().Str("vm", s.id).Int("slot", s.slot).Str("job", spec.JobID).Msg("micro-VM running")
+	fields := map[string]any{"total_ms": time.Since(start).Milliseconds()}
+	for k, v := range s.timings {
+		fields[k] = v
+	}
+	log.Info().Str("vm", s.id).Int("slot", s.slot).Str("job", spec.JobID).Fields(fields).Msg("micro-VM running")
 	return conn, nil
 }
 	if err != nil {
 		return nil, err
 	}
+	start := time.Now()
 	if err := s.bootNetwork(ctx, netw); err != nil {
 		return nil, err
 	}
+	s.timings["net_ms"] = time.Since(start).Milliseconds() - s.timings["tap_ms"]
+	start = time.Now()
 	api, err := s.bootVMM(ctx, spec)
 	if err != nil {
 		return nil, err
 	}
+	s.timings["vmm_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	files, err := s.bootFiles(ctx, spec)
 	if err != nil {
 		return nil, err
 	}
+	s.timings["files_ms"] = time.Since(start).Milliseconds() - s.timings["scratch_ms"]
+	start = time.Now()
 	accepted, err := s.bootVsock()
 	if err != nil {
 		return nil, err
 	if err := s.bootCache(spec); err != nil {
 		return nil, err
 	}
+	s.timings["vsock_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
 	if err := api.configure(ctx, s.vmConfig(spec, netw, files)); err != nil {
 		return nil, err
 	}
-	return s.waitExecutor(ctx, accepted)
+	s.timings["configure_ms"] = time.Since(start).Milliseconds()
+	start = time.Now()
+	conn, err := s.waitExecutor(ctx, accepted)
+	if err == nil {
+		s.timings["connect_ms"] = time.Since(start).Milliseconds()
+	}
+	return conn, err
 }
 // bootNetwork creates the TAP (it must exist when Firecracker opens it) and
 	if err := d.store.save(s.rec); err != nil {
 		return err
 	}
+	start := time.Now()
 	if err := createTap(ctx, d.opt.Run, s.tap, s.lay.uid, s.gateway); err != nil {
 		return err
 	}
+	s.timings["tap_ms"] = time.Since(start).Milliseconds()
 	s.attached = true // from here Detach is idempotent and always safe
 	return d.net.Attach(ctx, netpolicy.Guest{Iface: s.tap, Gateway: netw.Gateway, Addr: netw.Guest, ForgePort: d.cfg.GuestForge.TCPPort()})
 }
 	if s.lay.jailed {
 		owner = s.lay.uid
 	}
-	return f, disk.CreateScratch(ctx, d.opt.Run, s.lay.host("scratch.ext4"), spec.DiskMiB, owner)
+	start := time.Now()
+	err = disk.CreateScratch(ctx, d.opt.Run, s.lay.host("scratch.ext4"), spec.DiskMiB, owner)
+	if err == nil {
+		s.timings["scratch_ms"] = time.Since(start).Milliseconds()
+	}
+	return f, err
 }
 // shareExternals makes the read-only disk of the host's external tools available

M internal/sandbox/vm/vm_test.go +10 -0


@@ -228,6 +228,16 @@ func TestStartRunStop(t *testing.T) {
228	228		if err != nil {
229	229		t.Fatal(err)
230	230		}
	231	+	timings := sb.(sandbox.Timed).StartTimings()
	232	+	for _, key := range []string{"tap_ms", "net_ms", "vmm_ms", "files_ms", "scratch_ms", "vsock_ms", "configure_ms", "connect_ms"} {
	233	+	if value, ok := timings[key]; !ok \|\| value < 0 {
	234	+	t.Errorf("%s = %d, present=%v", key, value, ok)
	235	+	}
	236	+	}
	237	+	timings["tap_ms"] = -1
	238	+	if sb.(sandbox.Timed).StartTimings()["tap_ms"] < 0 {
	239	+	t.Error("shared timing map")
	240	+	}
231	241		out, code := runStub(t, conn)
232	242		if out != "hello from fake guest\n" \|\| code != 0 {
233	243		t.Fatalf("out=%q code=%d", out, code)


@@ -228,6 +228,16 @@ func TestStartRunStop(t *testing.T) {
228	if err != nil {	228		if err != nil {
229	t.Fatal(err)	229		t.Fatal(err)
230	}	230		}
		231	+	timings := sb.(sandbox.Timed).StartTimings()
		232	+	for _, key := range []string{"tap_ms", "net_ms", "vmm_ms", "files_ms", "scratch_ms", "vsock_ms", "configure_ms", "connect_ms"} {
		233	+	if value, ok := timings[key]; !ok \|\| value < 0 {
		234	+	t.Errorf("%s = %d, present=%v", key, value, ok)
		235	+	}
		236	+	}
		237	+	timings["tap_ms"] = -1
		238	+	if sb.(sandbox.Timed).StartTimings()["tap_ms"] < 0 {
		239	+	t.Error("shared timing map")
		240	+	}
231	out, code := runStub(t, conn)	241		out, code := runStub(t, conn)
232	if out != "hello from fake guest\n" \|\| code != 0 {	242		if out != "hello from fake guest\n" \|\| code != 0 {
233	t.Fatalf("out=%q code=%d", out, code)	243		t.Fatalf("out=%q code=%d", out, code)

M main.go +1 -0


@@ -79,6 +79,7 @@ func execCmd(ctx context.Context) int {
79	79		}
80	80		code, err := guest.Exec(ctx, guest.ExecConfig{
81	81		Target: target,
	82	+	BootMs: guest.ParseBootMs(os.Getenv("ERMITE_BOOT_MS")),
82	83		Sandbox: envOr("ERMITE_SANDBOX", "container"),
83	84		Version: envOr("ERMITE_VERSION", version),
84	85		// A test image without the user "runner" (ERMITE_RUNNER_ALLOW_ROOT_STEPS=1);


@@ -79,6 +79,7 @@ func execCmd(ctx context.Context) int {
79	}	79		}
80	code, err := guest.Exec(ctx, guest.ExecConfig{	80		code, err := guest.Exec(ctx, guest.ExecConfig{
81	Target: target,	81		Target: target,
		82	+	BootMs: guest.ParseBootMs(os.Getenv("ERMITE_BOOT_MS")),
82	Sandbox: envOr("ERMITE_SANDBOX", "container"),	83		Sandbox: envOr("ERMITE_SANDBOX", "container"),
83	Version: envOr("ERMITE_VERSION", version),	84		Version: envOr("ERMITE_VERSION", version),
84	// A test image without the user "runner" (ERMITE_RUNNER_ALLOW_ROOT_STEPS=1);	85		// A test image without the user "runner" (ERMITE_RUNNER_ALLOW_ROOT_STEPS=1);