-
Notifications
You must be signed in to change notification settings - Fork 4.4k
profile_finish_ts actually describes profile start timestamp #22505
Description
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