[exegesis] Benchmark: provide optional progress meter / ETA

[lebedev.ri]

Summary

Now that --opcode-index=-1 is mostly stable,
and i can migrate off of my custom tooling that emulated it,
there comes a bit of confusion as to the status of the run.

It is normal for the single all-opcode run to take ~3 minutes,
and it's a bit more than one can be comfortable with,
without having some sort of visual indication of the progress.

Thus, i present:

$ ./bin/llvm-exegesis -mode=inverse_throughput --opcode-index=-1 --benchmarks-file=/dev/null --dump-object-to-disk=0 --measurements-print-progress --skip-measurements
<...>
XAM_Fp80: unsupported opcode: pseudo instruction
XBEGIN: Unsupported opcode: isPseudo/usesCustomInserter
XBEGIN_2: Unsupported opcode: isBranch/isIndirectBranch
XBEGIN_4: Unsupported opcode: isBranch/isIndirectBranch
XCH_F: unsupported second-form X87 instruction
Processing...   1%, ETA 02:10
Processing...   2%, ETA 02:03
Processing...   3%, ETA 02:00
Processing...   4%, ETA 01:57
Processing...   5%, ETA 01:54
Processing...   6%, ETA 01:53
Processing...   7%, ETA 01:51
Processing...   8%, ETA 01:50
Processing...   9%, ETA 01:49
Processing...  10%, ETA 01:48
Processing...  11%, ETA 01:46
Processing...  12%, ETA 01:45
Processing...  13%, ETA 01:44
Processing...  14%, ETA 01:43
Processing...  15%, ETA 01:42
Processing...  16%, ETA 01:42
Processing...  17%, ETA 01:41

As usual, the ETA estimation is statically-insignificant,
and is a lie/does not converge at least until 50% through.
It would be nice to have an actual progress indicator like in LIT,
but i'm not sure we have such a luxury in C++ form in LLVM codebase already.

[lebedev.ri]

s/RunningAverage/SimpleMovingAverage/

[lebedev.ri]

Now with a test.

[tschuett]

Did find you found this one:
https://reviews.llvm.org/D38416

[lebedev.ri]

In D139797#3987231, @tschuett wrote:

Did find you found this one:
https://reviews.llvm.org/D38416

I'm wary of patch feature creep and *exceptionally* wary of review sluggishness.
I don't think we are not allowed to add something to a subtool even it it would fit into elsewhere.

[RKSimon]

In D139797#3987258, @lebedev.ri wrote:

In D139797#3987231, @tschuett wrote:

Did find you found this one:
https://reviews.llvm.org/D38416

I'm wary of patch feature creep and *exceptionally* wary of review sluggishness.
I don't think we are not allowed to add something to a subtool even it it would fit into elsewhere.

Agreed - better to keep this inside exegesis until someone actually needs it someplace else - as long as the only exegesis dependency is the namespace it should be easier enough to move to Support (and change the namespace then),

[courbet]

llvm/tools/llvm-exegesis/lib/ProgressMeter.h

21

Please add a small descriptove comment so that one doe snot have to read the code, somehting like:

// Represents `\sum_{i=1..accumulated}{step_i} / accumulated`, where `step_i` is the value passed to the `i`-th call to `step()`, and `accumulated` is the total number of calls to `step()`.

42

Any reason not to inline this (and other members) ? That's a lot of repeated typing.

[courbet]

llvm/unittests/tools/llvm-exegesis/ProgressMeterTest.cpp

25

?

31

[nit] at top level, I this this would be better as a function rather than a variable of lambda type:

auto Pt(int i) {return PreprogrammedClock::time_point(PreprogrammedClock::duration(i)); }

[courbet]

llvm/tools/llvm-exegesis/lib/ProgressMeter.h

61

You should define what getAverage is when step() has never been called rather then crash here. Ar at least assert explicitly.

126

assert(NumStepsTotal > 0);

140–141

You're not using Unaccounted afterwards, so:

