[SVLS-3697] Fix missing post runtime duration metrics and log values after a shutdown #25473
Conversation
DylanLovesCoffee
added
kind/bug
team/serverless
qa/done
Regression DetectorRegression Detector ResultsRun ID: ec8749ad-5fa8-40dc-a4ba-29adca51b1b1 Performance changes are noted in the perf column of each table:
No significant changes in experiment optimization goalsConfidence level: 90.00% There were no significant changes in experiment optimization goals at this confidence level and effect size tolerance.
|
| perf | experiment | goal | Δ mean % | Δ mean % CI |
|---|---|---|---|---|
| ➖ | tcp_syslog_to_blackhole | ingress throughput | +13.19 | [-9.50, +35.88] |
| ➖ | pycheck_1000_100byte_tags | % cpu utilization | +0.48 | [-4.35, +5.30] |
| ➖ | uds_dogstatsd_to_api_cpu | % cpu utilization | +0.24 | [-2.66, +3.14] |
| ➖ | otel_to_otel_logs | ingress throughput | +0.17 | [-0.19, +0.54] |
| ➖ | basic_py_check | % cpu utilization | +0.10 | [-2.57, +2.76] |
| ➖ | uds_dogstatsd_to_api | ingress throughput | +0.03 | [-0.17, +0.23] |
| ➖ | trace_agent_json | ingress throughput | -0.00 | [-0.01, +0.01] |
| ➖ | trace_agent_msgpack | ingress throughput | -0.00 | [-0.00, +0.00] |
| ➖ | tcp_dd_logs_filter_exclude | ingress throughput | -0.04 | [-0.09, +0.00] |
| ➖ | file_tree | memory utilization | -0.19 | [-0.31, -0.08] |
| ➖ | idle | memory utilization | -0.38 | [-0.42, -0.35] |
Explanation
A regression test is an A/B test of target performance in a repeatable rig, where "performance" is measured as "comparison variant minus baseline variant" for an optimization goal (e.g., ingress throughput). Due to intrinsic variability in measuring that goal, we can only estimate its mean value for each experiment; we report uncertainty in that value as a 90.00% confidence interval denoted "Δ mean % CI".
For each experiment, we decide whether a change in performance is a "regression" -- a change worth investigating further -- if all of the following criteria are true:
-
Its estimated |Δ mean %| ≥ 5.00%, indicating the change is big enough to merit a closer look.
-
Its 90.00% confidence interval "Δ mean % CI" does not contain zero, indicating that if our statistical model is accurate, there is at least a 90.00% chance there is a difference in performance between baseline and comparison variants.
-
Its configuration does not mark it "erratic".
| @@ -310,6 +310,15 @@ func (lc *LambdaLogsCollector) processMessage( | |||
| }) | |||
| lc.invocationEndTime = message.time | |||
| lc.executionContext.UpdateEndTime(message.time) | |||
|
|
|||
| // The state is saved when a shutdown event is received. A shutdown event can occur before the | |||
| // runtimeDone log message is received so we save the state again to properly store the end time | |||
There was a problem hiding this comment.
Just want to confirm there can't be a race condition here, where we save the context of the next invocation?
There was a problem hiding this comment.
Yup, shouldn't be the case here since we reset the isStateSaved bool to false at the start of the next invocation. So worse case we won't attempt to save the context
Test changes on VMUse this command from test-infra-definitions to manually test this PR changes on a VM: inv create-vm --pipeline-id=34843387 --os-family=ubuntu |
| @@ -1304,6 +1304,101 @@ func TestRuntimeMetricsMatchLogsProactiveInit(t *testing.T) { | |||
| assert.Len(t, timedMetrics, 0) | |||
| } | |||
|
|
|||
| func TestRuntimeMetricsOnTimeout(t *testing.T) { | |||
There was a problem hiding this comment.
test is flaky -> fix in-progress
Serverless Benchmark Results
tl;drUse these benchmarks as an insight tool during development.
What is this benchmarking?The The benchmark is run using a large variety of lambda request payloads. In the charts below, there is one row for each event payload type. How do I interpret these charts?The charts below comes from The benchstat docs explain how to interpret these charts.
I need more helpFirst off, do not worry if the benchmarks are failing. They are not tests. The intention is for them to be a tool for you to use during development. If you would like a hand interpreting the results come chat with us in Benchmark stats |
Codecov ReportAttention: Patch coverage is
Additional details and impacted files@@ Coverage Diff @@
## main #25473 +/- ##
===========================================
+ Coverage 45.00% 73.15% +28.15%
===========================================
Files 2314 58 -2256
Lines 266463 5298 -261165
===========================================
- Hits 119919 3876 -116043
+ Misses 136986 1251 -135735
+ Partials 9558 171 -9387
Flags with carried forward coverage won't be shown. Click here to find out more. ☔ View full report in Codecov by Sentry. |
What does this PR do?
Fixes a
0value foraws.lambda.enhanced.post_runtime_durationmetric and a0value for theRuntime DurationandPost Runtime Durationin the Extension's REPORT log.BEFORE:
AFTER:
Motivation
https://datadoghq.atlassian.net/browse/SVLS-3697
Related to #18933
After some investigation, I found that during a SHUTDOWN event caused by a timeout, we would save the invocation's execution context to disk before we processed the
platform.runtimeDonelog from which we get the runtime'sendTime. Then we process theplatform.reportlog where we generateaws.lambda.enhanced.post_runtime_durationand theREPORTlog, but we fail to calculate the durations due to a zero value for theendTime.Rough visual timeline of the issue:
Additional Notes
Possible Drawbacks / Trade-offs
Describe how to test/QA your changes
Updated unit tests and rolled out to self-monitoring apps