performance - Lost Cycles on Intel? An inconsistency between rdtsc and CPU_CLK_UNHALTED.REF_TSC

Question

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:

INST_RETIRED.ANY
CPU_CLK_UNHALTED.THREAD
CPU_CLK_UNHALTED.REF_TSC

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:

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.

So for a CPU-bound loop, I expect this value to be the same as the free-running TSC value read from rdstc, since they should diverge only for halted cycles instructions or what the "TM stopclock state" is.

I test this with the following loop (the entire standalone demo is available on github):

for (int i = 0; i < 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
",
            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);
}

The only important thing in the timed region is busy_loop(CALIBRATION_LOOPS); which is simply a tight loop of volatile stores, which as compiled by gcc and clang executes at one cycle per iteration on recent hardware:

void busy_loop(uint64_t iters) {
    volatile int sink;
    do {
        sink = 0;
    } while (--iters > 0);
    (void)sink;
}

The PFCSTART and PFCEND commands read the CPU_CLK_UNHALTED.REF_TSC counter using libpfc. The __rdtsc() is an intrinsic that reads the TSC via the rdtsc instruction. Finally, we measure real time with nanos() which is simply:

int64_t nanos() {
    auto t = std::chrono::high_resolution_clock::now();
    return std::chrono::time_point_cast<std::chrono::nanoseconds>(t).time_since_epoch().count();
}

Yes, I don't issue a cpuid, 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.

With TurboBoost enabled, here's are the first few results from a typical run on my i7-6700HQ Skylake CPU are:

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

Here, REF_TSC is the fixed TSC performance counter as described above, and rdtsc is the result from the rdtsc instruction. Eff Mhz 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. Ratio is the ratio of REF_TSC and rdtsc 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).

Graphically it looks something like this²:

The rdstc call is returning nearly exact results¹, while the PMU TSC counter is all over the place, sometimes almost as low as 2300 MHz.

If I turn off turbo, however, the results are much more consistent:

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

Basically, the ratio is 1.000000 to 6 decimal places.

Graphically (with the Y axis scale forced to be the same as the previous graph):

Now the code is just running a hot loop, and there should be no hlt or mwait instructions, certainly nothing that would imply a variation of more than 10%. I can't say for sure 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).

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).

---

¹ In fact, for a while I really was getting exact results to two decimal places: 2591.97 MHz - 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 rdstc results. One possibility is gradual clock adjustment, being made by the Linux timing subsystem to bring the local crystal derived time inline with the ntpd determined time. Perhaps, it is just a crystal drift - the last graph above shows a steady increase in the measured period of rdtsc each second.

² 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.

Answer 1

TL;DR

The discrepancy you are observing between RDTSC and REFTSC and is due to TurboBoost P-state transitions. During these transitions, most of the core, including the fixed-function performance counter REF_TSC, is halted for approximately 20000-21000 cycles (8.5us), but rdtsc continues at its invariant frequency. rdtsc is probably in an isolated power and clock domain because it is so important and because of its documented wallclock-like behaviour.

The RDTSC-REFTSC Discrepancy

The discrepancy manifests itself as a tendency for RDTSC to overcount REFTSC. The longer the program runs, the more positive the difference RDTSC-REFTSC tends to be. Over very long stretches it can mount as high as 1%-2% or even higher.

Of course, it has been observed by yourself already that the overcounting disappears when TurboBoost is disabled, which can be done as follows when using intel_pstate:

echo 1 > /sys/devices/system/cpu/intel_pstate/no_turbo

But that does not tell us for sure that TurboBoost is at fault for the discrepancy; It could be that the higher P-States enabled by TurboBoost eat up the available headroom, causing thermal throttling and halts.

Possible Throttling?

TurboBoost is a dynamic frequency and voltage scaling solution to opportunistically take advantage of headroom in the operating envelope (thermal or electrical). When possible, TurboBoost will then scale up the core frequency and voltage of the processor beyond their nominal value, thus improving performance at the expense of higher power consumption.

