title: Lost Cycles on Intel? An inconsistency between rdtsc and CPU_CLK_UNHALTED.REF_TSC
body: <p>On recent CPUs (at least the last decade or so) Intel has offered three fixed-function hardware performance counters, in addition to various configurable performance counters. The three fixed counters are:</p>
  
  <pre><code>INST_RETIRED.ANY
  CPU_CLK_UNHALTED.THREAD
  CPU_CLK_UNHALTED.REF_TSC
  </code></pre>
  
  <p>The first counts retired instructions, the second number of actual cycles, and the last is what interests us. The description for Volume 3 of the Intel Software Developers manual is:</p>
  
  <blockquote>
    <p>This event counts the number of reference cycles at the TSC rate when
    the core is not in a halt state and not in a TM stop-clock state. The
    core enters the halt state when it is running the HLT instruction or
    the MWAIT instruction. This event is not affected by core frequency
    changes (e.g., P states) but counts at the same frequency as the time
    stamp counter. This event can approximate elapsed time while the core
    was not in a halt state and not in a TM stopclock state.</p>
  </blockquote>
  
  <p>So for a CPU-bound loop, I expect this value to be the same as the free-running TSC value read from <code>rdstc</code>, since they should diverge only for halted cycles instructions or what the "TM stopclock state" is.</p>
  
  <p>I test this with the following loop (the entire <a href="https://github.com/travisdowns/turbo-cycles-mystery" rel="noreferrer">standalone demo is available on github</a>):</p>
  
  <pre><code>for (int i = 0; i &lt; 100; i++) {
      PFC_CNT cnt[7] = {};
  
      int64_t start = nanos();
      PFCSTART(cnt);
      int64_t tsc =__rdtsc();
      busy_loop(CALIBRATION_LOOPS);
      PFCEND(cnt);
      int64_t tsc_delta   = __rdtsc() - tsc;
      int64_t nanos_delta = nanos() - start;
  
      printf(CPU_W "d" REF_W ".2f" TSC_W ".2f" MHZ_W ".2f" RAT_W ".6f\n",
              sched_getcpu(),
              1000.0 * cnt[PFC_FIXEDCNT_CPU_CLK_REF_TSC] / nanos_delta,
              1000.0 * tsc_delta / nanos_delta,
              1000.0 * CALIBRATION_LOOPS / nanos_delta,
              1.0 * cnt[PFC_FIXEDCNT_CPU_CLK_REF_TSC]/tsc_delta);
  }
  </code></pre>
  
  <p>The only important thing in the timed region is <code>busy_loop(CALIBRATION_LOOPS);</code> which is simply a tight loop of volatile stores, which <a href="https://godbolt.org/g/iw23Cg" rel="noreferrer">as compiled</a> by <code>gcc</code> and <code>clang</code> executes at one cycle per iteration on recent hardware:</p>
  
  <pre><code>void busy_loop(uint64_t iters) {
      volatile int sink;
      do {
          sink = 0;
      } while (--iters &gt; 0);
      (void)sink;
  }
  </code></pre>
  
  <p>The <code>PFCSTART</code> and <code>PFCEND</code> commands read the <code>CPU_CLK_UNHALTED.REF_TSC</code> counter using <a href="https://github.com/obilaniu/libpfc" rel="noreferrer">libpfc</a>. The <code>__rdtsc()</code> is an intrinsic that reads the TSC via the <code>rdtsc</code> instruction. Finally, we measure real time with <code>nanos()</code> which is simply:</p>
  
  <pre><code>int64_t nanos() {
      auto t = std::chrono::high_resolution_clock::now();
      return std::chrono::time_point_cast&lt;std::chrono::nanoseconds&gt;(t).time_since_epoch().count();
  }
  </code></pre>
  
  <p>Yes, I don't issue a <code>cpuid</code>, and things aren't interleaved in an exact way, but the calibration loop is a full second so such nanosecond-scale issues just get diluted down to more or less nothing.</p>
  
  <p>With TurboBoost enabled, here's are the first few results from a typical run on my i7-6700HQ Skylake CPU are:</p>
  
  <pre><code>CPU# REF_TSC   rdtsc Eff Mhz     Ratio
     0 2392.05 2591.76 2981.30  0.922946
     0 2381.74 2591.79 3032.86  0.918955
     0 2399.12 2591.79 3032.50  0.925660
     0 2385.04 2591.79 3010.58  0.920230
     0 2378.39 2591.79 3010.21  0.917663
     0 2355.84 2591.77 2928.96  0.908970
     0 2364.99 2591.79 2942.32  0.912492
     0 2339.64 2591.77 2935.36  0.902720
     0 2366.43 2591.79 3022.08  0.913049
     0 2401.93 2591.79 3023.52  0.926747
     0 2452.87 2591.78 3070.91  0.946400
     0 2350.06 2591.79 2961.93  0.906733
     0 2340.44 2591.79 2897.58  0.903020
     0 2403.22 2591.79 2944.77  0.927246
     0 2394.10 2591.79 3059.58  0.923723
     0 2359.69 2591.78 2957.79  0.910449
     0 2353.33 2591.79 2916.39  0.907992
     0 2339.58 2591.79 2951.62  0.902690
     0 2395.82 2591.79 3017.59  0.924389
     0 2353.47 2591.79 2937.82  0.908047
  </code></pre>
  
  <p>Here, <code>REF_TSC</code> is the fixed TSC performance counter as described above, and <code>rdtsc</code> is the result from the <code>rdtsc</code> instruction. <code>Eff Mhz</code> is the effective calculated true CPU frequency over the interval and is mostly shown for curiosity's sake and as a quick confirmation of how much turbo is kicking in. <code>Ratio</code> is the ratio of <code>REF_TSC</code> and <code>rdtsc</code> columns. I would expect this to be very close to 1, but in practice we see it hovers around 0.90 to 0.92 with a lot of variance (I've seen it as low as 0.8 on other runs).</p>
  
  <p>Graphically it looks something like this<sup>2</sup>:</p>
  
  <p><a href="https://i.stack.imgur.com/qUZvm.png" rel="noreferrer"><img src="https://i.stack.imgur.com/qUZvm.png" alt="PMU tsc vs rdstc"></a></p>
  
  <p>The <code>rdstc</code> call is returning nearly <em>exact</em> results<sup>1</sup>, while the PMU TSC counter is all over the place, sometimes almost as low as 2300 MHz.</p>
  
  <p>If I <strong>turn off turbo</strong>, however, the results are much more consistent:</p>
  
  <pre><code>CPU# REF_TSC   rdtsc Eff Mhz     Ratio
     0 2592.26 2592.25 2588.30  1.000000
     0 2592.26 2592.26 2591.11  1.000000
     0 2592.26 2592.26 2590.40  1.000000
     0 2592.25 2592.25 2590.43  1.000000
     0 2592.26 2592.26 2590.75  1.000000
     0 2592.26 2592.26 2590.05  1.000000
     0 2592.25 2592.25 2590.04  1.000000
     0 2592.24 2592.24 2590.86  1.000000
     0 2592.25 2592.25 2590.35  1.000000
     0 2592.25 2592.25 2591.32  1.000000
     0 2592.25 2592.25 2590.63  1.000000
     0 2592.25 2592.25 2590.87  1.000000
     0 2592.25 2592.25 2590.77  1.000000
     0 2592.25 2592.25 2590.64  1.000000
     0 2592.24 2592.24 2590.30  1.000000
     0 2592.23 2592.23 2589.64  1.000000
     0 2592.23 2592.23 2590.83  1.000000
     0 2592.23 2592.23 2590.49  1.000000
     0 2592.23 2592.23 2590.78  1.000000
     0 2592.23 2592.23 2590.84  1.000000
     0 2592.22 2592.22 2588.80  1.000000
  </code></pre>
  
  <p>Basically, the ratio is 1.000000 to <em>6 decimal places</em>. </p>
  
  <p>Graphically (with the Y axis scale forced to be the same as the previous graph):</p>
  
  <p><a href="https://i.stack.imgur.com/dspP3.png" rel="noreferrer"><img src="https://i.stack.imgur.com/dspP3.png" alt="PMU vs rdtsc (no turbo)"></a></p>
  
  <p>Now the code is just running a hot loop, and there should be no <code>hlt</code> or <code>mwait</code> instructions, certainly nothing that would imply a variation of more than 10%. I can't say <em>for sure</em> what "TM stop-clock cycles" are, but I'd bet they are "thermal management stop-clock cycles", a trick used to temporarily throttle the CPU when reaches its maximum temp. However, I looked at the integrated thermistor readings, and I never saw the CPU break 60C, far below the 90C-100C where termal management kicks in (I think). </p>
  
  <p>Any idea what this could be? Are there implied "halt cycles" to transition between different turbo frequencies? This definitely happens since the box is not quiet and so the turbo frequency is jumping up and down as other cores start and stop working on background stuff (the max turbo frequency depends directly on the number of active cores: on my box it is 3.5, 3.3, 3.2, 3.1 GHz for 1, 2, 3 or 4 cores active, respectively).</p>
  
  <hr>
  
  <p><sup>1</sup> In fact, for a while I really was getting <em>exact</em> results to two decimal places: <code>2591.97 MHz</code> - iteration after iteration. Then something changed and I'm not exactly sure what and there is a small variation of about 0.1% in the <code>rdstc</code> results. One possibility is gradual clock adjustment, being made by the Linux timing subsystem to bring the local crystal derived time inline with the <code>ntpd</code> determined time. Perhaps, it is just a crystal drift - the last graph above shows a steady increase in the measured period of <code>rdtsc</code> each second.</p>
  
  <p><sup>2</sup> The graphs don't correspond to the same runs as the the values show in the text because I'm not going to update the graphs each time I change the text output format. The qualitative behavior is essentially the same on every run, however.</p>