Skip to content

Commit 5b7ba90

Browse files
lym953claude
andcommitted
fix: emit cold-start invocation metric immediately if initStart already processed
Handles both orderings of the Invoke event and platform.initStart. If initStart has already resolved the durable tag by the time invocation #1 arrives, there's nothing to wait for, so emit the metric right away instead of holding it back (which previously would only be flushed at shutdown, since platform.initStart doesn't fire again). Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
1 parent 4272990 commit 5b7ba90

1 file changed

Lines changed: 68 additions & 3 deletions

File tree

bottlecap/src/lifecycle/invocation/processor.rs

Lines changed: 68 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -115,8 +115,8 @@ pub struct Processor {
115115
/// Timestamp of the cold-start invocation metric in On-Demand mode, held back until
116116
/// `platform.initStart` sets the durable tag so it's not missed on invocation #1.
117117
///
118-
/// This assumes `platform.initStart` always arrives after the Invoke event, which is what
119-
/// we've observed in production.
118+
/// Only used when `platform.initStart` hasn't already been processed by the time invocation
119+
/// #1 arrives; see `platform_init_start_processed`.
120120
pending_first_invocation_metric_timestamp: Option<i64>,
121121
/// Whether the first On-Demand invocation has already been seen.
122122
///
@@ -125,6 +125,14 @@ pub struct Processor {
125125
/// (an unordered, separate path from `on_invoke_event`), which would otherwise make later
126126
/// invocations look like cold starts too and hold back their metric indefinitely.
127127
first_on_demand_invocation_seen: bool,
128+
/// Whether `platform.initStart` has already been processed.
129+
///
130+
/// We've observed `platform.initStart` arrive after the Invoke event in production (the
131+
/// Extensions API's `next()` call is unbuffered, while Telemetry API delivery lags), which
132+
/// is why invocation #1's metric is normally held back. But that's not a hard ordering
133+
/// guarantee, so if `platform.initStart` has already set the durable tag by the time
134+
/// invocation #1 arrives, this flag lets us skip the hold-back and emit immediately.
135+
platform_init_start_processed: bool,
128136
}
129137

130138
impl Processor {
@@ -170,6 +178,7 @@ impl Processor {
170178
init_duration_metric_emitted: false,
171179
pending_first_invocation_metric_timestamp: None,
172180
first_on_demand_invocation_seen: false,
181+
platform_init_start_processed: false,
173182
}
174183
}
175184

@@ -182,6 +191,9 @@ impl Processor {
182191
if is_on_demand_cold_start {
183192
self.first_on_demand_invocation_seen = true;
184193
}
194+
// Only hold back if `platform.initStart` hasn't already resolved the durable tag.
195+
let should_hold_back_invocation_metric =
196+
is_on_demand_cold_start && !self.platform_init_start_processed;
185197

186198
// In Managed Instance mode, if awaiting the first invocation after init, find and update the empty context created on init start
187199
if self.aws_config.is_managed_instance_mode() && self.awaiting_first_invocation {
@@ -248,7 +260,7 @@ impl Processor {
248260
}
249261

250262
// Hold back the metric for a cold start in On-Demand mode; see `pending_first_invocation_metric_timestamp`.
251-
if is_on_demand_cold_start {
263+
if should_hold_back_invocation_metric {
252264
self.pending_first_invocation_metric_timestamp = Some(timestamp);
253265
} else {
254266
self.enhanced_metrics.increment_invocation_metric(timestamp);
@@ -373,6 +385,7 @@ impl Processor {
373385
{
374386
self.enhanced_metrics.set_durable_function_tag();
375387
}
388+
self.platform_init_start_processed = true;
376389
// Flush the held-back metric now that the durable tag (if any) has been set.
377390
self.flush_pending_first_invocation_metric();
378391

@@ -2184,6 +2197,58 @@ mod tests {
21842197
);
21852198
}
21862199

2200+
#[tokio::test]
2201+
async fn test_on_invoke_event_does_not_hold_metric_if_init_start_already_processed() {
2202+
let mut processor = setup();
2203+
2204+
// Simulate the reverse order: `platform.initStart` arrives before the Invoke event
2205+
// and reports a durable runtime.
2206+
processor.on_platform_init_start(
2207+
Utc::now(),
2208+
Some("python:3.14.DurableFunction.v6".to_string()),
2209+
);
2210+
2211+
// The durable tag is already known, so the metric must be emitted immediately
2212+
// instead of being held back.
2213+
let now: i64 = std::time::UNIX_EPOCH
2214+
.elapsed()
2215+
.expect("unable to poll clock, unrecoverable")
2216+
.as_secs()
2217+
.try_into()
2218+
.unwrap_or_default();
2219+
processor.on_invoke_event("req-1".to_string());
2220+
assert!(
2221+
processor
2222+
.pending_first_invocation_metric_timestamp
2223+
.is_none(),
2224+
"Expected the invocation metric to be emitted immediately, not held back"
2225+
);
2226+
2227+
let runtime = processor
2228+
.runtime
2229+
.clone()
2230+
.expect("runtime should have been resolved by on_invoke_event");
2231+
let ts = (now / 10) * 10;
2232+
let expected_tags = dogstatsd::metric::SortedTags::parse(&format!(
2233+
"cold_start:true,durable_function:true,runtime:{runtime}"
2234+
))
2235+
.ok();
2236+
let entry = processor
2237+
.enhanced_metrics
2238+
.aggr_handle
2239+
.get_entry_by_id(
2240+
crate::metrics::enhanced::constants::INVOCATIONS_METRIC.into(),
2241+
expected_tags,
2242+
ts,
2243+
)
2244+
.await
2245+
.unwrap();
2246+
assert!(
2247+
entry.is_some(),
2248+
"Expected the invocation metric to carry the durable_function:true tag"
2249+
);
2250+
}
2251+
21872252
#[tokio::test]
21882253
async fn test_init_duration_emitted_from_init_report() {
21892254
let mut processor = setup();

0 commit comments

Comments
 (0)