Repository navigation
Conversation
❌ ErrorsYour PR has failed checks. Please review the issues below and take necessary action before merging. 🚦 3 Pipeline jobs failed
Useful? React with 👍 / 👎 This comment will be updated automatically if new data arrives.🔗 Commit SHA: b231f95 | Docs | View more details | Give us feedback! |
|
The failure of "Lockfile Scan" job is unrelated. Will fix it in a separate PR. |
There was a problem hiding this comment.
🟢 Approval recommended
The instrumentation is scoped, consistent, and introduces no identified correctness issues.
0 open findings
What changed in this PR
Adds targeted debug timing for measurable cold-start initialization steps, improving startup performance diagnostics.
Changes:
- Adds a reusable duration-logging macro and cold-start tracing target.
- Instruments key initialization steps and assigns the existing readiness log to the same target.
| File | Description |
|---|---|
bottlecap/src/logger.rs |
Defines the timing macro and cold-start target. |
bottlecap/src/bin/bottlecap/main.rs |
Records durations across extension initialization. |
🧠 Review effort: Balanced
💡 Add a code-review agent skill or configure MCP servers for context-aware, tailored reviews. Learn more in the docs.
…he cargo-audit waiver (#1414) ## Problem The "Bottlecap (Rust) / Lockfile Scan" check fails on every branch, for example #1412 and an automated dd-trace-go upgrade branch. Trivy finds advisory GHSA-2mjx-qc3c-rqvc in `rustls` 0.23.43 and exits 1. `main` will fail the same way on its next run. ## Why this PR ignores the advisory The fix is in `rustls` 0.23.45, and we cannot use that version yet: - `rustls` 0.23.45 requires `aws-lc-rs` 1.18 or later. `aws-lc-rs` 1.18 uses AWS-LC-FIPS 4.x, which has no FIPS 140-3 certification yet. Our FIPS builds must use a certified crypto module. So the team reverted the bump to 0.23.45 in #1389, and #1390 pinned `aws-lc-rs` below 1.18. - The non-FIPS builds do not use `aws-lc-rs`, but both builds use the same `Cargo.lock`, so they get the same `rustls` version. - `datadog-fips` from `serverless-components` also requires `rustls` below 0.23.45. In a copy of `main` without our own cap, `cargo update -p rustls --precise 0.23.45` fails on that requirement. #1389 accepted this risk for `cargo-audit`, where the advisory has its RustSec ID, RUSTSEC-2026-0285. The GitHub advisory links to that RustSec page. The advisory says that the handshake transcript stays authenticated, so an attacker cannot change or complete a handshake. The effect is that a peer can send in plaintext some handshake messages that must be encrypted. ## Change Trivy uses its own ignore list, `.trivyignore.yaml`, and that list did not have the advisory. This PR adds GHSA-2mjx-qc3c-rqvc to it, with the same reason. It also adds a line to `bottlecap/.cargo/audit.toml` that names the Trivy entry. Then the person who removes one ignore after the certification also removes the other. `.github/workflows/vulnerability-scan.yml` reads the same file for its daily `Cargo.lock` scan, so that scan also skips the advisory. The daily image scans in that workflow do not read the file, and this PR does not change them. ## Testing ### Steps 1. Copy `bottlecap/Cargo.lock`, `bottlecap/Cargo.toml` and `.trivyignore.yaml` into an empty directory. 2. Run Trivy with the options of the CI step: `trivy fs --scanners vuln --ignorefile .trivyignore.yaml --ignore-unfixed --exit-code 1 --format table bottlecap`. 3. Do steps 1 and 2 for `main` and for this branch. ### Result | Check | Before (`main`, `469decc8`) | After (this branch) | | --- | --- | --- | | Trivy findings | 1, GHSA-2mjx-qc3c-rqvc in `rustls` 0.23.43 | 0 | | Trivy exit code | 1 | 0 | I used the local Trivy installation, not the version and database that CI uses. The CI run on this PR is the real check. 🤖 Generated with [Claude Code](https://claude.com/claude-code) Co-authored-by: Claude Opus 5.5 <noreply@anthropic.com>
Add debug logs under the "cold_start_duration" tracing target for each non-trivial step before the extension is ready, and move the existing "ready in" total under the same target. Steps were chosen from five cold starts of a probe build that timed every step. Steps that took under 0.1 ms in all runs were left out, except the two that do expensive work only when a feature is on: resolving additional endpoint secrets and creating the AppSec processor. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Replace the cold-start-only helper with a log_duration! macro in the library crate, so that later duration targets (trace flush, for example) reuse it from any module. A function cannot take the target, because tracing requires it to be a constant at each call site. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
776fb27 to
acf98dd
Compare
clifordshelton
left a comment
clifordshelton
left a comment
There was a problem hiding this comment.
Thanks for this! Per-step cold start timings will save us from building probe layers. I have two main requests, plus a few smaller ones inline.
1. Put all the timings in one JSON log line
Right now the numbers are only inside the message text, like Loading config took 1.609ms. To us that's easy to read, but to Datadog it's just a string. To put it on a chart, someone would have to write a custom parser (grok rule) for each step's message, and keep it in sync whenever a message changes. In practice that means people end up reading these logs one by one instead of graphing them.
If the timings are JSON fields instead, Datadog picks them up as numbers automatically. Then we can:
- Graph each step over time, e.g. average or p99 of
load_config_ms, and see right away if a release made a step slower. - Split the chart by runtime, region, architecture, or extension version to see where a slowdown happens.
- Sort or filter logs by a step's duration to find the slowest cold starts, e.g.
@cold_start.start_telemetry_listener_ms:>50. - Build a dashboard or monitor from them later without extra setup.
Instead, it would be better if we log all the step timings once as JSON fields on a single line and remove the separate per-step lines:
{"status":"debug",
"message":"DD_EXTENSION | DEBUG | Cold start step durations",
"cold_start":{"total_ms":21,"enable_logging_ms":5.84,"load_aws_config_ms":2.44,
"load_config_ms":1.61,"wait_for_register_ms":7.19,
"start_dogstatsd_ms":0.29,"start_telemetry_listener_ms":2.21}}With this, a chart of @cold_start.start_telemetry_listener_ms would have shown the 63.9 ms outlier in your test table. Make sure we use numbers for the values and not strings so that it parses correctly.
To do this, logger::Formatter needs to write these extra fields into the JSON. Today it only writes status and message and drops everything else.
2. Turn these logs off by default
Your numbers in #1413 show these lines were 33 of 117 debug lines across 3 cold starts. That's a lot of extra lines (~28%) for someone using DD_LOG_LEVEL=debug to debug something else.
How about we make the cold_start_duration target off by default, even when DD_LOG_LEVEL=debug. People who need the timings can turn them on with DD_LOG_LEVEL_BY_TARGET=cold_start_duration=debug from #1413. Let's use the same rule for future targets like trace_flush_duration.
| /// Logs at debug level how long `step` took since `start`, under a duration target such as | ||
| /// [`COLD_START_DURATION`]. A macro, because `tracing` needs the target as a constant. | ||
| #[macro_export] | ||
| macro_rules! log_duration { |
There was a problem hiding this comment.
With one summary line (see the main comment), we don't need a log per step. You can record each step's time into a struct instead, and log the struct once, right after "ready in". Use short snake_case names like load_config, since they become the JSON field names.
| ) | ||
| .await | ||
| .await; | ||
| log_duration!(COLD_START_DURATION, "Registering the extension", step_start); |
There was a problem hiding this comment.
We can remove this one because it's sort of a duplicate. Registration runs in the background while config loads, so this time overlaps with other steps. The wait at line 200 is the part that actually delays startup, so that's the one to keep.
| resolve_additional_endpoints_secrets(&mut lambda_config, &aws_config).await; | ||
| log_duration!( | ||
| COLD_START_DURATION, | ||
| "Resolving additional endpoint secrets", |
There was a problem hiding this comment.
This step only does real work (calling AWS to fetch the secret) when an additional endpoints secret ARN such as DD_ADDITIONAL_ENDPOINTS_SECRET_ARN is set. For everyone else it does nothing, which is why it showed ~0 ms in all three of your cold starts. If we always record it, most functions get a field that is always ~0 and never tells us anything. It's better to only record it when that ARN is set, so when it does show up, it's meaningful.
| }; | ||
| log_duration!( | ||
| COLD_START_DURATION, | ||
| "Creating the AppSec processor", |
There was a problem hiding this comment.
Same idea here. The AppSec processor only builds the WAF when DD_SERVERLESS_APPSEC_ENABLED=true, which is when it gets slow (38–41 ms in your probe build). When AppSec is off it's always ~0 ms, so let's only record it when AppSec is enabled.
| let mut flush_control = FlushControl::new(flush_strategy, config.flush_timeout); | ||
|
|
||
| debug!( | ||
| target: COLD_START_DURATION, |
There was a problem hiding this comment.
I'd keep "ready in" as it was, on the default target. This line has been around a long time, and support and engineers search for it when looking into cold starts. If it moves to the cold_start_duration target, then turning that target off (the default suggested in the main comment) would also hide "ready in". People would lose a line they rely on without realizing why. Keeping it on the default target means it still shows up with DD_LOG_LEVEL=debug like it does today, and the new timing line is the only thing the target controls.
Replace the per-step debug lines with one "Cold start step durations" line. Each step is a numeric field under a nested `cold_start` object, rounded to 2 decimals, so that Datadog can graph and filter each step. The steps are collected in a ColdStartDurations struct. It replaces the `start_time` parameter of extension_loop_active, so the function keeps 7 parameters. The registration task returns its duration with its result. logger::Formatter writes the fields of an event as JSON values, and nests a field named `group.key` under `group`. It used to drop every field except the message. No other log call passes fields. The summary line uses `event!`, because `debug!` in tracing 0.1.44 cannot parse dotted field names after `target:`. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Overview
The extension's cold start duration increases from time to time, and finding the cause takes a lot of engineering time. The extension logs only the total time to ready. So, to find which step became slower, we must add temporary timers and build a test layer.
This PR adds a debug log for each step of the extension's initialization that takes measurable time. Each log uses the
cold_start_durationtracing target. The existing "Datadog Next-Gen Extension ready in Nms" log also moves to this target, with the same message. The target lets #1413 turn on these logs alone, without the rest of the debug logs.The logs use a
log_duration!macro inlogger.rs, so later targets such astrace_flush_durationcan use it from any module. It is a macro and not a function, becausetracingrequires the target to be a constant at each call site.Example output for one cold start at
DD_LOG_LEVEL=debug:Which steps get a log
To select the steps, I made a probe build with a timer on every initialization step. Then I ran five cold starts with it. This PR keeps these steps:
DD_ADDITIONAL_ENDPOINTS_SECRET_ARN.DD_SERVERLESS_APPSEC_ENABLED=true, this step took 38 ms and 41 ms in two cold starts.The probe build also timed the steps that follow. Each one took less than 0.1 ms in all five runs, so this PR has no log for them:
Each step has its own timer, so the step durations do not add up to the total. For example, the registration request runs in a background task at the same time as config loading. "Waiting for extension registration" is the time that the main task waits for it.
Testing
Steps
ARCHITECTURE=arm64 FIPS=0 ./scripts/build_bottlecap_layer.shand publish it to the sandbox account.DD_LOG_LEVEL=debug.Result
All three cold starts logged each step. Durations in milliseconds:
The test function had no additional endpoint secrets and AppSec was off, so those two steps took almost no time. The AppSec measurement above came from the probe build. I did not test the additional endpoint secret path, and I did not test on amd64 or FIPS builds.
Next steps:
🤖 Generated with Claude Code