Skip to content

profile_finish_ts actually describes profile start timestamp #22505

@timothyg-stripe

Description

@timothyg-stripe

Description of the bug:

#17636 adds a new field in Bazel profiles called profile_finish_ts. But the name is a misnomer: it actually describes the starting timestamp of the profile.

Which category does this issue belong to?

Performance

What's the simplest, easiest way to reproduce this bug? Please provide a minimal example if possible.

$ date; bazel build --profile=test.json.gz //literally/anything; date
Wed May 22 19:00:08 UTC 2024
Starting local Bazel server and connecting to it...
...
Wed May 22 19:01:43 UTC 2024

$ gzip -cd test.json.gz | head -1
{"otherData":{"bazel_version":"release 7.1.2","build_id":"a8bf67d4-41dd-48af-8edf-0104076e739f","output_base":"/pay/cache/.cache/bazel/_bazel_timothyg/59fa07eaaf81cbcc62a646fca1339445","date":"2024-05-22T19:00:12.208166312Z","profile_finish_ts":1716404412000},"traceEvents":[

Which operating system are you running Bazel on?

Linux

What is the output of bazel info release?

release 7.1.2

If bazel info release returns development version or (@non-git), tell us how you built Bazel.

No response

What's the output of git remote get-url origin; git rev-parse HEAD ?

No response

Is this a regression? If yes, please try to identify the Bazel commit where the bug was introduced.

No response

Have you found anything relevant by searching the web?

#17636 says:

The name [date] is misleading since users could mistook it for profile start time, while it actually means the finish/end time, when Bazel calls the writer to serialize profiling data to disk.

But this is actually just wrong, at least in the current version of Bazel. The timestamp is captured near the beginning of JsonTraceFileWriter#run, which is called when the JsonTraceFileWriter thread starts running. Tracing through the code we see:

profiler.JsonTraceFileWriter#start (starts the JsonTraceFileWriter thread)
profiler.Profiler#start
runtime.BlazeRuntime#initProfiler
runtime.BlazeCommandDispatcher#execExclusively

The position of the call in runtime.BlazeCommandDispatcher#execExclusively is clearly before anything important has started.

Additionally, profile_finish_ts also lacks precision compared to the date field it's supposed to replace, being truncated to the nearest second while date has microsecond precision on modern Linux.

Any other information, logs, or outputs that you want to share?

No response

Metadata

Metadata

Assignees

No one assigned

    Labels

    P3We're not considering working on this, but happy to review a PR. (No assignee)help wantedSomeone outside the Bazel team could own thisteam-PerformanceIssues for Performance teamstype: bug

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions