google / google/benchmark

[BUG] Certain performance counters are not measured and are always zero

Open
#1,896 6 comments 0 reactions 0 assignees View on GitHub
Dominant language
C++
Stars
10.4k
Forks
1.8k
Avg merge
2d 4h
Merged PRs (30d)
8

Description

**Describe the bug**

Certain counters such as `frontend_retired.l2_miss` are always reported as zero using the [performance counters integration with libpfm](https://github.com/google/benchmark/blob/main/docs/perf_counters.md).

To confirm that this is indeed a bug I have made a small example where I'm flushing a function from all caches using the `clflush` instruction and then calling it, which should lead to an L2 miss. perf stat and record confirm that `frontend_retired.l2_miss` should be non-zero and the miss is happening within the function, however the counters reported by google benchmark are always zero. I have also noticed this issue with a few other events such as `frontend_retired.latency_ge_1`.

**System**
Which OS, compiler, and compiler version are you using:
- OS: Ubuntu 22.04, Kernel 6.8.0-49-generic
- Compiler and version: GNU assembler version 2.38 (x86_64-linux-gnu) using BFD version (GNU Binutils for Ubuntu) 2.38, g++ (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0
- Processor: 11th Gen Intel(R) Core(TM) i5-11400H

**To reproduce**

Make a file `fun.S` with the following contents.

```
.section .data

.section .text

.global fun
.global not_fun

.align 512
not_fun:
nop
ret

.align 512
fun:
clflush not_fun
mfence
call not_fun
ret
```
The function `fun` flushes `not_fun` from all the caches and then calls it, which will cause a cache miss as it tries to fetch the first instruction of the function.

Make two more files, `prog1.S` and `prog2.cpp` respectively with the following contents.

```
.section .data

.section .text

.global _start
_start:
mov $10000000, %rcx

loop:
call fun
dec %rcx
jnz loop

xor %rdi,%rdi
mov $60, %rax
syscall
```
```
#include

extern "C" void fun();

void BM(benchmark::State &state) {
for (auto _ : state) {
fun();
}
}

BENCHMARK(BM);

BENCHMARK_MAIN();
```
and a Makefile:
```
all: fun.o prog1.o prog2.o
g++ prog1.o fun.o -o prog1.out -std=c++17 -nostdlib -no-pie -O3 -Wall -Werror -fno-omit-frame-pointer -isystem benchmark/include -Lbenchmark/build/src -lbenchmark -lpthread -lpfm
g++ prog2.o fun.o -o prog2.out -std=c++17 -no-pie -O3 -Wall -Werror -fno-omit-frame-pointer -isystem benchmark/include -Lbenchmark/build/src -lbenchmark -lpthread -lpfm

prog1.o: prog1.S
as prog1.S -o prog1.o

fun.o: fun.S
as fun.S -o fun.o

prog2.o:
g++ prog2.cpp -c -std=c++17 -no-pie -O3 -Wall -Werror -fno-omit-frame-pointer -isystem benchmark/include -Lbenchmark/build/src -lbenchmark -lpthread -lpfm

clean:
rm *.o *.out
```

First, I run `prog1.out` along with perf to get the expected results without google benchmark's code interfering with everything. The code for `prog1.S` is simply a loop which calls `fun` 1e7 times.

```
$ sudo perf stat -e cycles,frontend_retired.l1i_miss,frontend_retired.l2_miss,frontend_retired.latency_ge_1 taskset -c 0 nice -n -20 ./prog1.out

Performance counter stats for 'taskset -c 0 nice -n -20 ./prog1.out':

6,71,13,49,717 cycles (49.99%)
14,09,768 frontend_retired.l1i_miss (50.04%)
13,26,441 frontend_retired.l2_miss (24.98%)
3,53,09,157 frontend_retired.latency_ge_1 (24.98%)

1.517582000 seconds time elapsed

1.515770000 seconds user
0.000999000 seconds sys
```
As expected, we see L2 misses. Using perf record/sampling it can be confirmed that all the misses are inside `fun` ![Image](https://github.com/user-attachments/assets/d0d1e037-6cda-405c-a50b-22052053d4bb)

Now, I run `prog2.out` to see what google benchmarks reports the counters as.

```
$ sudo taskset -c 0 nice -n -20 ./prog2.out --benchmark_perf_counters=CYCLES,frontend_retired.l1i_miss,frontend_retired.l2_miss,frontend_retired.latency_ge_1 --benchmark_counters_tabular=true --benchmark_min_time=10000000x
Running ./prog2.out
Run on (12 X 4279.92 MHz CPU s)
CPU Caches:
L1 Data 48 KiB (x6)
L1 Instruction 32 KiB (x6)
L2 Unified 1280 KiB (x6)
L3 Unified 12288 KiB (x1)
Load Average: 0.18, 0.38, 0.49
-------------------------------------------------------------------------------------------------------------------------------------------------
Benchmark Time CPU Iterations CYCLES frontend_retired.l1i_miss frontend_retired.l2_miss frontend_retired.latency_ge_1
-------------------------------------------------------------------------------------------------------------------------------------------------
BM 158 ns 158 ns 10000000 702.339 0.342522 0 0
```

and **the L2 misses are zero.**

For one more final confirmation we run google benchmark under perf stat - I'm not sure if both programs trying to use the same counters will mess something up, but anyways google benchmark again reports the counter values as zero whereas perf stat gives non-zero values. It is unlikely that these non-zero values are cause by google benchmarks code instead of the test code, as I have shown above that the test code on its own indeed causes the event as confirmed using perf stat + record.

```
$ sudo perf stat -e cycles,frontend_retired.l1i_miss,frontend_retired.l2_miss,frontend_retired.latency_ge_1 taskset -c 0 nice -n -20 ./prog2.out --benchmark_perf_counters=CYCLES,frontend_retired.l1i_miss,frontend_retired.l2_miss,frontend_retired.latency_ge_1 --benchmark_counters_tabular=true --benchmark_min_time=10000000x
Running ./prog2.out
Run on (12 X 4184.45 MHz CPU s)
CPU Caches:
L1 Data 48 KiB (x6)
L1 Instruction 32 KiB (x6)
L2 Unified 1280 KiB (x6)
L3 Unified 12288 KiB (x1)
Load Average: 0.41, 0.42, 0.47
-------------------------------------------------------------------------------------------------------------------------------------------------
Benchmark Time CPU Iterations CYCLES frontend_retired.l1i_miss frontend_retired.l2_miss frontend_retired.latency_ge_1
-------------------------------------------------------------------------------------------------------------------------------------------------
BM 158 ns 158 ns 10000000 699.904 0.28635 0 0

Performance counter stats for 'taskset -c 0 nice -n -20 ./prog2.out --benchmark_perf_counters=CYCLES,frontend_retired.l1i_miss,frontend_retired.l2_miss,frontend_retired.latency_ge_1 --benchmark_counters_tabular=true --benchmark_min_time=10000000x':

7,03,84,92,871 cycles (16.85%)
41,63,656 frontend_retired.l1i_miss (16.84%)
10,25,334 frontend_retired.l2_miss (0.13%)
26,30,55,471 frontend_retired.latency_ge_1 (0.13%)

1.592229730 seconds time elapsed

1.586011000 seconds user
0.006000000 seconds sys
```

**Expected behavior**
The counter values should be non-zero when it is clear that L2 cache misses are happening (confirmed with perf).

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.