LTP test perf_event_open02.c: possible rounding issue on aarch64 KVM

LTP test perf_event_open02.c: possible rounding issue on aarch64 KVM

[Petr Vorel]

Hi,

I have problem with LTP test perf_event_open02.c [1] on QEMU using KVM on
openSUSE aarch64 kernel 5.15.5-1-default (not much different from stable kernel
from kernel.org):

# /opt/ltp/testcases/bin/perf_event_open02
...
perf_event_open02.c:104: TINFO: bench_work estimated loops = 8083 in 500 ms
perf_event_open02.c:149: TINFO: [0] value:2425293761 time_enabled:749092800 time_running:749092800
perf_event_open02.c:149: TINFO: [1] value:2425287027 time_enabled:749141475 time_running:749141475
perf_event_open02.c:149: TINFO: [2] value:2433046583 time_enabled:757346300 time_running:757346300
perf_event_open02.c:149: TINFO: [3] value:2432771537 time_enabled:753369300 time_running:753369300
perf_event_open02.c:149: TINFO: [4] value:2432551620 time_enabled:753784075 time_running:753784075
perf_event_open02.c:149: TINFO: [5] value:2432386104 time_enabled:753481750 time_running:753481750
perf_event_open02.c:149: TINFO: [6] value:2095086137 time_enabled:768866050 time_running:660021525
perf_event_open02.c:308: TINFO: nhw: 6, overall task clock: 4098138525
perf_event_open02.c:309: TINFO: hw sum: 116450294745, task clock sum: 24589636350
perf_event_open02.c:321: TINFO: ratio: 6.000196
perf_event_open02.c:323: TFAIL: test failed (ratio was greater than 6)
...

The test tries to assert the precision of hardware counters (using struct
perf_event_attr hw_event.type = PERF_TYPE_HARDWARE), but sometimes it fails with
slight overrun. We suppose that this is a rounding error, but it'd be nice to
get this confirmed from kernel developers.

Related kernel setup (or you need to know something else)
grep PERF_EVENTS config-5.15.5-1-default # aarch64
CONFIG_HAVE_PERF_EVENTS=y
CONFIG_PERF_EVENTS=y
CONFIG_HW_PERF_EVENTS=y

Test is running inside testing framework with this setup:
qemu-system-aarch64 -device virtio-gpu-pci -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 2048 -machine virt,gic-version=host -cpu host -mem-prealloc -mem-path /dev/hugepages/ -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot menu=on,splash-time=5000 -device nec-usb-xhci -device usb-tablet -device usb-kbd -smp 2 -enable-kvm -no-shutdown -vnc :97,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay0-file,filename=/var/lib/openqa/pool/7/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on -device virtio-blk-device,id=hd0-device,drive=hd0-overlay0,bootindex=0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/7/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0 -drive id=pflash-code-overlay0,if=pflash,file=/var/lib/openqa/pool/7/raid/pflash-code-overlay0,unit=0,readonly=on -drive id=pflash-vars-overlay0,if=pflash,file=/var/lib/openqa/pool/7/raid/pflash-vars-overlay0,unit=1

Running the same OS and kernel (aarch64 JeOS Tumbleweed 20211202) on RPI it's working:
perf_event_open02.c:104: TINFO: bench_work estimated loops = 3601 in 500 ms
perf_event_open02.c:149: TINFO: [0] value:1080601748 time_enabled:480527015 time_running:480527015
perf_event_open02.c:149: TINFO: [1] value:1080599535 time_enabled:480540573 time_running:480540573
perf_event_open02.c:149: TINFO: [2] value:1080592770 time_enabled:480533868 time_running:480533868
perf_event_open02.c:149: TINFO: [3] value:1080607121 time_enabled:480571573 time_running:480571573
perf_event_open02.c:149: TINFO: [4] value:1080598264 time_enabled:480568330 time_running:480568330
perf_event_open02.c:149: TINFO: [5] value:1080608798 time_enabled:480600001 time_running:480600001
perf_event_open02.c:149: TINFO: [6] value:923390393 time_enabled:480919479 time_running:410947611
perf_event_open02.c:308: TINFO: nhw: 6, overall task clock: 4990107074
perf_event_open02.c:309: TINFO: hw sum: 51868804135, task clock sum: 29940616417
perf_event_open02.c:321: TINFO: ratio: 5.999995
perf_event_open02.c:325: TPASS: test passed

