i#6938 sched migrate: Add scheduler statistics

clients/drcachesim/common/memtrace_stream.h

@@ -64,6 +64,26 @@ namespace drmemtrace { /**< DrMemtrace tracing + simulation infrastructure names
  */
 class memtrace_stream_t {
 public:
+    /**
+     * Statistics on the resulting schedule from interleaving and switching
+     * between the inputs.
+     */
+    enum schedule_statistic_t {
+        /** Count of switches between inputs. */
+        SCHED_STAT_SWITCHES,
+        /**
+         * Count of preempts due to time quantum expiration.  Includes instances
+         * of the quantum expiring but no switch happening.
+         */
+        SCHED_STAT_TIME_PREEMPTS,
+        /** Count of #TRACE_MARKER_TYPE_DIRECT_THREAD_SWITCH markers. */
+        SCHED_STAT_DIRECT_SWITCH_ATTEMPTS,
+        /** Count of #TRACE_MARKER_TYPE_DIRECT_THREAD_SWITCH attempts that succeeded. */
+        SCHED_STAT_DIRECT_SWITCH_SUCCESSES,
+        /** Count of statistic types. */
+        SCHED_STAT_TYPE_COUNT,
+    };
+
     /** Destructor. */
     virtual ~memtrace_stream_t()
     {
@@ -240,6 +260,17 @@ class memtrace_stream_t {
     {
         return false;
     }
+
+    /**
+     * Returns the value of the specified statistic for this output stream.
+     * The values for all output stream must be summed to obtain global counts.
+     * Returns -1 if statistics are not supported for this stream.
+     */
+    virtual int64_t
+    get_schedule_statistic(schedule_statistic_t stat) const
+    {
+        return -1;
+    }
 };
 
 /**

clients/drcachesim/scheduler/scheduler.cpp

@@ -664,6 +664,22 @@ scheduler_tmpl_t<RecordType, ReaderType>::stream_t::set_active(bool active)
  * Scheduler.
  */
 
+template <typename RecordType, typename ReaderType>
+scheduler_tmpl_t<RecordType, ReaderType>::~scheduler_tmpl_t()
+{
+    for (unsigned int i = 0; i < outputs_.size(); ++i) {
+        VPRINT(this, 1, "Stats for output #%d\n", i);
+        VPRINT(this, 1, "%-25s: %9" PRId64 "\n", "Switches",
+               outputs_[i].stats[memtrace_stream_t::SCHED_STAT_SWITCHES]);
+        VPRINT(this, 1, "%-25s: %9" PRId64 "\n", "Time preempts",
+               outputs_[i].stats[memtrace_stream_t::SCHED_STAT_TIME_PREEMPTS]);
+        VPRINT(this, 1, "%-25s: %9" PRId64 "\n", "Direct switch attempts",
+               outputs_[i].stats[memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_ATTEMPTS]);
+        VPRINT(this, 1, "%-25s: %9" PRId64 "\n", "Direct switch successes",
+               outputs_[i].stats[memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_SUCCESSES]);
+    }
+}
+
 template <typename RecordType, typename ReaderType>
 bool
 scheduler_tmpl_t<RecordType, ReaderType>::check_valid_input_limits(
@@ -2595,6 +2611,7 @@ scheduler_tmpl_t<RecordType, ReaderType>::set_cur_input(output_ordinal_t output,
     if (outputs_[output].prev_input >= 0) {
         std::lock_guard<std::mutex> lock(*inputs_[outputs_[output].prev_input].lock);
         prev_workload = inputs_[outputs_[output].prev_input].workload;
+        ++outputs_[output].stats[memtrace_stream_t::SCHED_STAT_SWITCHES];
     }
 
     std::lock_guard<std::mutex> lock(*inputs_[input].lock);
@@ -2895,6 +2912,8 @@ scheduler_tmpl_t<RecordType, ReaderType>::pick_next_input(output_ordinal_t outpu
                             target->blocked_time = 0;
                             target->unscheduled = false;
                         }
+                        ++outputs_[output].stats
+                              [memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_SUCCESSES];
                     } else if (unscheduled_priority_.find(target)) {
                         target->unscheduled = false;
                         unscheduled_priority_.erase(target);
@@ -2905,6 +2924,8 @@ scheduler_tmpl_t<RecordType, ReaderType>::pick_next_input(output_ordinal_t outpu
                                "@%" PRIu64 "\n",
                                output, prev_index, target->index,
                                inputs_[prev_index].reader->get_last_timestamp());
+                        ++outputs_[output].stats
+                              [memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_SUCCESSES];
                     } else {
                         // We assume that inter-input dependencies are captured in
                         // the _DIRECT_THREAD_SWITCH, _UNSCHEDULE, and _SCHEDULE markers
@@ -3056,6 +3077,7 @@ scheduler_tmpl_t<RecordType, ReaderType>::process_marker(input_info_t &input,
     case TRACE_MARKER_TYPE_DIRECT_THREAD_SWITCH: {
         if (!options_.honor_direct_switches)
             break;
+        ++outputs_[output].stats[memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_ATTEMPTS];
         memref_tid_t target_tid = marker_value;
         auto it = tid2input_.find(workload_tid_t(input.workload, target_tid));
         if (it == tid2input_.end()) {
@@ -3404,6 +3426,7 @@ scheduler_tmpl_t<RecordType, ReaderType>::next_record(output_ordinal_t output,
                     preempt = !need_new_input;
                     need_new_input = true;
                     input->instrs_in_quantum = 0;
+                    ++outputs_[output].stats[memtrace_stream_t::SCHED_STAT_TIME_PREEMPTS];
                 }
             } else if (options_.quantum_unit == QUANTUM_TIME) {
                 if (cur_time == 0 || cur_time < input->prev_time_in_quantum) {
@@ -3427,6 +3450,7 @@ scheduler_tmpl_t<RecordType, ReaderType>::next_record(output_ordinal_t output,
                     preempt = !need_new_input;
                     need_new_input = true;
                     input->time_spent_in_quantum = 0;
+                    ++outputs_[output].stats[memtrace_stream_t::SCHED_STAT_TIME_PREEMPTS];
                 }
             }
         }
@@ -3687,6 +3711,16 @@ scheduler_tmpl_t<RecordType, ReaderType>::is_record_kernel(output_ordinal_t outp
     return inputs_[index].reader->is_record_kernel();
 }
 
+template <typename RecordType, typename ReaderType>
+int64_t
+scheduler_tmpl_t<RecordType, ReaderType>::get_statistic(
+    output_ordinal_t output, memtrace_stream_t::schedule_statistic_t stat) const
+{
+    if (stat >= memtrace_stream_t::SCHED_STAT_TYPE_COUNT)
+        return -1;
+    return outputs_[output].stats[stat];
+}
+
 template <typename RecordType, typename ReaderType>
 typename scheduler_tmpl_t<RecordType, ReaderType>::stream_status_t
 scheduler_tmpl_t<RecordType, ReaderType>::set_output_active(output_ordinal_t output,

clients/drcachesim/scheduler/scheduler.h

@@ -1125,6 +1125,16 @@ template <typename RecordType, typename ReaderType> class scheduler_tmpl_t {
             return scheduler_->is_record_kernel(ordinal_);
         }
 
+        /**
+         * Returns the value of the specified statistic for this output stream.
+         * The values for all output stream must be summed to obtain global counts.
+         */
+        int64_t
+        get_schedule_statistic(schedule_statistic_t stat) const override
+        {
+            return scheduler_->get_statistic(ordinal_, stat);
+        }
+
     protected:
         scheduler_tmpl_t<RecordType, ReaderType> *scheduler_ = nullptr;
         int ordinal_ = -1;
@@ -1153,7 +1163,7 @@ template <typename RecordType, typename ReaderType> class scheduler_tmpl_t {
         : ready_priority_(static_cast<int>(get_time_micros()))
     {
     }
-    virtual ~scheduler_tmpl_t() = default;
+    virtual ~scheduler_tmpl_t();
 
     /**
      * Initializes the scheduler for the given inputs, count of output streams, and
@@ -1440,6 +1450,9 @@ template <typename RecordType, typename ReaderType> class scheduler_tmpl_t {
         bool at_eof = false;
         // Used for replaying wait periods.
         uint64_t wait_start_time = 0;
+        // Exported statistics.
+        std::vector<int64_t> stats =
+            std::vector<int64_t>(memtrace_stream_t::SCHED_STAT_TYPE_COUNT);
     };
 
     // Used for reading as-traced schedules.
@@ -1791,6 +1804,11 @@ template <typename RecordType, typename ReaderType> class scheduler_tmpl_t {
     // to kernel execution.
     bool
     is_record_kernel(output_ordinal_t output);
+
+    int64_t
+    get_statistic(output_ordinal_t output,
+                  memtrace_stream_t::schedule_statistic_t stat) const;
+
     ///////////////////////////////////////////////////////////////////////////
     // Support for ready queues for who to schedule next:
 

clients/drcachesim/tests/scheduler_unit_tests.cpp

@@ -130,6 +130,21 @@ memref_is_nop_instr(memref_t &record)
     return pc != nullptr && instr_is_nop(instr);
 }
 
+static void
+verify_scheduler_stats(scheduler_t::stream_t *stream, int64_t switches, int64_t preempts,
+                       int64_t direct_attempts, int64_t direct_successes)
+{
+    assert(stream->get_schedule_statistic(memtrace_stream_t::SCHED_STAT_SWITCHES) ==
+           switches);
+    assert(stream->get_schedule_statistic(memtrace_stream_t::SCHED_STAT_TIME_PREEMPTS) ==
+           preempts);
+    assert(stream->get_schedule_statistic(
+               memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_ATTEMPTS) == direct_attempts);
+    assert(stream->get_schedule_statistic(
+               memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_SUCCESSES) ==
+           direct_successes);
+}
+
 static void
 test_serial()
 {
@@ -1076,6 +1091,13 @@ test_synthetic()
         for (int i = 0; i < NUM_OUTPUTS; i++) {
             std::cerr << "cpu #" << i << " schedule: " << sched_as_string[i] << "\n";
         }
+        // Check scheduler stats.  # switches is the # of letter transitions; # preempts
+        // is the count of 3-letters-in-a-row sequences (3 is the quantum) except the
+        // last for an input (EOF doesn't count as a preempt).
+        verify_scheduler_stats(scheduler.get_stream(0), /*switches=*/10, /*preempts=*/6,
+                               /*direct_attempts=*/0, /*direct_successes=*/0);
+        verify_scheduler_stats(scheduler.get_stream(1), /*switches=*/11, /*preempts=*/8,
+                               /*direct_attempts=*/0, /*direct_successes=*/0);
 #ifndef WIN32
         // XXX: Windows microseconds on test VMs are very coarse and stay the same
         // for long periods.  Instruction quanta use wall-clock idle times, so
@@ -1256,6 +1278,11 @@ test_synthetic_time_quanta()
         check_next(cpu0, ++time, scheduler_t::STATUS_EOF);
         if (scheduler.write_recorded_schedule() != scheduler_t::STATUS_SUCCESS)
             assert(false);
+        // Check scheduler stats.
+        verify_scheduler_stats(scheduler.get_stream(0), /*switches=*/2, /*preempts=*/2,
+                               /*direct_attempts=*/0, /*direct_successes=*/0);
+        verify_scheduler_stats(scheduler.get_stream(1), /*switches=*/3, /*preempts=*/1,
+                               /*direct_attempts=*/0, /*direct_successes=*/0);
     }
     {
         replay_file_checker_t checker;
@@ -1377,6 +1404,13 @@ test_synthetic_with_timestamps()
         ".CC.C.II.IC.CC.F.FF.I.II.FF.F..BB.B.HH.HE.EE.BB.B.HH.H..DD.DA.AA.G.GG.DD.D._");
     assert(sched_as_string[1] ==
            ".FF.F.JJ.JJ.JJ.JJ.J.CC.C.II.I..EE.EB.BB.H.HH.EE.E..AA.A.GG.GD.DD.AA.A.GG.G.");
+    // Check scheduler stats.  # switches is the # of letter transitions; # preempts
+    // is the count of 3-letters-in-a-row sequences (3 is the quantum) except the
+    // last for an input (EOF doesn't count as a preempt).
+    verify_scheduler_stats(scheduler.get_stream(0), /*switches=*/14, /*preempts=*/11,
+                           /*direct_attempts=*/0, /*direct_successes=*/0);
+    verify_scheduler_stats(scheduler.get_stream(1), /*switches=*/14, /*preempts=*/9,
+                           /*direct_attempts=*/0, /*direct_successes=*/0);
 }
 
 static void
@@ -1461,6 +1495,13 @@ test_synthetic_with_priorities()
         ".BB.B.HH.HE.EE.BB.B.HH.H..FF.F.JJ.JJ.JJ.JJ.J.CC.C.II.I..DD.DA.AA.G.GG.DD.D._");
     assert(sched_as_string[1] ==
            ".EE.EB.BB.H.HH.EE.E..CC.C.II.IC.CC.F.FF.I.II.FF.F..AA.A.GG.GD.DD.AA.A.GG.G.");
+    // Check scheduler stats.  # switches is the # of letter transitions; # preempts
+    // is the count of 3-letters-in-a-row sequences (3 is the quantum) except the
+    // last for an input (EOF doesn't count as a preempt).
+    verify_scheduler_stats(scheduler.get_stream(0), /*switches=*/14, /*preempts=*/9,
+                           /*direct_attempts=*/0, /*direct_successes=*/0);
+    verify_scheduler_stats(scheduler.get_stream(1), /*switches=*/14, /*preempts=*/11,
+                           /*direct_attempts=*/0, /*direct_successes=*/0);
 }
 
 static void
@@ -1781,6 +1822,13 @@ test_synthetic_with_syscalls_multiple()
     assert(sched_as_string[0] ==
            "BHHHFFFJJJJJJBEEHHHFFFBCCCEEIIIDDDBAAAGGGDDDB________B_______");
     assert(sched_as_string[1] == "EECCCIIICCCBEEJJJHHHIIIFFFEAAAGGGBDDDAAAGGG________B");
+    // Check scheduler stats.  # switches is the # of letter transitions; # preempts
+    // is the count of 3-letters-in-a-row sequences (3 is the quantum) except the
+    // last for an input (EOF doesn't count as a preempt).
+    verify_scheduler_stats(scheduler.get_stream(0), /*switches=*/20, /*preempts=*/11,
+                           /*direct_attempts=*/0, /*direct_successes=*/0);
+    verify_scheduler_stats(scheduler.get_stream(1), /*switches=*/17, /*preempts=*/10,
+                           /*direct_attempts=*/0, /*direct_successes=*/0);
 }
 
 static void
@@ -4173,6 +4221,8 @@ test_direct_switch()
             std::cerr << "cpu #" << i << " schedule: " << sched_as_string[i] << "\n";
         }
         assert(sched_as_string[0] == CORE0_SCHED_STRING);
+        verify_scheduler_stats(scheduler.get_stream(0), /*switches=*/4, /*preempts=*/0,
+                               /*direct_attempts=*/3, /*direct_successes=*/2);
     }
     {
         // Test disabling direct switches.
@@ -4210,6 +4260,8 @@ test_direct_switch()
             std::cerr << "cpu #" << i << " schedule: " << sched_as_string[i] << "\n";
         }
         assert(sched_as_string[0] == CORE0_SCHED_STRING);
+        verify_scheduler_stats(scheduler.get_stream(0), /*switches=*/4, /*preempts=*/0,
+                               /*direct_attempts=*/0, /*direct_successes=*/0);
     }
 }
 