The higher power consumption of course increases core temperature and power consumption. Eventually, some sort of limit will be hit, and TurboBoost will have to crank down performance.

TM1 Thermal Throttling?

I began by investigating whether the Thermal Control Circuitry (TCC) for Thermal Monitor 1 (TM1) or 2 (TM2) was causing thermal throttling. TM1 reduces power consumption by inserting TM stop-clock cycles, and these are one of the conditions documented to lead to a halt of REFTSC. TM2, on the other hand, does not gate the clock; It only scales the frequency.

I modified libpfc() to enable me to read select MSRs, specifically the IA32_PACKAGE_THERM_STATUS and IA32_THERM_STATUS MSRs. Both contain a read-only Status and a read-write, hardware-sticky Log flag for various thermal conditions:

(The IA32_PACKAGE_THERM_STATUS register is substantially the same)

While some of these bits were on occasion set (especially when blocking laptop air vents!), they did not seem to correlate with RDTSC overcounting, which would reliably occur regardless of thermal status.

Hardware Duty Cycling? C-State Residency?

Digging elsewhere in the SDM for stop-clock-like hardware I happened upon HDC (Hardware Duty Cycle), a mechanism by which the OS can manually request the CPU to operate only a fixed proportion of the time; HDC hardware implements this by running the processor for 1-15 clock cycles per 16-clock period, and force-idling it for the remaining 15-1 clock cycles of that period.

HDC offers very useful registers, in particular the MSRs:

• IA32_THREAD_STALL: Counts the number of cycles stalled due to forced idling on this logical processor.
• MSR_CORE_HDC_RESIDENCY: Same as above but for the physical processor, counts cycles when one or more logical processors of this core are force-idling.
• MSR_PKG_HDC_SHALLOW_RESIDENCY: Counts cycles that the package was in C2 state and at least one logical processor was force-idling.
• MSR_PKG_HDC_DEEP_RESIDENCY: Counts cycles that the package was in a deeper (which precisely is configurable) C-state and at least one logical processor was force-idling.

For further details refer to the Intel SDM Volume 3, Chapter 14, §14.5.1 Hardware Duty Cycling Programming Interface.

But my i7-4700MQ 2.4 GHz CPU doesn't support HDC, and so that was that for HDC.

Other Sources of Throttling?

Digging some more still in the Intel SDM I found a very, very juicy MSR: MSR_CORE_PERF_LIMIT_REASONS. This register reports a large number of very useful Status and sticky Log bits:

690H MSR_CORE_PERF_LIMIT_REASONS - Package - Indicator of Frequency Clipping in Processor Cores

• Bit 0: PROCHOT Status
• Bit 1: Thermal Status
• Bit 4: Graphics Driver Status. When set, frequency is reduced below the operating system request due to Processor Graphics driver override.
• Bit 5: Autonomous Utilization-Based Frequency Control Status. When set, frequency is reduced below the operating system request because the processor has detected that utilization is low.
• Bit 6: Voltage Regulator Thermal Alert Status. When set, frequency is reduced below the operating system request due to a thermal alert from the Voltage Regulator.
• Bit 8: Electrical Design Point Status. When set, frequency is reduced below the operating system request due to electrical design point constraints (e.g. maximum electrical current consumption).
• Bit 9: Core Power Limiting Status. When set, frequency is reduced below the operating system request due to domain-level power limiting.
• Bit 10: Package-Level Power Limiting PL1 Status. When set, frequency is reduced below the operating system request due to package-level power limiting PL1.
• Bit 11: Package-Level Power Limiting PL2 Status. When set, frequency is reduced below the operating system request due to package-level power limiting PL2.
• Bit 12: Max Turbo Limit Status. When set, frequency is reduced below the operating system request due to multi-core turbo limits.
• Bit 13: Turbo Transition Attenuation Status. When set, frequency is reduced below the operating system request due to Turbo transition attenuation. This prevents performance degradation due to frequent operating ratio changes.
• Bit 16: PROCHOT Log
• Bit 17: Thermal Log
• Bit 20: Graphics Driver Log
• Bit 21: Autonomous Utilization-Based Frequency Control Log
• Bit 22: Voltage Regulator Thermal Alert Log
• Bit 24: Electrical Design Point Log
• Bit 25: Core Power Limiting Log
• Bit 26: Package-Level Power Limiting PL1 Log
• Bit 27: Package-Level Power Limiting PL2 Log
• Bit 28: Max Turbo Limit Log
• Bit 29: Turbo Transition Attenuation Log

