Record instructions retired alongside time in TIME_TRACE (depends on #928)

Debug/TimeProfiling.cpp

@@ -15,6 +15,8 @@
 #include <cstring>
 #include "Shell/Options.hpp"
 #include "Lib/Environment.hpp"
+#include "Lib/PerfInstructions.hpp"
+#include "Lib/Timer.hpp"
 
 namespace Shell {
 
@@ -23,10 +25,21 @@ using namespace Lib;
 
 TimeTrace::TimeTrace()
   : _root("[root]")
-  , _stack({ {&_root, Clock::now(), }, })
+  // -1 for the instruction counter: it does not exist yet, since this object is a
+  // static constructed long before Timer::reinitialise() opens it. See
+  // rebaseInstructionCounters(), which fixes this up once it does.
+  , _stack({ {&_root, Clock::now(), -1}, })
   , _enabled(false)
 {  }
 
+void TimeTrace::rebaseInstructionCounters()
+{
+  long long now = Timer::instructionCountAnyThread();
+  for (auto& x : _stack) {
+    get<2>(x) = now;
+  }
+}
+
 TimeTrace::ScopedTimer::ScopedTimer(const char* name)
   : ScopedTimer(TimeTrace::instance(), name)
 { }
@@ -52,12 +65,17 @@ TimeTrace::ScopedTimer::ScopedTimer(TimeTrace& trace, const char* name)
       children.push_back(std::make_unique<Node>(name));
       node = &*children.back();
     }
+    // Read the clock first and the instruction counter second, so that the
+    // instruction interval sits *inside* the time interval: the cost of the clock
+    // read itself is then excluded from the instruction count, while time keeps
+    // measuring everything, as it always did.
     auto start = Clock::now();
+    auto startInstr = Timer::instructionCount();
 #if VDEBUG
     _start = start;
 #endif
 
-    _trace._stack.push_back(std::make_pair(node, start));
+    _trace._stack.push_back(std::make_tuple(node, start, startInstr));
   }
 }
 
@@ -76,12 +94,16 @@ TimeTrace::ScopedTimer::~ScopedTimer()
   if (!_trace._enabled.load(std::memory_order_relaxed))
     return;
 
+  // mirror of the constructor: instructions innermost, time outermost
+  auto nowInstr = Timer::instructionCount();
   auto now = Clock::now();
   auto cur = _trace._stack.back();
   _trace._stack.pop_back();
   auto node = get<0>(cur);
   auto start = get<1>(cur);
-  node->measurements.add(now  - start);
+  auto startInstr = get<2>(cur);
+  node->measurements.add(now - start,
+      (startInstr < 0 || nowInstr < 0) ? 0 : nowInstr - startInstr);
   ASS_EQ(node->name, _name);
   ASS(start == _start);
 }
@@ -125,31 +147,55 @@ std::ostream& operator<<(std::ostream& out, TimeTrace::Duration const& self)
 // << duration_cast<microseconds>(total / cnt).count() << " μs"
 }
 
