Relax some checks for win32 where time is not reliable on GA CI; add …

…print_percentage helper to avoid NaN

clients/drcachesim/tests/schedule_stats_test.cpp

@@ -197,7 +197,10 @@ test_basic_stats()
     assert(result.direct_switch_requests == 2);
     assert(result.waits == 3);
     assert(result.idle_microseconds == 0);
+    // XXX: For 32-bit Windows test VMs we see coarse time updates resulting in 0's.
+#if !(defined(WIN32) && !defined(X64))
     assert(result.cpu_microseconds > 0);
+#endif
     return true;
 }
 
@@ -256,10 +259,15 @@ test_idle()
     assert(result.waits == 3);
     assert(result.idles == 6);
     // It is hard to test wall-clock time precise values so we have sanity checks.
+    std::cerr << "got idle " << result.idle_microseconds << "us, cpu "
+              << result.cpu_microseconds << "us\n"; // NOCHECK
+    // XXX: For 32-bit Windows test VMs we see coarse time updates resulting in 0's.
+#if !(defined(WIN32) && !defined(X64))
     assert(result.idle_microseconds > 0);
     assert(result.idle_micros_at_last_instr > 0 &&
            result.idle_micros_at_last_instr <= result.idle_microseconds);
     assert(result.cpu_microseconds > 0);
+#endif
     return true;
 }
 

clients/drcachesim/tests/scheduler_unit_tests.cpp

@@ -935,7 +935,6 @@ test_synthetic()
         "..AA......CCC..EEE..GGGDDDFFFBBBCCC.EEE.AAA.GGG.";
     static const char *const CORE1_SCHED_STRING =
         "..BB......DDD..FFFABCCCEEEAAAGGGDDD.FFF.BBB.____";