@@ -5353,7 +5405,6 @@ test_main(int argc, const char *argv[])
     test_kernel_switch_sequences();
     test_random_schedule();
     test_record_scheduler();
-
     dr_standalone_exit();
     return 0;
 }

clients/drcachesim/tools/schedule_stats.cpp

@@ -411,6 +411,27 @@ schedule_stats_t::aggregate_results(counters_t &total)
 {
     for (const auto &shard : shard_map_) {
         total += shard.second->counters;
+        // Sanity check against the scheduler's own stats, unless the trace
+        // is pre-scheduled or we're in core-serial mode where we don't have access
+        // to the separate output streams.
+        if (TESTANY(OFFLINE_FILE_TYPE_CORE_SHARDED, shard.second->filetype) ||
+            serial_stream_ != nullptr)
+            continue;
+        assert(shard.second->counters.total_switches ==
+               shard.second->stream->get_schedule_statistic(
+                   memtrace_stream_t::SCHED_STAT_SWITCHES));
+        // We can only find a lower bound on preempts as the preempt stat from
+        // the scheduler includes no-switch cases.
+        assert(shard.second->counters.total_switches -
+                   shard.second->counters.voluntary_switches <=
+               shard.second->stream->get_schedule_statistic(
+                   memtrace_stream_t::SCHED_STAT_TIME_PREEMPTS));
+        assert(shard.second->counters.direct_switch_requests ==
+               shard.second->stream->get_schedule_statistic(
+                   memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_ATTEMPTS));
+        assert(shard.second->counters.direct_switches ==
+               shard.second->stream->get_schedule_statistic(
+                   memtrace_stream_t::SCHED_STAT_DIRECT_SWITCH_SUCCESSES));
     }
 }