Menu
I'm running some experiments around getting highly consistent runtimes for a piece of code. The code I'm currently timing is a pretty arbitrary CPU-bound workload:
int cpu_workload_external_O3(){
int x = 0;
for(int ind = 0; ind < 12349560; ind++){
x = ((x ^ 0x123) + x * 3) % 123456;
}
return x;
}
I've written a kernel module that disables interrupts and then runs 10 trials of the above function, timing each trial by taking the difference in the clock cycle counter from before and after. Other things to note:
In other words, I believe most/all sources of system variability are accounted for, and, especially when run as a kernel module with interrupts disabled via spin_lock_irqsave(), the code should achieve pretty much identical performance run-to-run (maybe a small performance hit on the first run when some instruction is first pulled into cache, but that's it).
Indeed, when the benchmarked code is compiled with -O3, I saw a range of at most 200 cycles out of ~135,845,192 on average, with most of the trials taking exactly the same amount of time. However, when compiled with -O0, the range shot up to as much as 158,386 cycles out of ~262,710,916. By range I mean the difference between the longest and shortest running times. Moreover, for the -O0 code, there's not much consistency to which of the trials is the slowest/fastest -- counterintuitively, in one occasion the fastest was the very first, and the slowest was the one right after!
So: what might be causing this high upper bound on variability in the -O0 code? Looking at the assembly, it seems that the -O3 code stores everything (?) in a register, whereas the -O0 code has a bunch of references to sp and so it seems to be accessing memory. But even then, I'd expect everything to get brought into L1 cache and sit there with a pretty deterministic access time.
The code being benchmarked is in the snippet above. The assembly is below. Both were compiled with gcc 7.4.0 with no flags except for -O0 and -O3.
-O00000000000000000 <cpu_workload_external_O0>:
0: d10043ff sub sp, sp, #0x10
4: b9000bff str wzr, [sp, #8]
8: b9000fff str wzr, [sp, #12]
c: 14000018 b 6c <cpu_workload_external_O0+0x6c>
10: b9400be1 ldr w1, [sp, #8]
14: 52802460 mov w0, #0x123 // #291
18: 4a000022 eor w2, w1, w0
1c: b9400be1 ldr w1, [sp, #8]
20: 2a0103e0 mov w0, w1
24: 531f7800 lsl w0, w0, #1
28: 0b010000 add w0, w0, w1
2c: 0b000040 add w0, w2, w0
30: 528aea61 mov w1, #0x5753 // #22355
34: 72a10fc1 movk w1, #0x87e, lsl #16
38: 9b217c01 smull x1, w0, w1
3c: d360fc21 lsr x1, x1, #32
40: 130c7c22 asr w2, w1, #12
44: 131f7c01 asr w1, w0, #31
48: 4b010042 sub w2, w2, w1
4c: 529c4801 mov w1, #0xe240 // #57920
50: 72a00021 movk w1, #0x1, lsl #16
54: 1b017c41 mul w1, w2, w1
58: 4b010000 sub w0, w0, w1
5c: b9000be0 str w0, [sp, #8]
60: b9400fe0 ldr w0, [sp, #12]
64: 11000400 add w0, w0, #0x1
68: b9000fe0 str w0, [sp, #12]
6c: b9400fe1 ldr w1, [sp, #12]
70: 528e0ee0 mov w0, #0x7077 // #28791
74: 72a01780 movk w0, #0xbc, lsl #16
78: 6b00003f cmp w1, w0
7c: 54fffcad b.le 10 <cpu_workload_external_O0+0x10>
80: b9400be0 ldr w0, [sp, #8]
84: 910043ff add sp, sp, #0x10
88: d65f03c0 ret
-O30000000000000000 <cpu_workload_external_O3>:
0: 528e0f02 mov w2, #0x7078 // #28792
4: 5292baa4 mov w4, #0x95d5 // #38357
8: 529c4803 mov w3, #0xe240 // #57920
c: 72a01782 movk w2, #0xbc, lsl #16
10: 52800000 mov w0, #0x0 // #0
14: 52802465 mov w5, #0x123 // #291
18: 72a043e4 movk w4, #0x21f, lsl #16
1c: 72a00023 movk w3, #0x1, lsl #16
20: 4a050001 eor w1, w0, w5
24: 0b000400 add w0, w0, w0, lsl #1
28: 0b000021 add w1, w1, w0
2c: 71000442 subs w2, w2, #0x1
30: 53067c20 lsr w0, w1, #6
34: 9ba47c00 umull x0, w0, w4
38: d364fc00 lsr x0, x0, #36
3c: 1b038400 msub w0, w0, w3, w1
40: 54ffff01 b.ne 20 <cpu_workload_external_O3+0x20> // b.any
44: d65f03c0 ret
The code running the trials is below. It reads PMCCNTR_EL0 before/after each iteration, stores the differences in an array, and prints out the min/max times in the end across all trials. The functions cpu_workload_external_O0 and cpu_workload_external_O3 are in external object files that are compiled separately, and then linked in.
#include <linux/init.h>
#include <linux/module.h>
#include <linux/kernel.h>
#include "cpu.h"
static DEFINE_SPINLOCK(lock);
void runBenchmark(int (*benchmarkFunc)(void)){
// Enable perf counters.
u32 pmcr;
asm volatile("mrs %0, pmcr_el0" : "=r" (pmcr));
asm volatile("msr pmcr_el0, %0" : : "r" (pmcr|(1)));
// Run trials, storing the time of each in `clockDiffs`.
u32 result = 0;
#define numtrials 10
u32 clockDiffs[numtrials] = {0};
u32 clockStart, clockEnd;
for(int trial = 0; trial < numtrials; trial++){
asm volatile("isb; mrs %0, PMCCNTR_EL0" : "=r" (clockStart));
result += benchmarkFunc();
asm volatile("isb; mrs %0, PMCCNTR_EL0" : "=r" (clockEnd));
// Reset PMCCNTR_EL0.
asm volatile("mrs %0, pmcr_el0" : "=r" (pmcr));
asm volatile("msr pmcr_el0, %0" : : "r" (pmcr|(((uint32_t)1) << 2)));
clockDiffs[trial] = clockEnd - clockStart;
}
// Compute the min and max times across all trials.
u32 minTime = clockDiffs[0];
u32 maxTime = clockDiffs[0];
for(int ind = 1; ind < numtrials; ind++){
u32 time = clockDiffs[ind];
if(time < minTime){
minTime = time;
} else if(time > maxTime){
maxTime = time;
}
}
// Print the result so the benchmark function doesn't get optimized out.
printk("result: %d\n", result);
printk("diff: max %d - min %d = %d cycles\n", maxTime, minTime, maxTime - minTime);
}
int init_module(void) {
printk("enter\n");
unsigned long flags;
spin_lock_irqsave(&lock, flags);
printk("-O0\n");
runBenchmark(cpu_workload_external_O0);
printk("-O3\n");
runBenchmark(cpu_workload_external_O3);
spin_unlock_irqrestore(&lock, flags);
return 0;
}
void cleanup_module(void) {
printk("exit\n");
}
$ lscpu
Architecture: aarch64
Byte Order: Little Endian
CPU(s): 16
On-line CPU(s) list: 0-15
Thread(s) per core: 1
Core(s) per socket: 4
Socket(s): 4
NUMA node(s): 1
Vendor ID: ARM
Model: 3
Model name: Cortex-A72
Stepping: r0p3
BogoMIPS: 166.66
L1d cache: 32K
L1i cache: 48K
L2 cache: 2048K
NUMA node0 CPU(s): 0-15
Flags: fp asimd evtstrm aes pmull sha1 sha2 crc32 cpuid
$ lscpu --extended
CPU NODE SOCKET CORE L1d:L1i:L2 ONLINE
0 0 0 0 0:0:0 yes
1 0 0 1 1:1:0 yes
2 0 0 2 2:2:0 yes
3 0 0 3 3:3:0 yes
4 0 1 4 4:4:1 yes
5 0 1 5 5:5:1 yes
6 0 1 6 6:6:1 yes
7 0 1 7 7:7:1 yes
8 0 2 8 8:8:2 yes
9 0 2 9 9:9:2 yes
10 0 2 10 10:10:2 yes
11 0 2 11 11:11:2 yes
12 0 3 12 12:12:3 yes
13 0 3 13 13:13:3 yes
14 0 3 14 14:14:3 yes
15 0 3 15 15:15:3 yes
$ numactl --hardware
available: 1 nodes (0)
node 0 cpus: 0 1 2 3 4 5 6 7 8 9 10 11 12 13 14 15
node 0 size: 32159 MB
node 0 free: 30661 MB
node distances:
node 0
0: 10
Below is some output from one execution of the kernel module:
[902574.112692] kernel-module: running on cpu 15
[902576.403537] kernel-module: trial 00: 309983568 74097394 98796602 <-- max
[902576.403539] kernel-module: trial 01: 309983562 74097397 98796597
[902576.403540] kernel-module: trial 02: 309983562 74097397 98796597
[902576.403541] kernel-module: trial 03: 309983562 74097397 98796597
[902576.403543] kernel-module: trial 04: 309983562 74097397 98796597
[902576.403544] kernel-module: trial 05: 309983562 74097397 98796597
[902576.403545] kernel-module: trial 06: 309983562 74097397 98796597
[902576.403547] kernel-module: trial 07: 309983562 74097397 98796597
[902576.403548] kernel-module: trial 08: 309983562 74097397 98796597
[902576.403550] kernel-module: trial 09: 309983562 74097397 98796597
[902576.403551] kernel-module: trial 10: 309983562 74097397 98796597
[902576.403552] kernel-module: trial 11: 309983562 74097397 98796597
[902576.403554] kernel-module: trial 12: 309983562 74097397 98796597
[902576.403555] kernel-module: trial 13: 309849076 74097403 98796630 <-- min
[902576.403557] kernel-module: trial 14: 309983562 74097397 98796597
[902576.403558] kernel-module: min time: 309849076
[902576.403559] kernel-module: max time: 309983568
[902576.403560] kernel-module: diff: 134492
For each trial, the values reported are: # of cycles (0x11), # of L1D accesses (0x04), # of L1I accesses (0x14). I'm using section 11.8 of this ARM PMU reference).
686
In recent Linux kernels the automatic NUMA page migration mechanism periodically shoots down TLB entries so that it can monitor NUMA locality. TLB reloads will slow down the O0 code, even if the data remains in the L1DCache.
The page migration mechanism should not be activated on kernel pages.
You check to see if automatic NUMA page migration is enabled with
$ cat /proc/sys/kernel/numa_balancing
and you can disable it with
$ echo 0 > /proc/sys/kernel/numa_balancing
Your variance is in the order of 6*10^-4. While shockingly more than 1.3*10^-6, once your program is talking to the caches, it is involved in many synchronized operations. Synchronized always means wasted time.
An interesting thing is how your -O0, -O3 comparison mimiks the general rule that an L1-cache-hit is about 2x a register reference. Your average O3 runs in 51.70% of the time your O0 does. When you apply the lower/uppper variances, we have (O3-200)/(O0+158386), we see a an improvement to 51.67%.
In short, yes, a cache will never be deterministic; and the low variance you see is in line with what should be expected from synchronizing with a slower device. It is only a large variance when compared to the more deterministic register-only machine.
21
If you love us? You can donate to us via Paypal or buy me a coffee so we can maintain and grow! Thank you!
Donate Us With