int Seconds = Unaccounted % 60;
int Minutes = Unaccounted / 60;

[lebedev.ri]

Thanks for taking a look!
Addressing review notes.

[lebedev.ri]

@courbet thank you for the review!

llvm/tools/llvm-exegesis/lib/ProgressMeter.h

+//===-- ProgressMeter.h -----------------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#ifndef LLVM_TOOLS_LLVM_EXEGESIS_PROGRESSMETER_H
+#define LLVM_TOOLS_LLVM_EXEGESIS_PROGRESSMETER_H
+
+#include "llvm/Support/Format.h"
+#include "llvm/Support/raw_ostream.h"
+#include <cassert>
+#include <chrono>
+#include <cmath>
+#include <optional>
+#include <type_traits>
+
+namespace llvm {
+namespace exegesis {
+
+/// Represents `\sum_{i=1..accumulated}{step_i} / accumulated`,
+/// where `step_i` is the value passed to the `i`-th call to `step()`,
+/// and `accumulated` is the total number of calls to `step()`.
+template <typename NumTy, typename DenTy = int> class SimpleMovingAverage {
+  NumTy Accumulated = NumTy(0);
+  DenTy Steps = 0;
+
+public:
+  SimpleMovingAverage() = default;
+
+  SimpleMovingAverage(const SimpleMovingAverage &) = delete;
+  SimpleMovingAverage(SimpleMovingAverage &&) = delete;
+  SimpleMovingAverage &operator=(const SimpleMovingAverage &) = delete;
+  SimpleMovingAverage &operator=(SimpleMovingAverage &&) = delete;
+
+  inline void step(NumTy Quantity) {
+    Accumulated += Quantity;
+    ++Steps;
+  }
+
+  inline NumTy getAccumulated() const { return Accumulated; }
+
+  inline DenTy getNumSteps() const { return Steps; }
+
+  template <typename AvgTy = NumTy>
+  inline std::optional<AvgTy> getAverage() const {
+    if (Steps == 0)
+      return std::nullopt;
+    return AvgTy(Accumulated) / Steps;
+  };
+};
+
+template <typename ClockTypeTy = std::chrono::steady_clock,
+          typename = std::enable_if_t<ClockTypeTy::is_steady>>
+class ProgressMeter {
+public:
+  using ClockType = ClockTypeTy;
+  using TimePointType = std::chrono::time_point<ClockType>;
+  using DurationType = std::chrono::duration<typename ClockType::rep,
+                                             typename ClockType::period>;
+  using CompetionPercentage = int;
+  using Sec = std::chrono::duration<double, std::chrono::seconds::period>;
+
+private:
+  raw_ostream &Out;
+  const int NumStepsTotal;
+  SimpleMovingAverage<DurationType> ElapsedTotal;
+
+public:
+  friend class ProgressMeterStep;
+  class ProgressMeterStep {
+    ProgressMeter *P;
+    const TimePointType Begin;
+
+  public:
+    inline ProgressMeterStep(ProgressMeter *P_)
+        : P(P_), Begin(P ? ProgressMeter<ClockType>::ClockType::now()
+                         : TimePointType()) {}
+
+    inline ~ProgressMeterStep() {
+      if (!P)
+        return;
+      const TimePointType End = ProgressMeter<ClockType>::ClockType::now();
+      P->step(End - Begin);
+    }
+
+    ProgressMeterStep(const ProgressMeterStep &) = delete;
+    ProgressMeterStep(ProgressMeterStep &&) = delete;
+    ProgressMeterStep &operator=(const ProgressMeterStep &) = delete;
+    ProgressMeterStep &operator=(ProgressMeterStep &&) = delete;
+  };
+
+  ProgressMeter(int NumStepsTotal_, raw_ostream &out_ = llvm::errs())
+      : Out(out_), NumStepsTotal(NumStepsTotal_) {
+    assert(NumStepsTotal > 0 && "No steps are planned?");
+  }
+
+  ProgressMeter(const ProgressMeter &) = delete;
+  ProgressMeter(ProgressMeter &&) = delete;
+  ProgressMeter &operator=(const ProgressMeter &) = delete;
+  ProgressMeter &operator=(ProgressMeter &&) = delete;
+
+private:
+  void step(DurationType Elapsed) {
+    assert((ElapsedTotal.getNumSteps() < NumStepsTotal) && "Step overflow!");
+    assert(Elapsed.count() >= 0 && "Negative time drift detected.");
+
+    auto [OldProgress, OldEta] = eta();
+    ElapsedTotal.step(Elapsed);
+    auto [NewProgress, NewEta] = eta();
+
+    if (NewProgress < OldProgress + 1)
+      return;
+
+    Out << format("Processing... %*d%%", 3, NewProgress);
+    if (NewEta) {
+      int SecondsTotal = std::ceil(NewEta->count());
+      int Seconds = SecondsTotal % 60;
+      int MinutesTotal = SecondsTotal / 60;
+
+      Out << format(", ETA %02d:%02d", MinutesTotal, Seconds);
+    }
+    Out << "\n";
+    Out.flush();
+  }
+
+  inline std::pair<CompetionPercentage, std::optional<Sec>> eta() const {
+    CompetionPercentage Progress =
+        (100 * ElapsedTotal.getNumSteps()) / NumStepsTotal;
+
+    std::optional<Sec> ETA;
+    if (std::optional<Sec> AverageStepDuration =
+            ElapsedTotal.template getAverage<Sec>())
+      ETA = (NumStepsTotal - ElapsedTotal.getNumSteps()) * *AverageStepDuration;
+
+    return {Progress, ETA};
+  }
+};
+
+} // namespace exegesis
+} // namespace llvm
+
+#endif