pfc.ko now supports this MSR, and a demo prints which of these log bits is active. The pfc.ko driver clears the sticky bits on every read.

I reran your experiments while printing the bits, and my CPU reports under very heavy load (all 4 cores/8 threads active) several limiting factors, including Electrical Design Point and Core Power Limiting. The Package-Level PL2 and Max Turbo Limit bits are always set on my CPU for reasons unknown to me. I also saw on occasion Turbo Transition Attenuation.

While none of these bits exactly correlated with the presence of the RDTSC-REFTSC discrepancy, the last bit gave me food for thought. The mere existence of Turbo Transition Attenuation implies that switching P-States has a substantial-enough cost that it must be rate-limited with some hysteresis mechanism. When I could not find an MSR that counted these transitions, I decided to do the next best thing - I'll use the magnitude of the RDTSC-REFTSC overcount to characterize the performance implications of a TurboBoost transition.

Experiment

The experiment setup is as follows. On my i7-4700MQ CPU, nominal speed 2.4GHz and max Turbo Speed 3.4 GHz, I'll offline all cores except 0 (the boot processor) and 3 (a convenient victim core not numbered 0 and not a logical sibling of 0). We will then ask the intel_pstate driver to give us a package performance of no less than 98% and no higher than 100%; This constrains the processor to oscillate between the second-highest and highest P-states (3.3 GHz and 3.4 GHz). I do this as follows:

echo   0 > /sys/devices/system/cpu/cpu1/online
echo   0 > /sys/devices/system/cpu/cpu2/online
echo   0 > /sys/devices/system/cpu/cpu4/online
echo   0 > /sys/devices/system/cpu/cpu5/online
echo   0 > /sys/devices/system/cpu/cpu6/online
echo   0 > /sys/devices/system/cpu/cpu7/online
echo  98 > /sys/devices/system/cpu/intel_pstate/min_perf_pct
echo 100 > /sys/devices/system/cpu/intel_pstate/max_perf_pct

I ran the demo application for 10000 samples at

1000,     1500,     2500,     4000,     6300,
10000,    15000,    25000,    40000,    63000,
100000,   150000,   250000,   400000,   630000,
1000000,  1500000,  2500000,  4000000,  6300000,
10000000, 15000000, 25000000, 40000000, 63000000

nanoseconds per add_calibration() executed at nominal CPU frequency (multiply the numbers above by 2.4 to get the actual argument to add_calibration()).

Results

This produces logs that look like this (case of 250000 nanos):

CPU 0, measured CLK_REF_TSC MHz        :          2392.56
CPU 0, measured rdtsc MHz              :          2392.46
CPU 0, measured add   MHz              :          3286.30
CPU 0, measured XREF_CLK  time (s)     :       0.00018200
CPU 0, measured delta     time (s)     :       0.00018258
CPU 0, measured tsc_delta time (s)     :       0.00018200
CPU 0, ratio ref_tsc :ref_xclk         :      24.00131868
CPU 0, ratio ref_core:ref_xclk         :      33.00071429
CPU 0, ratio rdtsc   :ref_xclk         :      24.00032967
CPU 0, core CLK cycles in OS           :                0
CPU 0, User-OS transitions             :                0
CPU 0, rdtsc-reftsc overcount          :              -18
CPU 0, MSR_IA32_PACKAGE_THERM_STATUS   : 000000008819080a
CPU 0, MSR_IA32_PACKAGE_THERM_INTERRUPT: 0000000000000003
CPU 0, MSR_CORE_PERF_LIMIT_REASONS     : 0000000018001000
        PROCHOT
        Thermal
        Graphics Driver
        Autonomou