ubuntu-kernel-tests

  1. Bug #2034476
  2. Activity log

Activity log for bug #2034476

Date Who What changed Old value New value Message
2023-09-06 02:37:23 Po-Hsu Lin bug added bug
2023-09-06 02:40:46 Po-Hsu Lin 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 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:  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.
2023-09-06 02:47:44 Po-Hsu Lin 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 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. 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.