llvm/tools/llvm-exegesis/llvm-exegesis.cpp

 
 #include "lib/Analysis.h"
 #include "lib/BenchmarkResult.h"
 #include "lib/BenchmarkRunner.h"
 #include "lib/Clustering.h"
 #include "lib/Error.h"
 #include "lib/LlvmState.h"
 #include "lib/PerfHelper.h"
+#include "lib/ProgressMeter.h"
 #include "lib/SnippetFile.h"
 #include "lib/SnippetRepetitor.h"
 #include "lib/Target.h"
 #include "lib/TargetSelect.h"
 #include "llvm/ADT/StringExtras.h"
 #include "llvm/ADT/Twine.h"
 #include "llvm/MC/MCInstBuilder.h"
 #include "llvm/MC/MCObjectFileInfo.h"
cl::values(
         clEnumValN(exegesis::InstructionBenchmark::Duplicate, "duplicate",
                    "Duplicate the snippet"),
         clEnumValN(exegesis::InstructionBenchmark::Loop, "loop",
                    "Loop over the snippet"),
         clEnumValN(exegesis::InstructionBenchmark::AggregateMin, "min",
                    "All of the above and take the minimum of measurements")),
     cl::init(exegesis::InstructionBenchmark::Duplicate));
 
+static cl::opt<bool> BenchmarkMeasurementsPrintProgress(
+    "measurements-print-progress",
+    cl::desc("Produce progress indicator when performing measurements"),
+    cl::cat(BenchmarkOptions), cl::init(false));
+
 static cl::opt<bool> BenchmarkSkipMeasurements(
     "skip-measurements",
     cl::desc("do everything except actually performing the measurements"),
     cl::cat(BenchmarkOptions), cl::init(false));
 
 static cl::opt<unsigned>
     NumRepetitions("num-repetitions",
                    cl::desc("number of time to repeat the asm snippet"),
if (NumRepetitions == 0) {
     ExitOnErr.setBanner("llvm-exegesis: ");
     ExitWithError("--num-repetitions must be greater than zero");
   }
 
   // Write to standard output if file is not set.
   if (BenchmarkFile.empty())
     BenchmarkFile = "-";
 
+  std::optional<ProgressMeter<>> Meter;
+  if (BenchmarkMeasurementsPrintProgress)
+    Meter.emplace(Configurations.size());
   for (const BenchmarkCode &Conf : Configurations) {
+    ProgressMeter<>::ProgressMeterStep MeterStep(Meter ? &*Meter : nullptr);
     InstructionBenchmark Result = ExitOnErr(Runner->runConfiguration(
         Conf, NumRepetitions, LoopBodySize, Repetitors, DumpObjectToDisk));
     ExitOnFileError(BenchmarkFile, Result.writeYaml(State, BenchmarkFile));
   }
   exegesis::pfm::pfmTerminate();
 }
 
 // Prints the results of running analysis pass `Pass` to file `OutputFilename`

