Similar to bug 2029405, this is another ftrace subtest failed on ARM64 generic / generic-64k because the `cat trace` command took too long to run.
Issue found on ARM64 nodes with both generic / generic-64k kernel.
In this case, the first test has passed, it's the second test that cause the timeout.
Partial test log: Running './ftracetest -vvv test.d/event/event-pid.tc' === Ftrace unit tests === .... [1] event tracing - restricts events based on pid + [ 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-pid.tc + echo 0 + echo 1 + 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.097 ms
--- 127.0.0.1 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.097/0.097/0.097/0.000 ms + cat trace + grep sched_switch + wc -l + count=737 + [ 737 -eq 0 ] + do_reset + echo + echo + echo 0 + clear_trace + echo + read mypid rest + echo 21356 + grep -q 21356 set_event_pid + 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.043 ms
--- 127.0.0.1 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.043/0.043/0.043/0.000 ms + cat trace + grep sched_switch + grep -v pid=21356 + wc -l + count=0 + [ 0 -ne 0 ] + do_reset + echo + echo + echo 0 + clear_trace + echo + echo 21356 + echo 1 + echo 1 + 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.042 ms
--- 127.0.0.1 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.042/0.042/0.042/0.000 ms + cat trace + grep sched_switch + grep -v pid=21356 + wc -l + count=10325 + [ 10325 -eq 0 ] + do_reset + echo + echo + echo 0 + clear_trace + echo [PASS] .... [2] (instance) event tracing - restricts events based on pidPING 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.097 ms
--- 127.0.0.1 ping statistics --- 1 packets transmitted, 1 received, 0% packet loss, time 0ms rtt min/avg/max/mdev = 0.097/0.097/0.097/0.000 ms + cat trace + grep sched_switch + wc -l Timer expired (600 sec.), nuking pid 21312
Similar to bug 2029405, this is another ftrace subtest failed on ARM64 generic / generic-64k because the `cat trace` command took too long to run.
Issue found on ARM64 nodes with both generic / generic-64k kernel.
In this case, the first test has passed, it's the second test that cause the timeout.
Partial test log: event/event- pid.tc' autotest/ client/ tmp/ubuntu_ kselftests_ ftrace/ src/linux/ tools/testing/ selftests/ ftrace/ test.d/ event/event- pid.tc
Running './ftracetest -vvv test.d/
=== Ftrace unit tests ===
....
[1] event tracing - restricts events based on pid
+ [ 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/
+ echo 0
+ echo 1
+ 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.097 ms
--- 127.0.0.1 ping statistics --- 097/0.097/ 0.000 ms
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.097/0.
+ cat trace
+ grep sched_switch
+ wc -l
+ count=737
+ [ 737 -eq 0 ]
+ do_reset
+ echo
+ echo
+ echo 0
+ clear_trace
+ echo
+ read mypid rest
+ echo 21356
+ grep -q 21356 set_event_pid
+ 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.043 ms
--- 127.0.0.1 ping statistics --- 043/0.043/ 0.000 ms
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.043/0.
+ cat trace
+ grep sched_switch
+ grep -v pid=21356
+ wc -l
+ count=0
+ [ 0 -ne 0 ]
+ do_reset
+ echo
+ echo
+ echo 0
+ clear_trace
+ echo
+ echo 21356
+ echo 1
+ echo 1
+ 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.042 ms
--- 127.0.0.1 ping statistics --- 042/0.042/ 0.000 ms
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.042/0.
+ cat trace
+ grep sched_switch
+ grep -v pid=21356
+ wc -l
+ count=10325
+ [ 10325 -eq 0 ]
+ do_reset
+ echo
+ echo
+ echo 0
+ clear_trace
+ echo
[PASS]
....
[2] (instance) event tracing - restricts events based on pidPING 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.097 ms
--- 127.0.0.1 ping statistics --- 097/0.097/ 0.000 ms
1 packets transmitted, 1 received, 0% packet loss, time 0ms
rtt min/avg/max/mdev = 0.097/0.
+ cat trace
+ grep sched_switch
+ wc -l
Timer expired (600 sec.), nuking pid 21312