Progress updates become ever more scarce without terminal cursor control

[tom-cnops]

Description of the bug:

The docs for the option --progress_report_interval=n read:
This option sets the reporting frequency, progress will be printed every n seconds.

But this seems to not work when Bazel can not update the terminal output in place. The delay between progress updates grows linearly as time increases.

I had a quick look at the code and according to the comments this was implemented intentionally. The commit message also mentions this.

The behavior as described in the docs would be nice for us, as then we can automatically check whether Bazel is still running correctly for some very long-running actions. There also seems no real benefit to increasing the update interval to 10 minutes or more, as we have encountered.

Of course, if I'm missing why this works this way, it would still be useful if the docs could be updated with the behavior for non-overwritable output.

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

Run a test that just sleeps and redirect stderr to a file.

cat > sleep.sh << 'EOF'
#!/usr/bin/env bash
sleep 10000
EOF
chmod +x sleep.sh
cat > BUILD.bazel << 'EOF'
sh_test(
    name = "sleep_test",
    size = "enormous",
    srcs = ["sleep.sh"],
)
EOF
touch WORKSPACE
bazel test //:sleep_test --progress_report_interval=2 2> output.txt

Initially the progress updates will be written every 2 seconds as requested, but after 40 seconds the delay between them will start increasing noticeably.

Which operating system are you running Bazel on?

Ubuntu 20.04

What is the output of bazel info release?

release 5.2.0

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 master; git rev-parse HEAD ?

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

[sgowroji]

Hello @tom-cnops, Could you please provide complete steps to reproduce the above issue with code repo. Thanks!

[tom-cnops]

Hi @sgowroji, I updated the original post. The minimal example can also be found at at https://github.com/tom-cnops/progress-minimal-example.

Running bazel test //:sleep_test --progress_report_interval=2 2> output.txt writes to the output file like below:

After five minutes the delay between progress messages is ~45 seconds, while I'd expect a progress message every 2 seconds in this case.

...

[1 / 2] Testing //:sleep_test; 1s linux-sandbox
[1 / 2] Testing //:sleep_test; 3s linux-sandbox
[1 / 2] Testing //:sleep_test; 6s linux-sandbox
[1 / 2] Testing //:sleep_test; 8s linux-sandbox
[1 / 2] Testing //:sleep_test; 10s linux-sandbox
[1 / 2] Testing //:sleep_test; 12s linux-sandbox
[1 / 2] Testing //:sleep_test; 14s linux-sandbox
[1 / 2] Testing //:sleep_test; 17s linux-sandbox
[1 / 2] Testing //:sleep_test; 19s linux-sandbox
[1 / 2] Testing //:sleep_test; 22s linux-sandbox
[1 / 2] Testing //:sleep_test; 26s linux-sandbox
[1 / 2] Testing //:sleep_test; 30s linux-sandbox
[1 / 2] Testing //:sleep_test; 36s linux-sandbox
[1 / 2] Testing //:sleep_test; 42s linux-sandbox
[1 / 2] Testing //:sleep_test; 50s linux-sandbox
[1 / 2] Testing //:sleep_test; 58s linux-sandbox
[1 / 2] Testing //:sleep_test; 67s linux-sandbox
[1 / 2] Testing //:sleep_test; 77s linux-sandbox
[1 / 2] Testing //:sleep_test; 88s linux-sandbox
[1 / 2] Testing //:sleep_test; 102s linux-sandbox
[1 / 2] Testing //:sleep_test; 118s linux-sandbox
[1 / 2] Testing //:sleep_test; 136s linux-sandbox
[1 / 2] Testing //:sleep_test; 158s linux-sandbox
[1 / 2] Testing //:sleep_test; 182s linux-sandbox
[1 / 2] Testing //:sleep_test; 210s linux-sandbox
[1 / 2] Testing //:sleep_test; 242s linux-sandbox
[1 / 2] Testing //:sleep_test; 280s linux-sandbox
[1 / 2] Testing //:sleep_test; 324s linux-sandbox

[larsrc-google]

show_progress_rate_limit is also involved. The option description says it's a minimum time. The docs say it's a fixed interval.

[sgowroji]

Hello @tom-cnops, Did you get chance to check the above comment. Thanks!

[tom-cnops]

As far as I can see show_progress_rate_limit does indeed set a minimum time. The docs could perhaps be formulated a bit better, but they also seem to suggest a minimum to me?

But this seems mostly orthogonal to the issue of the interval increasing if there is no cursor control:

• If progress_report_interval is longer than show_progress_rate_limit, the latter basically does nothing.
• If progress_report_interval is shorter, then it will initially be overridden by show_progress_rate_limit, but the drift still happens and the time between progress messages will increase with ~15s per 100 seconds.

[meteorcloudy]

Looks like the performance team has more expertise on this, so reassigning to team-Performance

[larsrc-google]

"expertise" is such a strong word. :)