Test is not supported ENOENT when running with similar setup on x86_64 and
s390x quests:
perf_event_open.h:31: TCONF: perf_event_open type/config not supported: ENOENT (2)

grep PERF_EVENTS config-5.15.5-1-default # x86_64
CONFIG_HAVE_PERF_EVENTS=y
CONFIG_PERF_EVENTS=y
CONFIG_PERF_EVENTS_INTEL_UNCORE=y
CONFIG_PERF_EVENTS_INTEL_RAPL=y
CONFIG_PERF_EVENTS_INTEL_CSTATE=y
CONFIG_PERF_EVENTS_AMD_POWER=m
CONFIG_PERF_EVENTS_AMD_UNCORE=m
CONFIG_HAVE_PERF_EVENTS_NMI=y

But it passes on ppc64le

perf_event_open02.c:104: TINFO: bench_work estimated loops = 4075 in 500 ms
perf_event_open02.c:151: TINFO: [0] value:815279669 time_enabled:316461566 time_running:316461566
perf_event_open02.c:151: TINFO: [1] value:815281799 time_enabled:316462740 time_running:316462740
perf_event_open02.c:151: TINFO: [2] value:815280588 time_enabled:316534086 time_running:316534086
perf_event_open02.c:151: TINFO: [3] value:815283285 time_enabled:316465672 time_running:316465672
perf_event_open02.c:151: TINFO: [4] value:815305390 time_enabled:316492698 time_running:316492698
perf_event_open02.c:151: TINFO: [5] value:686550649 time_enabled:316631866 time_running:266632316
perf_event_open02.c:308: TINFO: nhw: 5, overall task clock: 2534004200
perf_event_open02.c:309: TINFO: hw sum: 32612814180, task clock sum: 12669966232
perf_event_open02.c:321: TINFO: ratio: 4.999978
perf_event_open02.c:325: TPASS: test passed

grep PERF_EVENTS config # ppc64le
CONFIG_HAVE_PERF_EVENTS=y
CONFIG_PERF_EVENTS=y
CONFIG_HAVE_PERF_EVENTS_NMI=y

