ftrace:test.d--event--event-pid.tc fails with timeout on focal:linux-hwe-5.15 ARM64

Bug #2034476 reported by Po-Hsu Lin
6
This bug affects 1 person
Affects Status Importance Assigned to Milestone
ubuntu-kernel-tests
New
Undecided
Unassigned

Bug Description

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 (Test on instance loop) 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]
 ....
 + . /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
 [2] (instance) event tracing - restricts events based on pid
 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
 Timer expired (600 sec.), nuking pid 21312

From the code (tools/testing/selftests/ftrace/test.d/event/event-pid.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.

Po-Hsu Lin (cypressyew)
description: updated
Po-Hsu Lin (cypressyew)
description: updated
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.