ftrace:test.d--event--event-pid.tc fails with timeout on focal:linux-hwe-5.15 ARM64
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/
=== 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 ---
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 ---
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 ---
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]
....
+ . /home/ubuntu/
+ 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.
+ cat trace
+ grep sched_switch
+ wc -l
Timer expired (600 sec.), nuking pid 21312
From the code (tools/
count=`cat trace | grep sched_switch | wc -l`
This command caused the timeout as `cat trace` seems to be never ending.