profile_finish_ts actually describes profile start timestamp

[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

[sluongng]

Great spot. I think I misunderstood the ordering in my original PR. Im totally in favor of changing this field to profile_start_ts.

In term of precision, I don't mind changing the implementation to Date as long as the local timezone is removed. My original intention wass to create a field that could be easily consumed by processing scripts without having to worry about timezones.

side note: I think I worked on this while using Bazel+JDK8 with profiles being created from Linux and MacOS.

[timothyg-stripe]

I'm perfectly fine with the Instant-based implementation – I agree it's better than Date :) it's just that the new field is misnamed.

[timothyg-stripe]

Also, you can get better precision for the numeric field if you do finishDate.getEpochSecond() * 1e3 + finishDate.getNano() / 1e6 (or if you want an integer, finishDate.toEpochMilli()).

[sluongng]

@timothyg-stripe it seems like you have a fix for this ready. Do you want to submit a PR for this?

[timothyg-stripe]

Sorry, I don't think I'll have time to fix this.