6 sub-tests from ubuntu_kselftests_ftrace failed with ARM64k
| Affects | Status | Importance | Assigned to | Milestone | |
|---|---|---|---|---|---|
| ubuntu-kernel-tests |
New
|
Undecided
|
Unassigned | ||
Bug Description
Before running the ftrace sub-tests one-by-one with -vvv flag (https:/
* [16] event tracing - enable/disable with event level files
* [19] event tracing - enable/disable with subsystem level files
The whole test will be interrupted on this point.
By running tests one-by-one with -vvv flag, it will have a chance to run though all sub-tests, with following failures:
(step 16)
* ftrace:
* ftrace:
(step 19)
* ftrace:
* ftrace:
* ftrace:
* ftrace:
So if it hung with step 16, you will see 6 failures reported. But if it hung with step 19 before the test improvement, you will see just 4 failures.
This is not a regression but some new issues revealed with this test case improvement.
They all timeout with the 600 seconds threshold. I did test these manually and it seems the culprit is the never ending `cat trace | grep sched_switch | wc -l` command for /sys/kernel/
I will paste the ending part of each tests below, you will find a more complete output in the attachments:
* ftrace:
[stderr] + . /home/ubuntu/
[stderr] + echo sched:sched_switch
[stderr] + yield
[stderr] + ping 127.0.0.1 -c 1
[stdout] PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
[stdout] 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.058 ms
[stdout]
[stdout] --- 127.0.0.1 ping statistics ---
[stdout] 1 packets transmitted, 1 received, 0% packet loss, time 0ms
[stdout] rtt min/avg/max/mdev = 0.058/0.
[stderr] + cat trace
[stderr] + grep sched_switch
[stderr] + wc -l
Timer expired (600 sec.), nuking pid 23930
* ftrace:
[stderr] + . /home/ubuntu/
[stderr] + echo 0
[stderr] + echo 1
[stderr] + yield
[stderr] + ping 127.0.0.1 -c 1
[stdout] PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
[stdout] 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.055 ms
[stdout]
[stdout] --- 127.0.0.1 ping statistics ---
[stdout] 1 packets transmitted, 1 received, 0% packet loss, time 0ms
[stdout] rtt min/avg/max/mdev = 0.055/0.
[stderr] + cat trace
[stderr] + grep sched_switch
[stderr] + wc -l
Timer expired (600 sec.), nuking pid 24304
* ftrace:
[stderr] + . /home/ubuntu/
[stderr] + echo sched:*
[stderr] + yield
[stderr] + ping 127.0.0.1 -c 1
[stdout] PING 127.0.0.1 (127.0.0.1) 56(84) bytes of data.
[stdout] 64 bytes from 127.0.0.1: icmp_seq=1 ttl=64 time=0.064 ms
[stdout]
[stdout] --- 127.0.0.1 ping statistics ---
[stdout] 1 packets transmitted, 1 received, 0% packet loss, time 0ms
[stdout] rtt min/avg/max/mdev = 0.064/0.
[stderr] + cat trace
[stderr] + grep -v ^#
[stderr] + awk { print $5 }
[stderr] + sort -u
[stderr] + wc -l
Timer expired (600 sec.), nuking pid 24412
* ftrace:
[stderr] + . /home/ubuntu/
[stderr] + disable_tracing
[stderr] + echo 0
[stderr] + clear_trace
[stderr] + echo
[stderr] + echo schedule
[stderr] + echo function_graph
[stdout] Now testing with stack tracer
[stderr] + echo Now testing with stack tracer
[stderr] + echo 1
[stderr] + disable_tracing
[stderr] + echo 0
[stderr] + clear_trace
[stderr] + echo
[stderr] + enable_tracing
[stderr] + echo 1
[stderr] + sleep 1
[stderr] + cat trace
[stderr] + grep ()
[stderr] + grep -v schedule
[stderr] + wc -l
[stderr] + count=0
[stderr] + [ 0 -ne 0 ]
[stderr] + cat trace
[stderr] + grep schedule()
[stderr] + wc -l
[stderr] + count=46070
[stderr] + [ 46070 -eq 0 ]
[stderr] + echo 0
[stderr] + clear_trace
[stderr] + echo
[stderr] + sleep 1
[stderr] + cat trace
[stderr] + grep ()
[stderr] + grep -v schedule
[stderr] + wc -l
Timer expired (600 sec.), nuking pid 24930
* ftrace:
[stderr] + . /home/ubuntu/
[stderr] + disable_tracing
[stderr] + echo 0
[stderr] + clear_trace
[stderr] + echo
[stderr] + echo schedule
[stderr] + echo function_graph
[stderr] + enable_tracing
[stderr] + echo 1
[stderr] + sleep 1
[stderr] + cat trace
[stderr] + grep ()
[stderr] + grep -v schedule
[stderr] + wc -l
[stderr] + count=0
[stderr] + [ 0 -ne 0 ]
[stderr] + cat trace
[stderr] + grep schedule()
[stderr] + wc -l
Timer expired (600 sec.), nuking pid 25115
* ftrace:
[stderr] + . /home/ubuntu/
[stdout] Testing function probes with enabling disabling tracing:
[stdout] ** DISABLE TRACING
[stderr] + SLEEP_TIME=.1
[stderr] + echo Testing function probes with enabling disabling tracing:
[stderr] + echo ** DISABLE TRACING
[stderr] + disable_tracing
[stderr] + echo 0
[stderr] + clear_trace
[stderr] + echo
[stderr] + cnt_trace
[stderr] + grep -v ^# trace
[stderr] + wc -l
[stderr] + cnt=0
[stderr] + [ 0 -ne 0 ]
[stderr] + echo ** ENABLE EVENTS
[stdout] ** ENABLE EVENTS
[stdout] ** ENABLE TRACING
[stderr] + echo 1
[stderr] + echo ** ENABLE TRACING
[stderr] + enable_tracing
[stderr] + echo 1
[stderr] + cnt_trace
[stderr] + grep -v ^# trace
[stderr] + wc -l
Timer expired (600 sec.), nuking pid 27469
| Po-Hsu Lin (cypressyew) wrote | #1 |
| Po-Hsu Lin (cypressyew) wrote | #2 |
| Po-Hsu Lin (cypressyew) wrote | #3 |
| Po-Hsu Lin (cypressyew) wrote | #4 |
| Po-Hsu Lin (cypressyew) wrote | #5 |
| Po-Hsu Lin (cypressyew) wrote | #6 |
| description: | updated |
| Jacob Martin (jacobmartin) wrote | #7 |
Complete test log for ftrace: