canonical-ubuntu-qa team mailing list archive

[Po-Hsu Lin <2034476@xxxxxxxxxxxxxxxxxx>]

Public bug reported:

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.

** Affects: ubuntu-kernel-tests
     Importance: Undecided
         Status: New


** Tags: 5.15 arm64 focal sru-20230807 ubuntu-kselftests-ftrace

** Description changed:

  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
+  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
-  + 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
+  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.

-- 
You received this bug notification because you are a member of Canonical
Platform QA Team, which is subscribed to ubuntu-kernel-tests.
https://bugs.launchpad.net/bugs/2034476

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

Status in ubuntu-kernel-tests:
  New

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.

To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu-kernel-tests/+bug/2034476/+subscriptions