+/**
+ * An instruction count.
+ *
+ * Deliberately *not* scaled the way Duration is. A count is an exact integer and
+ * comparing two runs is the main thing one does with it, so rounding it to three
+ * significant figures would be self-defeating: printing 12345 as "12 k" gives the
+ * value 1000-instruction granularity, i.e. 8% of itself, which swamps the real
+ * run-to-run variation (which is nearer 0.001%).
+ */
+struct InstrCount { long long n; };
+
+std::ostream& operator<<(std::ostream& out, InstrCount const& self)
+{
+  if (self.n < 0) {
+    return out << "-";
+  }
+  return out << self.n;
+}
+
 struct TimeTrace::Node::NodeFormatOpts {
   // std::vector, not Lib::Stack: printing runs on the timer thread, see Node
   std::vector<const char*>& indent;
   Lib::Option<Duration> parentDuration;
   bool last;
   bool align;
+  // whether the hardware instruction counter was available for this run; when it
+  // was not we still print the field, as "-", so the format stays unconditional
+  bool haveInstr;
   Lib::Option<unsigned> nameWidth;
 
-  NodeFormatOpts child(Node& parent) 
-  { return { .indent = this->indent, 
-             .parentDuration = some(parent.totalDuration()), 
-             .last = false, 
+  NodeFormatOpts child(Node& parent)
+  { return { .indent = this->indent,
+             .parentDuration = some(parent.totalDuration()),
+             .last = false,
              .align = this->align,
+             .haveInstr = this->haveInstr,
              .nameWidth = align
                ? iterTraits(arrayIter(parent.children))
                    .map([](auto& c) { return unsigned(strlen(c->name)); })
                    .max()
                : none<unsigned>(),
                }; }
 
-  static NodeFormatOpts root(decltype(indent) indent) 
-  { return { .indent = indent, 
-             .parentDuration = Option<Duration>(), 
-             .last = true, 
+  static NodeFormatOpts root(decltype(indent) indent, bool haveInstr)
+  { return { .indent = indent,
+             .parentDuration = Option<Duration>(),
+             .last = true,
              .align = false,
+             .haveInstr = haveInstr,
              .nameWidth = none<unsigned>(),
            }; }
 };
@@ -205,8 +251,10 @@ void TimeTrace::Node::printPrettyRec(std::ostream& out, NodeFormatOpts& opts)
   } else {
     out << total / cnt;
   }
-  out << ", cnt: "  << msetw(6) << cnt
-      << ")" << std::endl;
+  out << ", cnt: "  << msetw(6) << cnt;
+  out << ", instr: " << msetw(12)
+      << InstrCount { opts.haveInstr ? measurements.instr() : -1 };
+  out << ")" << std::endl;
 
   // Order a local copy rather than sorting `children` in place: this is called on the
   // timer thread while the main thread may still be scanning and appending to
@@ -334,16 +382,28 @@ void TimeTrace::Node::flatten_(FlattenState& s)
 void TimeTrace::printPretty(std::ostream& out)
 {
 
+  // Credit the scopes that are still open with what they have run so far -- [root]
+  // among them, so this is what gives the top of the trace any numbers at all.
+  //
+  // NB: instructionCountAnyThread(), not the rdpmc reader: when a resource limit
+  // fires we are called on timer_thread, where rdpmc would read the wrong CPU's
+  // counter. This costs a syscall, but happens once per process.
   auto now = Clock::now();
+  auto nowInstr = Timer::instructionCountAnyThread();
+  bool haveInstr = nowInstr >= 0;
+  auto inFlightInstr = [&](long long startInstr) {
+    return (!haveInstr || startInstr < 0) ? 0 : nowInstr - startInstr;
+  };
+
   for (auto& x : _stack) {
     auto node = get<0>(x);
     auto start = get<1>(x);
-    node->measurements.add(now - start);
+    node->measurements.add(now - start, inFlightInstr(get<2>(x)));
   }
 
   auto& root = _tmpRoots.empty() ? _root : *_tmpRoots.back();
   std::vector<const char*> indent;
-  auto rootOpts = Node::NodeFormatOpts::root(indent);
+  auto rootOpts = Node::NodeFormatOpts::root(indent, haveInstr);
 
   out << "===== start of time trace =====" << std::endl;
   rootOpts.align = false;
@@ -361,7 +421,7 @@ void TimeTrace::printPretty(std::ostream& out)
   for (auto& x : _stack) {
     auto node = get<0>(x);
     auto start = get<1>(x);
-    node->measurements.remove(now - start);
+    node->measurements.remove(now - start, inFlightInstr(get<2>(x)));
   }
 
   if (!env.options->timeStatisticsFocus().empty()) {

Debug/TimeProfiling.hpp

@@ -112,22 +112,29 @@ class TimeTrace
   class Measurements {
     Duration _sum;
     unsigned _cnt;
+    // user-space instructions retired inside the measured blocks; 0 when the
+    // hardware counter is unavailable (see Lib/PerfInstructions.hpp)
+    long long _instrSum;
 
   public:
-    void add(Duration d) {
+    void add(Duration d, long long instr) {
       _cnt += 1;
       _sum += d;
+      _instrSum += instr;
     }
-    void remove(Duration d) {
+    void remove(Duration d, long long instr) {
       _cnt -= 1;
       _sum -= d;
+      _instrSum -= instr;
     }
     Duration sum() const { return _sum; }
     unsigned cnt() const { return _cnt; }
+    long long instr() const { return _instrSum; }
     Duration avg() const { return sum() / cnt(); }
     void extend(Measurements other) {
       _sum += other._sum;
       _cnt += other._cnt;
+      _instrSum += other._instrSum;
     }
   };
 
@@ -202,11 +209,23 @@ class TimeTrace
    * running main thread -- see Lib/Timer.cpp, limitReached().
    */
   void setEnabled(bool);
+
+  /**
+   * Re-base the instruction-counter readings of the currently open scopes -- in
+   * practice just [root], which is entered before the counter exists at all.
+   *
+   * Called by Timer::reinitialise() once the perf event has been opened and reset,
+   * so that [root] measures instructions from the counter's own origin rather than
+   * reporting none.
+   */
+  void rebaseInstructionCounters();
 private:
 
   Node _root;
   std::vector<Node*> _tmpRoots;
-  std::vector<std::tuple<Node*, TimePoint>> _stack;
+  // node, and the time / instruction-counter readings taken when it was entered
+  // (the instruction reading is -1 when the hardware counter is unavailable)
+  std::vector<std::tuple<Node*, TimePoint, long long>> _stack;
   // read on every TIME_TRACE scope and written by the timer thread
   std::atomic<bool> _enabled;
 };

Lib/PerfInstructions.hpp

@@ -0,0 +1,120 @@
+/*
+ * This file is part of the source code of the software program
+ * Vampire. It is protected by applicable
+ * copyright laws.
+ *
+ * This source code is distributed under the licence found here
+ * https://vprover.github.io/license.html
+ * and in the source directory
+ */
+/**
+ * @file PerfInstructions.hpp
+ * Reading the hardware "instructions retired" counter cheaply, from user space.
+ *
+ * Lib/Timer.cpp opens a PERF_COUNT_HW_INSTRUCTIONS event and reads it with
+ * read(PERF_FD), which costs a syscall (measured: ~560ns). That is fine for the
+ * timer thread's periodic limit check, but far too slow for a counter we want to
+ * sample on every TIME_TRACE scope.
+ *
+ * The fast path is to mmap the same file descriptor -- which yields a
+ * struct perf_event_mmap_page -- and read the counter register directly with the
+ * rdpmc instruction. Measured on the reference server: 8.9ns, against 27.5ns for
+ * clock_gettime(CLOCK_MONOTONIC), i.e. cheaper than the clock read the profiler
+ * already does.
+ *
+ * IMPORTANT: instructionCount() may only be called from the thread that
+ * Timer::reinitialise() ran on -- in practice, Vampire's main thread. rdpmc reads
+ * the performance counter register of whatever CPU the *caller* is running on,
+ * which for any other thread is not this event at all. The `index` check below
+ * catches the common case (returning -1 so the caller can fall back), but it is not
+ * a guarantee, so do not call this from timer_thread; use
+ * Timer::updateInstructionCount() there instead.
+ *
+ * This header pulls in <linux/perf_event.h>, so include it only where it is needed
+ * rather than from a widely-included header.
+ */
+
+#ifndef __PerfInstructions__
+#define __PerfInstructions__
+
+#include "Lib/Portability.hpp"
+
+#if VAMPIRE_PERF_EXISTS
+#include <cstdint>
+#include <linux/perf_event.h>
+#endif
+
+namespace Lib {
+namespace Timer {
+
+#if VAMPIRE_PERF_EXISTS
+
+/** The mmap'd metadata page of the perf event, or nullptr when unavailable.
+ *  Set up by Timer::reinitialise(). */
+extern perf_event_mmap_page *PERF_MMAP_PAGE;
+
+/** Whether instructionCount() can return anything meaningful at all. */
+bool instructionCountingAvailable();
+
+#if defined(__x86_64__) || defined(__i386__)
+inline uint64_t rdpmc(uint32_t counter)
+{
+  uint32_t low, high;
+  __asm__ __volatile__("rdpmc" : "=a"(low), "=d"(high) : "c"(counter));
+  return (static_cast<uint64_t>(high) << 32) | low;
+}
+#define VAMPIRE_RDPMC_EXISTS 1
+#endif
+
+#endif // VAMPIRE_PERF_EXISTS
+
+/**
+ * User-space instructions retired by this thread since the counter was reset,
+ * or -1 if that cannot be determined right now.
+ *
+ * Callers should treat -1 as "no measurement", not as a count.
+ */
+inline long long instructionCount()
+{
+#if VAMPIRE_PERF_EXISTS && defined(VAMPIRE_RDPMC_EXISTS)
+  perf_event_mmap_page *pc = PERF_MMAP_PAGE;
+  if (!pc)
+    return -1;
+
+  uint64_t count;
+  uint32_t seq, idx;
+  int64_t offset;
+  uint16_t width;
+
+  do {
+    // pc->lock is a seqlock the kernel bumps whenever it reschedules the event,
+    // which is exactly when index and offset change under us
+    seq = pc->lock;
+    __atomic_signal_fence(__ATOMIC_SEQ_CST);
+
+    idx = pc->index;      // 0: the event is not on this CPU's PMU at the moment
+    offset = pc->offset;  // what it counted during previous schedulings
+    width = pc->pmc_width;
+
+    if (!pc->cap_user_rdpmc || !idx || width == 0 || width > 64)
+      return -1;
+
+    count = rdpmc(idx - 1);
+    // the hardware register is narrower than 64 bits (typically 48); sign-extend
+    count <<= 64 - width;
+    count = static_cast<uint64_t>(static_cast<int64_t>(count) >> (64 - width));
+    count += offset;
+
+    __atomic_signal_fence(__ATOMIC_SEQ_CST);
+  } while (pc->lock != seq);
+
+  return static_cast<long long>(count);
+#else
+  return -1;
+#endif
+}
+
+} // namespace Timer
+} // namespace Lib
+
+#endif // __PerfInstructions__