Comment 0 for bug 2034476

Revision history for this message
Po-Hsu Lin (cypressyew) wrote :

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