topic You might want to monitor in Software Tuning, Performance Optimization & Platform Monitoring

__rdtscp had been interrupted by something

wei__peng — Tue, 16 Jul 2019 10:22:34 GMT

Hello everyone, there are a situation really confused me.

We are using "__rdtscp" to record a timestamp for performance evaluation.

Os: "Linux CentOS Linux release 7.6.1810 (Core)".

Kernel: "3.10.0-957.12.1.el7.x86_64".

CPU is "Intel(R) Xeon(R) CPU E3-1225 v3 @ 3.20GHz" , already set to "No turbo" mode in bios.

Boot loading params is "BOOT_IMAGE=/boot/vmlinuz-3.10.0-957.12.1.el7.x86_64 root=UUID=1acb82ac-5687-44d5-a50e-2bef16102958 ro crashkernel=auto intel_pstate=disable idle=poll nohz=off processor.max_cstate=0 intel_idle.max_cstate=0 pcie_aspm=performance mce=ignore_ce ipmi_si.force_kipmi=0 nmi_watchdog=0 hpet=disabled noht nohz=on nohalt nosoftlockup isolcpus=2,3 rhgb quiet LANG=en_US.UTF-8"

Our program has been bound to core 2 and 3, and the testing thread is running only on core 3 which no other threads will run at.

Code as below:

       int64_t       start = __rdtscp(&core);
       int64_t       end = __rdtscp(&core);
       int64_t       diff = end - start;

Consecutively reading TSC two times, subsequently calculating the distribution of this diff.

But we get result as below:

Average time is :34
test for 221s
Least value is :24
Below 3000 is 0.99999
Stats period, Diff
0-10 tick, 0
10-20 tick, 0
20-30 tick, 3134491945
30-40 tick, 1859915250
40-50 tick, 1694477174
50-60 tick, 0
60-70 tick, 0
70-80 tick, 0
80-90 tick, 1
90-100 tick, 0
100-110 tick, 0
110-120 tick, 0

...

lots of zero

...

3440-3450 tick, 0
3450-3460 tick, 0
3460-3470 tick, 3
3470-3480 tick, 7
3480-3490 tick, 41
3490-3500 tick, 44
3500-3510 tick, 143
3510-3520 tick, 351
3520-3530 tick, 745
3530-3540 tick, 669
3540-3550 tick, 1485
3550-3560 tick, 1638
3560-3570 tick, 2980
3570-3580 tick, 3467
3580-3590 tick, 3283
3590-3600 tick, 2227
3600-3610 tick, 1837
3610-3620 tick, 1398
3620-3630 tick, 882
3630-3640 tick, 991
3640-3650 tick, 542
3650-3660 tick, 313
3660-3670 tick, 247
3670-3680 tick, 273
3680-3690 tick, 200
3690-3700 tick, 276
3700-3710 tick, 451
3710-3720 tick, 320
3720-3730 tick, 199
3730-3740 tick, 188
3740-3750 tick, 195
3750-3760 tick, 159
3760-3770 tick, 260
3770-3780 tick, 494
3780-3790 tick, 373
3790-3800 tick, 406
3800-3810 tick, 567
3810-3820 tick, 586
3820-3830 tick, 661
3830-3840 tick, 772
3840-3850 tick, 1374
3850-3860 tick, 999
3860-3870 tick, 1425
3870-3880 tick, 1328
3880-3890 tick, 1639
3890-3900 tick, 1409
3900-3910 tick, 1431
3910-3920 tick, 1695
3920-3930 tick, 1803
3930-3940 tick, 1781
3940-3950 tick, 1486
3950-3960 tick, 2401
3960-3970 tick, 1620
3970-3980 tick, 1125
3980-3990 tick, 1150
3990-4000 tick, 1403
4000-4010 tick, 969
4010-4020 tick, 996
4020-4030 tick, 1306
4030-4040 tick, 743
4040-4050 tick, 470
4050-4060 tick, 731
4060-4070 tick, 727
4070-4080 tick, 531
4080-4090 tick, 680
4090-4100 tick, 874
4100-4110 tick, 353
4110-4120 tick, 309
4120-4130 tick, 372
4130-4140 tick, 287
4140-4150 tick, 250
4150-4160 tick, 267
4160-4170 tick, 289
4170-4180 tick, 140
4180-4190 tick, 174
4190-4200 tick, 131
4200-4210 tick, 170
4210-4220 tick, 157
4220-4230 tick, 179
4230-4240 tick, 163

All of sudden, above 3500 ticks, there are lots of figs.

In theory, this shouldn't happen like this. Just like had been interrupted by something, but I had already isolated this core and disabled turbo mode and other options for CPU and OS which will keep CPU's frequency stable.

Has anyone knows why! Thanks a lot!

You might want to monitor

McCalpinJohn — Wed, 17 Jul 2019 15:05:00 GMT

You might want to monitor SMIs -- some platforms use these to monitor processor temperature and control frequency. On most processors the number of SMIs is counted by MSR 0x34 (MSR_SMI_COUNT).

You can also get processor stalls like this from the Power Control Unit (PCU). Disabling Turbo helps, but the PCU will halt cores for other reasons...

Cores may be halted when transitioning to/from 256-bit SIMD mode. This is not seen on all processor models, but I have seen it on the Xeon E5 v3 platforms, and I saw it even when Turbo boost was disabled. Some discussion is at https://www.agner.org/optimize/blog/read.php?i=165#378 ;
Cores may be halted when the number of active (C0 and/or C1) cores changes. I don't know about the Xeon E3 v3 family, but most Intel processors have a transition between 0-1 active cores and 2-3 active cores. This is usually associated with Turbo boost p-state changes, but it is conceivable that it might happen in other cases.

The easiest way to look for evidence of core stalls is to measure both the TSC and the fixed-function counter 2 ("CPU_CLK_UNHALTED.REF"). These increment at the same rate while the core is not halted, so if they don't match, it means that the core was halted.

In the processors with the "server uncore" (Xeon E5, E7), the uncore power control unit has performance monitoring events that may provide additional insight, but I don't know if the "client uncore" in the Xeon E3 supports any such features.....

Your kernel parameters

HadiBrais — Wed, 17 Jul 2019 18:14:00 GMT

Your kernel parameters include both "nohz=on" and "nohz=off." Also "nohalt" is probably useless on the Linux version you're using, so it may not actually disable hyperthreading. "nohalt" only has an effect on Itanium processors. "isolcpus" only isolates the specified cores from user tasks i.e., the thread scheduler will never schedule a user thread on any of the specified cores unless the affinity mask includes some of these cores. That doesn't mean that kernel threads and hardware interrupts will not occur on isolated cores. You can use the command "watch -d 'cat /proc/interrupts'" to check whether hardware interrupts are occurring on the isolated cores during the execution of your program. It may be necessary to disable irqbalance and assign all interrupts to one of the cores that are not in the isolcpus list.