https://lists.ubuntu.com/archives/kernel-team/2023-November/147192.html
** Description changed: - First time seen this since ftrace refactor out from - ubuntu_kernel_selftests to ubuntu-kselftests-ftrace + + [Impact] + On ARM64 systems, tests like event-enable.tc, event-pid.tc in + linux/tools/testing/selftests/ftrace will take too much time to run + and consequently leading to test timeout. + + The culprit is the `cat` command on the changing trace file. + + [Fix] + * 25b9513872 selftests/ftrace: Stop tracing while reading the trace + file by default + + This patch can be cherry-picked into Jammy. I didn't see this issue in + our 5.4 kernels. And it's already landed in newer kernels. + + [Test] + On an ARM64 testing node, apply this patch to the kernel tree and run + event-pid.tc test in linux/tools/testing/selftests/ftrace with: + + sudo ./ftracetest -vvv test.d/event/event-pid.tc + + The test should finish within a few minutes. + + [Regression Potential] + Change limited to testing tools, it should not have any actual impact + to kernel functions. + + == Original Bug Report == + First time seen this since ftrace refactor out from ubuntu_kernel_selftests to ubuntu-kselftests-ftrace Issue found on ARM64 nodes with both generic / generic-64k kernel. Partial test log: - Running './ftracetest -vvv test.d/event/subsystem-enable.tc' - === Ftrace unit tests === - .... - [1] event tracing - enable/disable with event level files - + [ 2 -eq 1 ] - + [ -f set_event_pid ] - + echo - + [ -f set_ftrace_pid ] - + echo - + [ -f set_ftrace_notrace ] - + echo - + [ -f set_graph_function ] - + echo - + tee set_graph_function set_graph_notrace - + [ -f stack_trace_filter ] - + echo - + [ -f kprobe_events ] - + echo - + [ -f uprobe_events ] - + echo - + [ -f synthetic_events ] - + echo - + [ -f snapshot ] - + echo 0 - + clear_trace - + echo - + enable_tracing - + echo 1 - + . /home/ubuntu/autotest/client/tmp/ubuntu_kselftests_ftrace/src/linux/tools/testing/selftests/ftrace/test.d/event/event-enable.tc - + echo sched:sched_switch - + yield - + ping 127.0.0.1 -c 1 - PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data. - 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.096 ms - - --- 127.0.0.1 ping statistics --- - 1 packets transmitted, 1 received, 0% packet loss, time 0ms - rtt min/avg/max/mdev = 0.096/0.096/0.096/0.000 ms - + cat trace - + grep sched_switch - + wc -l - Timer expired (600 sec.), nuking pid 20982 + Running './ftracetest -vvv test.d/event/subsystem-enable.tc' + === Ftrace unit tests === + .... + [1] event tracing - enable/disable with event level files + + [ 2 -eq 1 ] + + [ -f set_event_pid ] + + echo + + [ -f set_ftrace_pid ] + + echo + + [ -f set_ftrace_notrace ] + + echo + + [ -f set_graph_function ] + + echo + + tee set_graph_function set_graph_notrace + + [ -f stack_trace_filter ] + + echo + + [ -f kprobe_events ] + + echo + + [ -f uprobe_events ] + + echo + + [ -f synthetic_events ] + + echo + + [ -f snapshot ] + + echo 0 + + clear_trace + + echo + + enable_tracing + + echo 1 + + . /home/ubuntu/autotest/client/tmp/ubuntu_kselftests_ftrace/src/linux/tools/testing/selftests/ftrace/test.d/event/event-enable.tc + + echo sched:sched_switch + + yield + + ping 127.0.0.1 -c 1 + PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data. + 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.096 ms + + --- 127.0.0.1 ping statistics --- + 1 packets transmitted, 1 received, 0% packet loss, time 0ms + rtt min/avg/max/mdev = 0.096/0.096/0.096/0.000 ms + + cat trace + + grep sched_switch + + wc -l + Timer expired (600 sec.), nuking pid 20982 From the code (tools/testing/selftests/ftrace/test.d/event/event- enable.tc) this test is trying to run: - count=`cat trace | grep sched_switch | wc -l` + count=`cat trace | grep sched_switch | wc -l` This command caused the timeout as `cat trace` seems to be never ending. ** Description changed: - [Impact] - On ARM64 systems, tests like event-enable.tc, event-pid.tc in - linux/tools/testing/selftests/ftrace will take too much time to run - and consequently leading to test timeout. + On ARM64 systems, tests like subsystem-enable.tc, event-enable.tc, + event-pid.tc in linux/tools/testing/selftests/ftrace will take too + much time to run and consequently leads to test timeout. The culprit is the `cat` command on the changing trace file. [Fix] * 25b9513872 selftests/ftrace: Stop tracing while reading the trace - file by default + file by default This patch can be cherry-picked into Jammy. I didn't see this issue in our 5.4 kernels. And it's already landed in newer kernels. [Test] On an ARM64 testing node, apply this patch to the kernel tree and run event-pid.tc test in linux/tools/testing/selftests/ftrace with: - sudo ./ftracetest -vvv test.d/event/event-pid.tc + sudo ./ftracetest -vvv test.d/event/event-pid.tc The test should finish within a few minutes. [Regression Potential] Change limited to testing tools, it should not have any actual impact to kernel functions. == Original Bug Report == First time seen this since ftrace refactor out from ubuntu_kernel_selftests to ubuntu-kselftests-ftrace Issue found on ARM64 nodes with both generic / generic-64k kernel. Partial test log: Running './ftracetest -vvv test.d/event/subsystem-enable.tc' === Ftrace unit tests === .... [1] event tracing - enable/disable with event level files + [ 2 -eq 1 ] + [ -f set_event_pid ] + echo + [ -f set_ftrace_pid ] + echo + [ -f set_ftrace_notrace ] + echo + [ -f set_graph_function ] + echo + tee set_graph_function set_graph_notrace + [ -f stack_trace_filter ] + echo + [ -f kprobe_events ] + echo + [ -f uprobe_events ] + echo + [ -f synthetic_events ] + echo + [ -f snapshot ] + echo 0 + clear_trace + echo + enable_tracing + echo 1 + . /home/ubuntu/autotest/client/tmp/ubuntu_kselftests_ftrace/src/linux/tools/testing/selftests/ftrace/test.d/event/event-enable.tc + echo sched:sched_switch + yield + ping 127.0.0.1 -c 1 PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data. 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.096 ms --- 127.0.0.1 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.096/0.096/0.096/0.000 ms + cat trace + grep sched_switch + wc -l Timer expired (600 sec.), nuking pid 20982 From the code (tools/testing/selftests/ftrace/test.d/event/event- enable.tc) this test is trying to run: count=`cat trace | grep sched_switch | wc -l` This command caused the timeout as `cat trace` seems to be never ending. ** Tags added: sru-20231030 -- You received this bug notification because you are a member of Kernel Packages, which is subscribed to linux in Ubuntu. https://bugs.launchpad.net/bugs/2029405 Title: Change in trace file leads to test timeout in ftrace tests on 5.15 ARM64 Status in ubuntu-kernel-tests: In Progress Status in linux package in Ubuntu: Fix Released Status in linux source package in Jammy: In Progress Bug description: [Impact] On ARM64 systems, tests like subsystem-enable.tc, event-enable.tc, event-pid.tc in linux/tools/testing/selftests/ftrace will take too much time to run and consequently leads to test timeout. The culprit is the `cat` command on the changing trace file. [Fix] * 25b9513872 selftests/ftrace: Stop tracing while reading the trace file by default This patch can be cherry-picked into Jammy. I didn't see this issue in our 5.4 kernels. And it's already landed in newer kernels. [Test] On an ARM64 testing node, apply this patch to the kernel tree and run event-pid.tc test in linux/tools/testing/selftests/ftrace with: sudo ./ftracetest -vvv test.d/event/event-pid.tc The test should finish within a few minutes. [Regression Potential] Change limited to testing tools, it should not have any actual impact to kernel functions. == Original Bug Report == First time seen this since ftrace refactor out from ubuntu_kernel_selftests to ubuntu-kselftests-ftrace Issue found on ARM64 nodes with both generic / generic-64k kernel. Partial test log: Running './ftracetest -vvv test.d/event/subsystem-enable.tc' === Ftrace unit tests === .... [1] event tracing - enable/disable with event level files + [ 2 -eq 1 ] + [ -f set_event_pid ] + echo + [ -f set_ftrace_pid ] + echo + [ -f set_ftrace_notrace ] + echo + [ -f set_graph_function ] + echo + tee set_graph_function set_graph_notrace + [ -f stack_trace_filter ] + echo + [ -f kprobe_events ] + echo + [ -f uprobe_events ] + echo + [ -f synthetic_events ] + echo + [ -f snapshot ] + echo 0 + clear_trace + echo + enable_tracing + echo 1 + . /home/ubuntu/autotest/client/tmp/ubuntu_kselftests_ftrace/src/linux/tools/testing/selftests/ftrace/test.d/event/event-enable.tc + echo sched:sched_switch + yield + ping 127.0.0.1 -c 1 PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data. 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.096 ms --- 127.0.0.1 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.096/0.096/0.096/0.000 ms + cat trace + grep sched_switch + wc -l Timer expired (600 sec.), nuking pid 20982 From the code (tools/testing/selftests/ftrace/test.d/event/event- enable.tc) this test is trying to run: count=`cat trace | grep sched_switch | wc -l` This command caused the timeout as `cat trace` seems to be never ending. To manage notifications about this bug go to: https://bugs.launchpad.net/ubuntu-kernel-tests/+bug/2029405/+subscriptions -- Mailing list: https://launchpad.net/~kernel-packages Post to : kernel-packages@lists.launchpad.net Unsubscribe : https://launchpad.net/~kernel-packages More help : https://help.launchpad.net/ListHelp