-
     {
         // Test instruction quanta.
         std::vector<scheduler_t::input_workload_t> sched_inputs;
@@ -961,8 +960,31 @@ test_synthetic()
         for (int i = 0; i < NUM_OUTPUTS; i++) {
             std::cerr << "cpu #" << i << " schedule: " << sched_as_string[i] << "\n";
         }
-        assert(sched_as_string[0] == CORE0_SCHED_STRING);
-        assert(sched_as_string[1] == CORE1_SCHED_STRING);
+#if !(defined(WIN32) && !defined(X64))
+        // XXX: Win32 microseconds on test VMs are very coarse and stay the same
+        // for long periods.  Instruction quanta use wall-clock idle times, so
+        // the result is extreme variations here.  We try to adjust by handling
+        // any schedule with singleton 'A' and 'B', but in some cases on Win32
+        // we see the A and B delayed all the way to the very end where they
+        // are adjacent to their own letters.  We just give up on this test on Win32.
+        if (sched_as_string[0] != CORE0_SCHED_STRING ||
+            sched_as_string[1] != CORE1_SCHED_STRING) {
+            bool found_single_A = false, found_single_B = false;
+            for (int cpu = 0; cpu < NUM_OUTPUTS; ++cpu) {
+                for (size_t i = 1; i < sched_as_string[cpu].size() - 1; ++i) {
+                    if (sched_as_string[cpu][i] == 'A' &&
+                        sched_as_string[cpu][i - 1] != 'A' &&
+                        sched_as_string[cpu][i + 1] != 'A')
+                        found_single_A = true;
+                    if (sched_as_string[cpu][i] == 'B' &&
+                        sched_as_string[cpu][i - 1] != 'B' &&
+                        sched_as_string[cpu][i + 1] != 'B')
+                        found_single_B = true;
+                }
+            }
+            assert(found_single_A && found_single_B);
+        }
+#endif
     }
     {
         // Test time quanta.

clients/drcachesim/tools/schedule_stats.cpp

@@ -306,6 +306,21 @@ schedule_stats_t::parallel_shard_memref(void *shard_data, const memref_t &memref
     return true;
 }
 
+void
+schedule_stats_t::print_percentage(double numerator, double denominator,
+                                   const std::string &label)
+{
+    double fraction;
+    if (denominator == 0) {
+        if (numerator == 0)
+            fraction = 0.;
+        else
+            fraction = 1.;
+    } else
+        fraction = numerator / denominator;
+    std::cerr << std::setw(12) << std::setprecision(2) << 100 * fraction << label;
+}
+
 void
 schedule_stats_t::print_counters(const counters_t &counters)
 {
@@ -326,43 +341,33 @@ schedule_stats_t::print_counters(const counters_t &counters)
               << counters.voluntary_switches << " voluntary context switches\n";
     std::cerr << std::setw(12) << counters.direct_switches
               << " direct context switches\n";
-    if (counters.total_switches > 0) {
-        std::cerr << std::setw(12) << std::setprecision(2)
-                  << 100 *
-                (counters.voluntary_switches /
-                 static_cast<double>(counters.total_switches))
-                  << "% voluntary switches\n";
-        std::cerr << std::setw(12) << std::setprecision(2)
-                  << 100 *
-                (counters.direct_switches / static_cast<double>(counters.total_switches))
-                  << "% direct switches\n";
-    }
+    print_percentage(static_cast<double>(counters.voluntary_switches),
+                     static_cast<double>(counters.total_switches),
+                     "% voluntary switches\n");
+    print_percentage(static_cast<double>(counters.direct_switches),
+                     static_cast<double>(counters.total_switches), "% direct switches\n");
     std::cerr << std::setw(12) << counters.syscalls << " system calls\n";
     std::cerr << std::setw(12) << counters.maybe_blocking_syscalls
               << " maybe-blocking system calls\n";
     std::cerr << std::setw(12) << counters.direct_switch_requests
               << " direct switch requests\n";
     std::cerr << std::setw(12) << counters.waits << " waits\n";
     std::cerr << std::setw(12) << counters.idles << " idles\n";
-    std::cerr << std::setw(12) << std::setprecision(2)
-              << 100 *
-            (counters.instrs / static_cast<double>(counters.instrs + counters.idles))
-              << "% cpu busy by record count\n";
+    print_percentage(static_cast<double>(counters.instrs),
+                     static_cast<double>(counters.instrs + counters.idles),
+                     "% cpu busy by record count\n");
     std::cerr << std::setw(12) << counters.cpu_microseconds << " cpu microseconds\n";
     std::cerr << std::setw(12) << counters.idle_microseconds << " idle microseconds\n";
     std::cerr << std::setw(12) << counters.idle_micros_at_last_instr
               << " idle microseconds at last instr\n";
-    std::cerr << std::setw(12) << std::setprecision(2)
-              << 100 *
-            (counters.cpu_microseconds /
-             static_cast<double>(counters.cpu_microseconds + counters.idle_microseconds))
-              << "% cpu busy by time\n";
-    std::cerr << std::setw(12) << std::setprecision(2)
-              << 100 *
-            (counters.cpu_microseconds /
-             static_cast<double>(counters.cpu_microseconds +
-                                 counters.idle_micros_at_last_instr))
-              << "% cpu busy by time, ignoring idle past last instr\n";
+    print_percentage(
+        static_cast<double>(counters.cpu_microseconds),
+        static_cast<double>(counters.cpu_microseconds + counters.idle_microseconds),
+        "% cpu busy by time\n");
+    print_percentage(static_cast<double>(counters.cpu_microseconds),
+                     static_cast<double>(counters.cpu_microseconds +
+                                         counters.idle_micros_at_last_instr),
+                     "% cpu busy by time, ignoring idle past last instr\n");
 }
 
 bool

clients/drcachesim/tools/schedule_stats.h

@@ -134,6 +134,9 @@ class schedule_stats_t : public analysis_tool_t {
         uint64_t segment_start_microseconds = 0;
     };
 
+    void
+    print_percentage(double numerator, double denominator, const std::string &label);
+
     void
     print_counters(const counters_t &counters);