Skip to content

[RDF] Fix the events/s figure in the progress bar's final line - #23065

Open
kutsibalci wants to merge 1 commit into
root-project:masterfrom
kutsibalci:rdf-progressbar-final-rate
Open

[RDF] Fix the events/s figure in the progress bar's final line#23065
kutsibalci wants to merge 1 commit into
root-project:masterfrom
kutsibalci:rdf-progressbar-final-rate

Conversation

@kutsibalci

Copy link
Copy Markdown
Contributor

This Pull request:

Changes or fixes:

ProgressHelper::PrintStatsFinal computes the events/s figure from a duration that has already been truncated to whole seconds:

const auto elapsedSeconds =
   std::chrono::duration_cast<std::chrono::seconds>(std::chrono::system_clock::now() - fBeginTime);
...
stream << "  " << std::scientific << std::setprecision(2) << (double)totalEvents / elapsedSeconds.count()
       << " evt/s";

duration_cast truncates toward zero, so elapsedSeconds.count() is an integer. Two consequences:

  • an event loop shorter than one second divides by zero and the line reads inf evt/s;
  • any longer loop is divided by a value that is up to one second too small, so the reported rate is always too high — by 100% for a run of just under two seconds.

Measured on this branch's parent, one 400-entry tree with a Filter that spins for a fixed time per entry, so the real rate is known:

real event loop measured rate master prints this PR prints
0.447 s 894 evt/s inf evt/s 8.94e+02 evt/s
2.408 s 166 evt/s 2.00e+02 evt/s (+20%) 1.66e+02 evt/s
5.607 s 71.3 evt/s 8.00e+01 evt/s (+12%) 7.13e+01 evt/s

The fix keeps the truncated value for the h:mm display, which wants whole seconds, and divides by the full-precision duration:

const std::chrono::duration<double> elapsed = std::chrono::system_clock::now() - fBeginTime;
const auto elapsedSeconds = std::chrono::duration_cast<std::chrono::seconds>(elapsed);

prettyPrint(elapsedSeconds) is unchanged, so the elapsed-time field prints exactly as before.

The in-run line is not affected and is not touched. PrintProgressAndStats takes its rate from EvtPerSec(), which averages the per-interval rates recorded in RecordEvtCountAndTime using a duration<double>. Only the final line had the integer division.

This is independent of #15323. That issue is about the numerator on the same line — ComputeTotalEvents() reports the size of the input dataset rather than what was processed. This PR deliberately does not touch the numerator; whichever way #15323 is decided, the denominator has to be a real duration.

Reproducer used for the table

The counts go to a file because the progress bar clears the terminal line with \r plus padding and swallows anything printed beside it.

#include <fstream>
#include <chrono>
void rate_repro()
{
   {
      TFile f("rate.root", "RECREATE");
      TTree t("t", "t");
      int x = 0;
      t.Branch("x", &x);
      for (int i = 0; i < 400; ++i) { x = i; t.Fill(); }
      t.Write();
   }
   std::ofstream out("rate.txt");

   auto run = [&out](const char *label, int spinUs) {
      ROOT::RDataFrame df("t", "rate.root");
      ROOT::RDF::Experimental::AddProgressBar(df);
      auto slow = df.Filter([spinUs](int) {
         auto stop = std::chrono::steady_clock::now() + std::chrono::microseconds(spinUs);
         while (std::chrono::steady_clock::now() < stop) {}
         return true;
      }, {"x"});
      auto t0 = std::chrono::steady_clock::now();
      auto n = *slow.Count();
      std::chrono::duration<double> wall = std::chrono::steady_clock::now() - t0;
      out << label << " entries=" << n << " wall=" << wall.count()
          << " true_evt_per_s=" << n / wall.count() << std::endl;
   };

   run("SHORT", 1000);
   run("MID", 6000);
   run("LONG", 14000);
}

Checklist:

  • tested changes locally
  • updated the docs (if necessary) — not necessary, no documented behaviour changes

Built from source at 6b57f8fc (ninja, gcc 13, -O3) and exercised through tree/dataframe/test/dataframe_helpers:

  • with only the test applied and the source unchanged, RDFHelpers.ProgressBarFinalRateIsFinite fails:
    the events/s figure is not finite: [Total elapsed time: 0:00m  processed files: 1  processed events: 100  inf evt/s]
    [  FAILED  ] RDFHelpers.ProgressBarFinalRateIsFinite
    
  • with the source change, it passes, and the whole suite is green: 33 tests from 2 test suites ran. [ PASSED ] 33 tests. — including ProgressBarRestorePrecision, which is the other test that inspects this stream.

This PR fixes # — no issue filed; happy to open one if you would rather track it that way.

AI disclosure

AI-assisted (Claude Code). The tool found the truncation while I was reading PrintStatsFinal for #15323, wrote the reproducer and the regression test, and drafted this description. I built ROOT from source, ran the reproducer and the test suite myself, and checked the before/after numbers in the table against the measured wall-clock rates. I have reviewed and understood the change and take responsibility for it.

PrintStatsFinal divided the event count by an elapsed time that had already
been truncated to whole seconds, so an event loop shorter than one second
divided by zero and printed `inf evt/s`, and a longer one reported a rate
quantised upwards by the truncation.

Keep the truncated value for the h:mm display and divide by the
full-precision duration instead. The in-run line is unaffected: it already
computes its rate from a duration<double> in RecordEvtCountAndTime.

Adds a regression test that fails on the current code with
`inf evt/s` and passes with this change.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Projects

None yet

Development

Successfully merging this pull request may close these issues.

3 participants