llvm/unittests/tools/llvm-exegesis/CMakeLists.txt

 set(exegesis_includes
   ${LLVM_MAIN_SRC_DIR}/tools/llvm-exegesis/lib
   )
 
 set(LLVM_LINK_COMPONENTS
   MC
   MCParser
   Object
   Support
   Symbolize
   )
 
 set(exegesis_sources
   BenchmarkRunnerTest.cpp
   ClusteringTest.cpp
   PerfHelperTest.cpp
+  ProgressMeterTest.cpp
   RegisterValueTest.cpp
   )
 
 set(exegesis_link_libraries LLVMExegesis)
 
 function(add_llvm_exegesis_unittest_includes)
   set(exegesis_includes ${exegesis_includes} ${ARGV} PARENT_SCOPE)
 endfunction()

llvm/unittests/tools/llvm-exegesis/ProgressMeterTest.cpp

+//===-- ProgressMeterTest.cpp -----------------------------------*- C++ -*-===//
+//
+// Part of the LLVM Project, under the Apache License v2.0 with LLVM Exceptions.
+// See https://llvm.org/LICENSE.txt for license information.
+// SPDX-License-Identifier: Apache-2.0 WITH LLVM-exception
+//
+//===----------------------------------------------------------------------===//
+
+#include "ProgressMeter.h"
+#include "gmock/gmock.h"
+#include "gtest/gtest.h"
+
+namespace llvm {
+namespace exegesis {
+
+namespace {
+
+struct PreprogrammedClock {
+  using duration = std::chrono::seconds;
+  using rep = duration::rep;
+  using period = duration::period;
+  using time_point = std::chrono::time_point<PreprogrammedClock, duration>;
+
+  static constexpr bool is_steady = true;
+
+  static time_point now() noexcept;
+};
+
+static int CurrentTimePoint = 0;
+auto Pt(int i) {
+  return PreprogrammedClock::time_point(PreprogrammedClock::duration(i));
+}
+static const std::array<const PreprogrammedClock::time_point, 10> TimePoints = {
+    Pt(0),  Pt(5),  Pt(6),  Pt(20), Pt(20),
+    Pt(35), Pt(37), Pt(75), Pt(77), Pt(100)};
+
+PreprogrammedClock::time_point PreprogrammedClock::now() noexcept {
+  time_point p = TimePoints[CurrentTimePoint];
+  ++CurrentTimePoint;
+  return p;
+}
+
+TEST(ProgressMeterTest, Integration) {
+  CurrentTimePoint = 0;
+  std::string TempString;
+  raw_string_ostream SS(TempString);
+  ProgressMeter<PreprogrammedClock> m(5, SS);
+  for (int i = 0; i != 5; ++i)
+    decltype(m)::ProgressMeterStep s(&m);
+  SS.flush();
+  ASSERT_EQ("Processing...  20%, ETA 00:20\n"
+            "Processing...  40%, ETA 00:29\n"
+            "Processing...  60%, ETA 00:23\n"
+            "Processing...  80%, ETA 00:18\n"
+            "Processing... 100%, ETA 00:00\n",
+            TempString);
+}
+
+} // namespace
+} // namespace exegesis
+} // namespace llvm