Discrepancy between the elapsed time reported by Bazel and the profile duration

[tpudlik]

Description of the bug:

Consider this invocation: https://btx.cloud.google.com/invocations/7f6a08b3-606a-44f5-99aa-6521a88de319/log

The elapsed time as logged is a little over 7 minutes:

INFO: Elapsed time: 428.388s, Critical Path: 11.30s

However, when I upload the command.profile.gz (available in the Invocation Artifacts tab) to Perfetto, I see only about 4 minutes and 30 seconds of profile data: https://ui.perfetto.dev/#!/?s=b032b2b7f81070f86acb8f0fcfa831a0397898a5

@tjgq

Which category does this issue belong to?

Remote Execution

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

No response

Which operating system are you running Bazel on?

MacOS

What is the output of bazel info release?

development version

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

I'm using 1ff5af18d045e8f30a2a0367470db4e8225a785c, fetched by Bazelisk via .bazelversion.

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

No response

If this is a regression, please try to identify the Bazel commit where the bug was introduced with bazelisk --bisect.

No response

Have you found anything relevant by searching the web?

No response

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

No response

[tpudlik]

Hypothesis: This could be due to BES upload time. There's a chicken-and-egg problem: Bazel wants to upload the trace profile to the BEP, so it has to stop profiling before the upload. But I've seen BES upload take over 1 minute, so it's definitely on the right order.

However, it would be nice to verify this (e.g. figure out if BES upload time itself is recorded, and make sure the numbers indeed add up).