Fix RIE init duration reporting - #185
Conversation
![aws-sam-tooling-bot[bot]](https://avatars.githubusercontent.com/b/1290?s=60&v=4){kind=small}
|
|
||
| initStart, initEnd := InitHandler(sandbox, functionVersion, timeout, bs) | ||
| initStart := InitHandler(sandbox, functionVersion, timeout, bs) | ||
| sandbox.AwaitInitCompletion() |
There was a problem hiding this comment.
[BUG] Waiting here is unbounded, which removes the only timeout enforcement RIE has over the init phase.
The init phase has no deadline of its own: initContext.Wait() is documented as "Timeout handling is managed upstream entirely" (internal/lambda/rapidcore/sandbox_api.go), and rapid.handleInit blocks inside doRuntimeDomainInit until the runtime calls /next, the process exits, or a Reset cancels the flow. The only thing that issues that Reset in RIE is the timeout goroutine started inside Server.Invoke:
go func() {
select {
case <-time.After(s.GetInvokeTimeout()):
timeoutChan <- ErrInvokeTimeout
...Because AwaitInitCompletion() now runs before sandbox.Invoke(...), that clock is never armed while init is pending. Concretely:
- Runtime hangs during init (bootstrap never calls
/next, e.g. a blocking import): the HTTP request hangs forever with no response and noReset. Previously the client gotTask timed out after N seconds. - Init is merely slower than the function timeout (say 30s init with
AWS_LAMBDA_FUNCTION_TIMEOUT=3): the handler blocks for the full 30s, and only then does the 3s invoke timeout start counting, so the client can wait init duration + invoke timeout.
Bounding the wait keeps the fix while preserving the timeout path — on expiry, control falls through to Invoke, which arms its timer and drives the Reset/timeout response as before:
// rapidcore
func (s Server) AwaitInitCompletion(timeout time.Duration) {
select {
case <-s.initCompleted:
case <-time.After(timeout):
// init still running; Invoke() enforces the timeout and triggers the Reset
}
}// rie
initStart := InitHandler(sandbox, functionVersion, timeout, bs)
sandbox.AwaitInitCompletion(timeoutDuration)Note the reported value is already clamped with math.Min(..., timeoutDuration), so capping the wait does not change what gets printed in the successful case.
| } | ||
|
|
||
| func (s *Server) AwaitInitCompletion() { | ||
| <-s.initCompleted |
There was a problem hiding this comment.
[CONCURRENCY] initCompleted is the only channel field on Server accessed without the mutex, and both of its unguarded accesses are reachable from different goroutines: it is assigned in Init (line 521), closed by the awaitInitCompletion goroutine (line 217), and received from here.
Two concrete problems:
- Double close panic.
close(s.initCompleted)re-reads the field at close time rather than using the channel the goroutine was started for.InvokeHandleris a plainnet/httphandler andinitDoneis an unsynchronizedbool, so two concurrent first invokes can both reachInit. If the secondInitreplaces the field before the first goroutine closes it, both goroutines close the same channel and the process dies withpanic: close of closed channel. - Blocking on a nil channel. If
AwaitInitCompletionis ever reached without a precedingInit,<-s.initCompletedis a receive on a nil channel and blocks forever.Invokeguards the analogous case explicitly (if initFailures == nil { return ErrInitNotStarted }).
Following the existing setInitFailuresChan/getInitFailuresChan pattern and capturing the channel locally fixes both:
func (s Server) setInitCompletedChan() {
s.mutex.Lock()
defer s.mutex.Unlock()
s.initCompleted = make(chan struct{})
}
func (s Server) getInitCompletedChan() chan struct{} {
s.mutex.Lock()
defer s.mutex.Unlock()
return s.initCompleted
}
func (s Server) awaitInitCompletion() {
initCompleted := s.getInitCompletedChan() // capture before Wait()
initSuccess, initFailure := s.initContext.Wait()
close(initCompleted) // never closes a channel created by a later Init()
...
}
func (s Server) AwaitInitCompletion() {
if initCompleted := s.getInitCompletedChan(); initCompleted != nil {
<-initCompleted
}
}
|
Thanks for catching these. Both points are addressed in 1668238. For the timeout case, I moved the completion read until after For the concurrency case, each init now owns its completion object, and the goroutine captures that object along with its init context and failure channel. Publishing the current completion object is mutex-protected, and calling Validation after the change:
|
There was a problem hiding this comment.
Code Review Results
Reviewed: ddf2bc4..1668238
Files: 5
Comments: 2
Comments on lines outside the diff:
[internal/lambda/rie/handlers.go:133] [GENERAL] Now that Init Duration is measured correctly, the Duration field on the same REPORT line double counts it, so the report becomes self-inconsistent for the cold invoke.
invokeStart is taken immediately after init is kicked off, not after it completes. sandbox.Invoke then blocks on init internally: Server.Invoke waits in s.awaitInitialized() before calling FastInvoke. So printEndReports computes time.Now().Sub(invokeStart) over init time plus handler time. With the PR's own e2e example (1.2 s module import), the line reads roughly Init Duration: 1302.32 ms Duration: ~1305 ms, whereas Lambda's Duration covers only the invocation.
Since the completion timestamp is now available, the invoke window can start from it:
initEnd := sandbox.AwaitInitCompletion()
// ...
if !initStart.IsZero() && initEnd.After(invokeStart) {
invokeStart = initEnd
}Note this requires the wait to happen before printEndReports rather than inline in its argument list, so formatInitDuration would need to return the timestamp (or take it) instead of calling AwaitInitCompletion itself. If you'd rather keep this PR narrowly scoped to Init Duration, that's reasonable — but the overlap is worth calling out explicitly, since the fix is what makes it visible.
| memorySize := GetenvWithDefault("AWS_LAMBDA_FUNCTION_MEMORY_SIZE", "3008") | ||
|
|
||
| var initStart time.Time | ||
| initMutex.Lock() |
There was a problem hiding this comment.
[CONCURRENCY] The global initMutex is locked and unlocked without defer, with a call into the whole init path in between. net/http recovers panics in handler goroutines, so a panic anywhere inside InitHandler would kill only this request and leave initMutex locked forever — every subsequent invoke would then block on initMutex.Lock() and the emulator would be permanently wedged with no error surfaced.
This is not hypothetical for InitHandler: it indexes envVar[1] on strings.SplitN(env, "=", 2) for every entry of os.Environ(), which panics on an environ entry with no =.
Scoping the lock so it is always released is enough:
func startInitOnce(sandbox Sandbox, functionVersion string, timeout int64, bs interop.Bootstrap) time.Time {
initMutex.Lock()
defer initMutex.Unlock()
if initDone {
return time.Time{}
}
// Set initDone so next invokes do not try to Init the function again
initDone = true
return InitHandler(sandbox, functionVersion, timeout, bs)
}Then the call site becomes initStart := startInitOnce(sandbox, functionVersion, timeout, bs), and the zero-time return keeps working with the existing initStart.IsZero() check in formatInitDuration.
|
Addressed both follow-up comments in 2c52c1e.
For successful cold invokes, the captured init completion timestamp now ends Validation after this update:
|
| case rapidcore.ErrInvokeTimeout: | ||
| printEndReports(invokePayload.ID, initDuration, memorySize, invokeStart, timeoutDuration) | ||
| initEnd := sandbox.AwaitInitCompletion() | ||
| printEndReports(invokePayload.ID, formatInitDuration(initStart, initEnd, timeoutDuration), memorySize, invokeStart, timeoutDuration) |
There was a problem hiding this comment.
[GENERAL] The timeout branch still passes the pre-init invokeStart to printEndReports, so this REPORT line counts the init window twice now that formatInitDuration measures real init completion.
invokeStart is captured at line 134, right after init is kicked off, and sandbox.Invoke blocks through the entire init phase. The success path compensates for that at line 227 by rebasing invokeStart to initEnd; this branch does not.
For a cold invoke that times out during init, Server.Invoke returns ErrInvokeTimeout only after Reset has cancelled the init flow (HandleReset calls CancelFlows before taking handlerExecutionMutex, so initContext.Wait() has already returned an InitFailure). AwaitInitCompletion() therefore returns the time init was aborted, roughly initStart + timeout. formatInitDuration caps that at timeoutDuration, and printEndReports independently caps now - invokeStart at the same value, so a 300 s timeout prints:
REPORT RequestId: ...Init Duration: 300000.00 msDuration: 300000.00 msBilled Duration: 300000 ms
The same elapsed wall clock is reported in both fields, and Init Duration is presented as a completed init when init was actually cancelled. Before this change the branch printed Init Duration: ~0.00 ms, so this is a new inconsistency specific to the timeout path.
Note that simply rebasing invokeStart here (as the success path does) would make Duration collapse to the reset time, which contradicts the Task timed out after N seconds body written two lines below. The cleaner fix is to distinguish a completed init from an aborted one — for example, have the completion signal carry whether init succeeded, and omit Init Duration (or report only the portion that elapsed before the deadline) when the init phase was terminated by the timeout reset — so that Init Duration and Duration never describe the same interval.
|
Addressed the latest timeout-reporting finding in 9ea5783. The init completion result now includes whether initialization actually succeeded. RIE prints I also audited the changed path for repeated waits, publication ordering, panic handling, and concurrent access. The timestamp and success flag are written before the completion channel closes, and repeated readers receive the same cached result. Validation:
|
| case rapidcore.ErrInvokeTimeout: | ||
| initEnd, initSucceeded := sandbox.AwaitInitCompletion() | ||
| initDuration := "" | ||
| if initSucceeded { |
There was a problem hiding this comment.
[GENERAL] Gating on initSucceeded drops Init Duration from the REPORT line entirely when the invoke times out during init, so the cold-start REPORT loses a field it has always had.
Tracing where this gate actually changes output: on the post-switch path (line 231), initSucceeded == false together with a non-zero initStart is unreachable — every init-failure path returns early through ErrInitDoneFailed or ErrInvokeDoneFailed, and warm invokes are already filtered by the initStart.IsZero() check inside formatInitDuration. That leaves this timeout branch as the only place the gate has an observable effect, and TestInvokeHandlerOmitsInitDurationWhenInitTimesOut locks the omission in.
Before this change RIE always printed an Init Duration on the first invoke (a near-zero value, since it stopped the clock when InitHandler returned). After it, a timeout during init prints:
REPORT RequestId: ...Duration: 1000.00 msBilled Duration: 1000 ms...
with no Init Duration at all, which diverges from the cloud REPORT line that RIE aims for parity with and can break anything parsing that field on a cold invoke.
The values needed are already valid here: awaitInitCompletion sets completedAt = time.Now() before closing done even on the reset-cancelled path, so initEnd is non-zero, and formatInitDuration already clamps to timeoutDuration. Dropping the gate yields the clamped init window rather than nothing:
case rapidcore.ErrInvokeTimeout:
initEnd, := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
printEndReports(invokePayload.ID, initDuration, memorySize, invokeStart, timeoutDuration)If omitting the field is deliberate, it is worth saying so explicitly — the reasoning in the PR discussion covered the Duration value for this branch, not the removal of Init Duration.
The core fix checks out: initContext.Wait() returns when the runtime calls /next, so Init Duration now spans runtime startup and user module loading. The earlier double-close, mutex-on-panic, and success-path Duration double-count findings are all genuinely resolved, and the completion signal is ordered before every blocking send in awaitInitCompletion, so I could not reproduce the unbounded-wait scenario in the current code.
|
Addressed in 8bc27a7. I restored Validation:
|
| return | ||
| case rapidcore.ErrInvokeTimeout: | ||
| initEnd := sandbox.AwaitInitCompletion() | ||
| initDuration := formatInitDuration(initStart, initEnd, timeoutDuration) |
There was a problem hiding this comment.
[BUG] The timeout branch still reports Duration from the pre-init invokeStart, so a cold invoke that times out counts the init window twice on the same REPORT line.
invokeStart is captured at line 134, immediately after startInitOnce kicks off init, and sandbox.Invoke blocks through the entire init phase. The success path compensates for this at lines 228-230 by rebasing invokeStart to initEnd; this branch does not. Since printEndReports clamps to timeoutDuration and formatInitDuration does too, a cold start that times out during init now prints:
REPORT RequestId: ...Init Duration: 1000.00 msDuration: 1000.00 msBilled Duration: 1000 ms...
for a request whose total wall time was ~1 s. Before this change Init Duration was sub-millisecond (it only measured sandbox.Init returning), so the overlap was invisible; now that it measures real init completion the two fields overlap fully. The same line also presents an init that was aborted by the timeout reset as a completed init — initEnd here is the moment CancelFlows tore init down, not the moment the runtime finished loading.
Making the timeout branch use the same rebase keeps both fields inside a single timeout window (Init Duration + Duration ≈ timeout):
case rapidcore.ErrInvokeTimeout:
initEnd := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
if !initStart.IsZero() && initEnd.After(invokeStart) {
invokeStart = initEnd
}
printEndReports(invokePayload.ID, initDuration, memorySize, invokeStart, timeoutDuration)If you would rather not report a duration for an init that never completed, the alternative is to suppress Init Duration on this branch instead — but the current combination of "full init duration" plus "full timeout duration" is the one outcome that cannot be reconciled with the elapsed time. Note that TestInvokeHandlerReportsInitDurationWhenInitTimesOut won't catch either variant today: it only asserts Init Duration is in (0, 1000] and that a Duration field is present, so it's worth asserting the relationship between the two values.
|
Addressed in fe7881b. The timeout path now rebases I expanded the regression coverage before pushing:
Validation:
Docker E2E with the Python 3.12 Lambda runtime:
|
| } | ||
| } | ||
|
|
||
| initEnd := sandbox.AwaitInitCompletion() |
There was a problem hiding this comment.
[GENERAL] The init-report block is now duplicated verbatim in two places — the timeout branch at lines 214-218 and here at 228-232:
initEnd := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
if !initStart.IsZero() && initEnd.After(invokeStart) {
invokeStart = initEnd
}
printEndReports(invokePayload.ID, initDuration, memorySize, invokeStart, timeoutDuration)This duplication is what produced the divergences already found in this PR's earlier revisions (the timeout branch printed a pre-init invokeStart while the success path rebased it, and later the two paths disagreed on whether Init Duration was emitted at all). Any future change to the REPORT line has to be applied twice, and the compiler cannot catch a missed one — the symptom is a silently wrong number in a log line, which is exactly the class of bug this PR fixes.
Consolidating both callers into one helper keeps the two REPORT paths structurally unable to drift:
// printInvokeReport emits the END/REPORT lines, attributing the init window to
// Init Duration and the remainder to Duration.
func printInvokeReport(sandbox Sandbox, invokeID string, initStart time.Time, invokeStart time.Time, memorySize string, timeoutDuration time.Duration) {
initEnd := sandbox.AwaitInitCompletion()
initDuration := formatInitDuration(initStart, initEnd, timeoutDuration)
if !initStart.IsZero() && initEnd.After(invokeStart) {
invokeStart = initEnd
}
printEndReports(invokeID, initDuration, memorySize, invokeStart, timeoutDuration)
}Both call sites then become a single line, and the timeout branch no longer needs to reassign invokeStart in the enclosing scope.
| durationMilliseconds, err := strconv.ParseFloat(durationMatches[1], 64) | ||
| require.NoError(t, err) | ||
| require.GreaterOrEqual(t, durationMilliseconds, float64(40)) | ||
| require.Less(t, durationMilliseconds, float64(90)) |
There was a problem hiding this comment.
[GENERAL] This assertion bounds a wall-clock measurement of a 50 ms sleep to under 90 ms, leaving only ~40 ms of headroom:
sandbox := &delayedInitSandbox{
initDelay: 50 time.Millisecond,
invokeDelay: 50 time.Millisecond,
invokeErr: rapidcore.ErrInvokeTimeout,
}
...
require.GreaterOrEqual(t, durationMilliseconds, float64(40))
require.Less(t, durationMilliseconds, float64(90))time.Sleep only guarantees a lower bound. On a CPU-throttled container or a loaded CI runner, a 50 ms sleep plus goroutine rescheduling, GC, and the pipe/regexp work in the same measured window routinely overshoots by tens of milliseconds, so this will fail intermittently on an unrelated change. The test's actual intent — that the invocation window excludes the init window — is fully captured by the lower bound plus the existing sum check against the 1 s timeout.
Dropping the tight ceiling keeps the assertion meaningful without the timing dependency:
require.GreaterOrEqual(t, durationMilliseconds, float64(40))
require.LessOrEqual(t, initDurationMilliseconds+durationMilliseconds, float64(1020))If an upper bound is still wanted to prove init time is not being double counted, comparing it against initDurationMilliseconds is more robust than a fixed millisecond ceiling, since both values scale together under load.
|
Addressed both cleanup comments in 8c18e35. The success and timeout paths now use one Validation before pushing:
|
| durationMilliseconds, err := strconv.ParseFloat(durationMatches[1], 64) | ||
| require.NoError(t, err) | ||
| require.GreaterOrEqual(t, durationMilliseconds, float64(40)) | ||
| require.Less(t, durationMilliseconds, initDurationMilliseconds*1.5) |
There was a problem hiding this comment.
[GENERAL] This assertion couples two independent wall-clock measurements with a 1.5x ratio, which makes the test load-sensitive:
sandbox := &delayedInitSandbox{
initDelay: 50 time.Millisecond,
invokeDelay: 50 time.Millisecond,
invokeErr: rapidcore.ErrInvokeTimeout,
}
...
require.GreaterOrEqual(t, durationMilliseconds, float64(40))
require.Less(t, durationMilliseconds, initDurationMilliseconds*1.5)initDurationMilliseconds measures the initDelay sleep and durationMilliseconds measures the invokeDelay sleep. Both nominally land at ~50 ms, so the upper bound is effectively ~75 ms against a 50 ms measurement — roughly 25 ms of headroom. time.Sleep only guarantees a lower bound, and overshoot is not correlated between the two sleeps: on a contended CI runner (or under -race) the second sleep can overshoot by more than the first, failing the assertion even though the reporting logic is correct. The GreaterOrEqual bounds are safe because sleeps never undershoot; only this relative upper bound is fragile.
The property this test actually cares about is that Init Duration and Duration cover disjoint windows rather than double-counting init. That can be asserted against measured total elapsed time instead of a fixed ratio:
start := time.Now()
InvokeHandler(response, request, sandbox, nil)
elapsed := float64(time.Since(start)) / float64(time.Millisecond)
...
// no double counting: the two reported windows must fit inside real elapsed time
require.LessOrEqual(t, initDurationMilliseconds+durationMilliseconds, elapsed)That keeps the regression coverage for the double-counting bug this PR fixes without depending on how precisely the two sleeps track each other.
|
Addressed in 427bcfb. The test now measures elapsed wall time around Validation:
|
1 participant
Issue #, if available:
Fixes #106
Description of changes:
RIE currently stops measuring init time as soon as
InitHandlerreturns. That only starts sandbox initialization; runtime startup and user module loading continue asynchronously, so the reported Init Duration can be much too small.This change waits for actual runtime initialization to finish before calculating the duration. It uses a separate completion signal instead of consuming the existing init result, so the current success and failure handling stays unchanged.
I tested this with:
go test ./...go test -race ./internal/lambda/rapidcore ./internal/lambda/rieBy submitting this pull request, I confirm that you can use, modify, copy, and redistribute this contribution, under the terms of your choice.