When I tried running aarch64 quest with stable kernel 5.10.76 from kernel.org on
my intel laptop, using simplified setup, the event was not supported (not sure
whether that was caused unavailable -enable-kvm or something else; I also
haven't checked kernel config):

qemu-system-aarch64 -M virt -cpu cortex-a53 -nographic -smp $SMP -kernel Image -append "rootwait root=/dev/vda console=ttyAMA0" -netdev user,id=eth0 -device virtio-net-device,netdev=eth0 -drive file=rootfs.ext4,if=none,format=raw,id=hd0 -device virtio-blk-device,drive=hd0
...
perf_event_open.h:26: TINFO: perf_event_open event.type: 0, event.config: 1
perf_event_open.h:30: TCONF: perf_event_open type/config not supported: ENOENT (2)

I also tested that stable kernel 5.10.76 on RPI but that passed (the same as openSUSE 5.15.5-1-default)
perf_event_open02.c:104: TINFO: bench_work estimated loops = 1496 in 500 ms
perf_event_open02.c:149: TINFO: [0] value:449725668 time_enabled:500191054 time_running:500191054
perf_event_open02.c:149: TINFO: [1] value:449728803 time_enabled:500204795 time_running:500204795
perf_event_open02.c:149: TINFO: [2] value:449732944 time_enabled:500210665 time_running:500210665
perf_event_open02.c:149: TINFO: [3] value:449738099 time_enabled:500210443 time_running:500210443
perf_event_open02.c:149: TINFO: [4] value:449745104 time_enabled:500234961 time_running:500234961
perf_event_open02.c:149: TINFO: [5] value:449756676 time_enabled:500247647 time_running:500247647
perf_event_open02.c:149: TINFO: [6] value:385474224 time_enabled:502975813 time_running:430976612
perf_event_open02.c:308: TINFO: nhw: 6, overall task clock: 4031349522
perf_event_open02.c:309: TINFO: hw sum: 21590362808, task clock sum: 24187113827
perf_event_open02.c:321: TINFO: ratio: 5.999756
perf_event_open02.c:325: TPASS: test passed

So is it a rounding issue on aarch64 QEMU/KVM?
Thanks for any hint what to check / try.

Kind regards,
Petr

[1] https://github.com/linux-test-project/ltp/tree/c2d4836c057fb9f78e7f625d71638d4f40f98659/testcases/kernel/syscalls/perf_event_open/perf_event_open02.c

Re: LTP test perf_event_open02.c: possible rounding issue on aarch64 KVM

[James Clark]

On 09/12/2021 12:20, Petr Vorel wrote:
> Hi,
> 
> I have problem with LTP test perf_event_open02.c [1] on QEMU using KVM on
> openSUSE aarch64 kernel 5.15.5-1-default (not much different from stable kernel
> from kernel.org):
> 
> # /opt/ltp/testcases/bin/perf_event_open02
> ...
> perf_event_open02.c:104: TINFO: bench_work estimated loops = 8083 in 500 ms
> perf_event_open02.c:149: TINFO: [0] value:2425293761 time_enabled:749092800 time_running:749092800
> perf_event_open02.c:149: TINFO: [1] value:2425287027 time_enabled:749141475 time_running:749141475
> perf_event_open02.c:149: TINFO: [2] value:2433046583 time_enabled:757346300 time_running:757346300
> perf_event_open02.c:149: TINFO: [3] value:2432771537 time_enabled:753369300 time_running:753369300
> perf_event_open02.c:149: TINFO: [4] value:2432551620 time_enabled:753784075 time_running:753784075
> perf_event_open02.c:149: TINFO: [5] value:2432386104 time_enabled:753481750 time_running:753481750
> perf_event_open02.c:149: TINFO: [6] value:2095086137 time_enabled:768866050 time_running:660021525
> perf_event_open02.c:308: TINFO: nhw: 6, overall task clock: 4098138525
> perf_event_open02.c:309: TINFO: hw sum: 116450294745, task clock sum: 24589636350
> perf_event_open02.c:321: TINFO: ratio: 6.000196
> perf_event_open02.c:323: TFAIL: test failed (ratio was greater than 6)
> ...
> 
> The test tries to assert the precision of hardware counters (using struct
> perf_event_attr hw_event.type = PERF_TYPE_HARDWARE), but sometimes it fails with
> slight overrun. We suppose that this is a rounding error, but it'd be nice to
> get this confirmed from kernel developers.
> 

I don't believe this is a rounding error because the test uses long longs for the totals and then
has a single division into a double. A difference of 0.000196 is too big to be explained by
rounding from a single division.

There is at least one other fix (f4bf9ba01802) in the commit history that involves
very close but failing values, and the fix wasn't to change the tolerance. So I'd say there is
probably a bug in the test, or you've found a real bug.

> Related kernel setup (or you need to know something else)
> grep PERF_EVENTS config-5.15.5-1-default # aarch64
> CONFIG_HAVE_PERF_EVENTS=y
> CONFIG_PERF_EVENTS=y
> CONFIG_HW_PERF_EVENTS=y
> 
> Test is running inside testing framework with this setup:
> qemu-system-aarch64 -device virtio-gpu-pci -only-migratable -chardev ringbuf,id=serial0,logfile=serial0,logappend=on -serial chardev:serial0 -audiodev none,id=snd0 -device intel-hda -device hda-output,audiodev=snd0 -m 2048 -machine virt,gic-version=host -cpu host -mem-prealloc -mem-path /dev/hugepages/ -netdev user,id=qanet0 -device virtio-net,netdev=qanet0,mac=52:54:00:12:34:56 -object rng-random,filename=/dev/urandom,id=rng0 -device virtio-rng-pci,rng=rng0 -boot menu=on,splash-time=5000 -device nec-usb-xhci -device usb-tablet -device usb-kbd -smp 2 -enable-kvm -no-shutdown -vnc :97,share=force-shared -device virtio-serial -chardev pipe,id=virtio_console,path=virtio_console,logfile=virtio_console.log,logappend=on -device virtconsole,chardev=virtio_console,name=org.openqa.console.virtio_console -chardev pipe,id=virtio_console1,path=virtio_console1,logfile=virtio_console1.log,logappend=on -device virtconsole,chardev=virtio_console1,name=org.openqa.console.virtio_console1 -chardev socket,path=qmp_socket,server=on,wait=off,id=qmp_socket,logfile=qmp_socket.log,logappend=on -qmp chardev:qmp_socket -S -device virtio-scsi-pci,id=scsi0 -blockdev driver=file,node-name=hd0-overlay0-file,filename=/var/lib/openqa/pool/7/raid/hd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=hd0-overlay0,file=hd0-overlay0-file,cache.no-flush=on -device virtio-blk-device,id=hd0-device,drive=hd0-overlay0,bootindex=0,serial=hd0 -blockdev driver=file,node-name=cd0-overlay0-file,filename=/var/lib/openqa/pool/7/raid/cd0-overlay0,cache.no-flush=on -blockdev driver=qcow2,node-name=cd0-overlay0,file=cd0-overlay0-file,cache.no-flush=on -device scsi-cd,id=cd0-device,drive=cd0-overlay0,serial=cd0 -drive id=pflash-code-overlay0,if=pflash,file=/var/lib/openqa/pool/7/raid/pflash-code-overlay0,unit=0,readonly=on -drive id=pflash-vars-overlay0,if=pflash,file=/var/lib/openqa/pool/7/raid/pflash-vars-overlay0,unit=1
> 
> Running the same OS and kernel (aarch64 JeOS Tumbleweed 20211202) on RPI it's working:
> perf_event_open02.c:104: TINFO: bench_work estimated loops = 3601 in 500 ms
> perf_event_open02.c:149: TINFO: [0] value:1080601748 time_enabled:480527015 time_running:480527015
> perf_event_open02.c:149: TINFO: [1] value:1080599535 time_enabled:480540573 time_running:480540573
> perf_event_open02.c:149: TINFO: [2] value:1080592770 time_enabled:480533868 time_running:480533868
> perf_event_open02.c:149: TINFO: [3] value:1080607121 time_enabled:480571573 time_running:480571573
> perf_event_open02.c:149: TINFO: [4] value:1080598264 time_enabled:480568330 time_running:480568330
> perf_event_open02.c:149: TINFO: [5] value:1080608798 time_enabled:480600001 time_running:480600001
> perf_event_open02.c:149: TINFO: [6] value:923390393 time_enabled:480919479 time_running:410947611
> perf_event_open02.c:308: TINFO: nhw: 6, overall task clock: 4990107074
> perf_event_open02.c:309: TINFO: hw sum: 51868804135, task clock sum: 29940616417
> perf_event_open02.c:321: TINFO: ratio: 5.999995
> perf_event_open02.c:325: TPASS: test passed
> 
> Test is not supported ENOENT when running with similar setup on x86_64 and
> s390x quests:
> perf_event_open.h:31: TCONF: perf_event_open type/config not supported: ENOENT (2)
> 
> grep PERF_EVENTS config-5.15.5-1-default # x86_64
> CONFIG_HAVE_PERF_EVENTS=y
> CONFIG_PERF_EVENTS=y
> CONFIG_PERF_EVENTS_INTEL_UNCORE=y
> CONFIG_PERF_EVENTS_INTEL_RAPL=y
> CONFIG_PERF_EVENTS_INTEL_CSTATE=y
> CONFIG_PERF_EVENTS_AMD_POWER=m
> CONFIG_PERF_EVENTS_AMD_UNCORE=m
> CONFIG_HAVE_PERF_EVENTS_NMI=y
> 
> But it passes on ppc64le
> 
> perf_event_open02.c:104: TINFO: bench_work estimated loops = 4075 in 500 ms
> perf_event_open02.c:151: TINFO: [0] value:815279669 time_enabled:316461566 time_running:316461566
> perf_event_open02.c:151: TINFO: [1] value:815281799 time_enabled:316462740 time_running:316462740
> perf_event_open02.c:151: TINFO: [2] value:815280588 time_enabled:316534086 time_running:316534086
> perf_event_open02.c:151: TINFO: [3] value:815283285 time_enabled:316465672 time_running:316465672
> perf_event_open02.c:151: TINFO: [4] value:815305390 time_enabled:316492698 time_running:316492698
> perf_event_open02.c:151: TINFO: [5] value:686550649 time_enabled:316631866 time_running:266632316
> perf_event_open02.c:308: TINFO: nhw: 5, overall task clock: 2534004200
> perf_event_open02.c:309: TINFO: hw sum: 32612814180, task clock sum: 12669966232
> perf_event_open02.c:321: TINFO: ratio: 4.999978
> perf_event_open02.c:325: TPASS: test passed
> 
> grep PERF_EVENTS config # ppc64le
> CONFIG_HAVE_PERF_EVENTS=y
> CONFIG_PERF_EVENTS=y
> CONFIG_HAVE_PERF_EVENTS_NMI=y
> 
> When I tried running aarch64 quest with stable kernel 5.10.76 from kernel.org on
> my intel laptop, using simplified setup, the event was not supported (not sure
> whether that was caused unavailable -enable-kvm or something else; I also
> haven't checked kernel config):
> 
> qemu-system-aarch64 -M virt -cpu cortex-a53 -nographic -smp $SMP -kernel Image -append "rootwait root=/dev/vda console=ttyAMA0" -netdev user,id=eth0 -device virtio-net-device,netdev=eth0 -drive file=rootfs.ext4,if=none,format=raw,id=hd0 -device virtio-blk-device,drive=hd0
> ...
> perf_event_open.h:26: TINFO: perf_event_open event.type: 0, event.config: 1
> perf_event_open.h:30: TCONF: perf_event_open type/config not supported: ENOENT (2)
> 
> I also tested that stable kernel 5.10.76 on RPI but that passed (the same as openSUSE 5.15.5-1-default)
> perf_event_open02.c:104: TINFO: bench_work estimated loops = 1496 in 500 ms
> perf_event_open02.c:149: TINFO: [0] value:449725668 time_enabled:500191054 time_running:500191054
> perf_event_open02.c:149: TINFO: [1] value:449728803 time_enabled:500204795 time_running:500204795
> perf_event_open02.c:149: TINFO: [2] value:449732944 time_enabled:500210665 time_running:500210665
> perf_event_open02.c:149: TINFO: [3] value:449738099 time_enabled:500210443 time_running:500210443
> perf_event_open02.c:149: TINFO: [4] value:449745104 time_enabled:500234961 time_running:500234961
> perf_event_open02.c:149: TINFO: [5] value:449756676 time_enabled:500247647 time_running:500247647
> perf_event_open02.c:149: TINFO: [6] value:385474224 time_enabled:502975813 time_running:430976612
> perf_event_open02.c:308: TINFO: nhw: 6, overall task clock: 4031349522
> perf_event_open02.c:309: TINFO: hw sum: 21590362808, task clock sum: 24187113827
> perf_event_open02.c:321: TINFO: ratio: 5.999756
> perf_event_open02.c:325: TPASS: test passed
> 
> So is it a rounding issue on aarch64 QEMU/KVM?
> Thanks for any hint what to check / try.
> 
> Kind regards,
> Petr
> 
> [1] https://github.com/linux-test-project/ltp/tree/c2d4836c057fb9f78e7f625d71638d4f40f98659/testcases/kernel/syscalls/perf_event_open/perf_event_open02.c
>