ubuntu_ftrace_smoke_test timeout on F-5.15/H/J/K-riscv

[Po-Hsu Lin]

Issue found on 5.8.0-13.15 RISCV with a KVM instance.

Test failed with "Timer expired (1350 sec.), nuking pid 520", test log:
$ AUTOTEST_PATH=/home/ubuntu/autotest sudo -E autotest/client/autotest-local --verbose autotest/client/tests/ubuntu_ftrace_smoke_test/control
03:46:12 INFO | Writing results to /home/ubuntu/autotest/client/results/default
03:46:12 DEBUG| Initializing the state engine
03:46:12 DEBUG| Persistent state client.steps now set to []
03:46:13 DEBUG| Persistent option harness now set to None
03:46:13 DEBUG| Persistent option harness_args now set to None
03:46:13 DEBUG| Selected harness: standalone
03:46:15 INFO | START ---- ---- timestamp=1609127175 localtime=Dec 28 03:46:15
03:46:16 DEBUG| Persistent state client._record_indent now set to 1
03:46:16 DEBUG| Test has timeout: 1350 sec.
03:46:16 INFO | START ubuntu_ftrace_smoke_test.ftrace-smoke-test ubuntu_ftrace_smoke_test.ftrace-smoke-test timestamp=1609127176 timeout=1350 localtime=Dec 28 03:46:16
03:46:16 DEBUG| Persistent state client._record_indent now set to 2
03:46:16 DEBUG| Persistent state client.unexpected_reboot now set to ('ubuntu_ftrace_smoke_test.ftrace-smoke-test', 'ubuntu_ftrace_smoke_test.ftrace-smoke-test')
03:46:16 DEBUG| Waiting for pid 520 for 1350 seconds
03:46:16 WARNI| System python is too old, crash handling disabled
03:46:16 DEBUG| Running '/home/ubuntu/autotest/client/tests/ubuntu_ftrace_smoke_test/ubuntu_ftrace_smoke_test.sh'
03:46:16 DEBUG| [stdout] PASSED (CONFIG_FUNCTION_TRACER=y in /boot/config-5.8.0-13-generic)
03:46:17 DEBUG| [stdout] PASSED (CONFIG_FUNCTION_GRAPH_TRACER=y in /boot/config-5.8.0-13-generic)
03:46:17 DEBUG| [stdout] PASSED (CONFIG_STACK_TRACER=y in /boot/config-5.8.0-13-generic)
03:46:17 DEBUG| [stdout] PASSED (CONFIG_DYNAMIC_FTRACE=y in /boot/config-5.8.0-13-generic)
03:46:19 DEBUG| [stdout] PASSED all expected /sys/kernel/debug/tracing files exist
03:46:19 DEBUG| [stdout] PASSED (function_graph in /sys/kernel/debug/tracing/available_tracers)
03:46:19 DEBUG| [stdout] PASSED (function in /sys/kernel/debug/tracing/available_tracers)
03:46:20 DEBUG| [stdout] PASSED (nop in /sys/kernel/debug/tracing/available_tracers)
03:46:26 DEBUG| [stdout] PASSED (tracer function can be enabled)
03:46:35 DEBUG| [stdout] PASSED (tracer function_graph can be enabled)
03:46:35 DEBUG| [stdout] - tracer function_graph got enough data
03:46:35 DEBUG| [stdout] - tracer function_graph completed
03:46:36 DEBUG| [stdout] - tracer function_graph being turned off
03:46:36 DEBUG| [stdout] - tracer got 532 irq events
03:46:43 DEBUG| [stdout] - tracer hwlat got enough data
03:46:43 DEBUG| [stdout] - tracer hwlat completed
03:46:43 DEBUG| [stdout] - tracer hwlat being turned off
03:46:44 DEBUG| [stdout] - tracer nop being set as current tracer
03:46:46 DEBUG| [stdout] PASSED (tracer hwlat can be enabled (got 12 lines of tracing output))
03:46:48 DEBUG| [stdout] - tracer blk got enough data
03:46:48 DEBUG| [stdout] - tracer blk completed
03:46:48 DEBUG| [stdout] - tracer blk being turned off
03:46:48 DEBUG| [stdout] - tracer nop being set as current tracer
03:46:50 DEBUG| [stdout] PASSED (tracer blk can be enabled (got 2 lines of tracing output))
03:46:56 INFO | Timer expired (1350 sec.), nuking pid 520
03:46:57 INFO | ERROR ubuntu_ftrace_smoke_test.ftrace-smoke-test ubuntu_ftrace_smoke_test.ftrace-smoke-test timestamp=1609127216 localtime=Dec 28 03:46:56 Unhandled AutoservRunError: Could not kill 520
  None
  Traceback (most recent call last):
    File "/home/ubuntu/autotest/client/job.py", line 510, in _runtest
      parallel.fork_waitfor_timed(self.resultdir, pid, timeout)
    File "/home/ubuntu/autotest/client/parallel.py", line 112, in fork_waitfor_timed
      utils.nuke_pid(pid)
    File "/home/ubuntu/autotest/client/shared/utils.py", line 1214, in nuke_pid
      raise error.AutoservRunError('Could not kill %d' % pid, None)
  AutoservRunError: Could not kill 520
  None

03:46:57 INFO | END ERROR ubuntu_ftrace_smoke_test.ftrace-smoke-test ubuntu_ftrace_smoke_test.ftrace-smoke-test timestamp=1609127217 localtime=Dec 28 03:46:57

[Kelsey Steele (kelsey-steele)]

There still seems to be a timeout occurring on G/riscv and F/riscv-5.8, though the results cut off:

04/13 22:39:04 DEBUG| utils:0116| Running '/home/ubuntu/autotest/client/tests/ubuntu_ftrace_smoke_test/ubuntu_ftrace_smoke_test.sh'
04/13 22:39:04 DEBUG| utils:0153| [stdout] PASSED (CONFIG_FUNCTION_TRACER=y in /boot/config-5.8.0-21-generic)
04/13 22:39:04 DEBUG| utils:0153| [stdout] PASSED (CONFIG_FUNCTION_GRAPH_TRACER=y in /boot/config-5.8.0-21-generic)
04/13 22:39:04 DEBUG| utils:0153| [stdout] PASSED (CONFIG_STACK_TRACER=y in /boot/config-5.8.0-21-generic)
04/13 22:39:05 DEBUG| utils:0153| [stdout] PASSED (CONFIG_DYNAMIC_FTRACE=y in /boot/config-5.8.0-21-generic)
04/13 22:39:07 DEBUG| utils:0153| [stdout] PASSED all expected /sys/kernel/debug/tracing files exist
04/13 22:39:07 DEBUG| utils:0153| [stdout] PASSED (function_graph in /sys/kernel/debug/tracing/available_tracers)
04/13 22:39:07 DEBUG| utils:0153| [stdout] PASSED (function in /sys/kernel/debug/tracing/available_tracers)
04/13 22:39:07 DEBUG| utils:0153| [stdout] PASSED (nop in /sys/kernel/debug/tracing/available_tracers)
04/13 22:39:13 DEBUG| utils:0153| [stdout] PASSED (tracer function can be enabled)
04/13 22:39:22 DEBUG| utils:0153| [stdout] PASSED (tracer function_graph can be enabled)

[Guilherme G. Piccoli (gpiccoli)]

Observed on G/RISC-V , cycle sru-20210510 .

[Kelsey Steele (kelsey-steele)]

Seeing on Hirsute/riscv 5.11.0-1010.10

[Guilherme G. Piccoli (gpiccoli)]

Observed on G/RISC-V , cycle sru-20210531 .

[Po-Hsu Lin (cypressyew)]

Found on 5.11.0-1014.14~20.04.1 RISCV

[Kleber Sacilotto de Souza (kleber-souza)]

Groovy has reached EOL and hirsute/linux-riscv is also affected. Adjusting bug accordingly.

[Brian Murray (brian-murray)]

The Hirsute Hippo has reached End of Life, so this bug will not be fixed for that release.

[Po-Hsu Lin (cypressyew)]

This happens with the current 15 min timeout on J-riscv, K-riscv, F-5.15-riscv

They're failing even with 30 min.

45 works.

[Po-Hsu Lin (cypressyew)]

https://git.launchpad.net/~canonical-kernel-team/+git/autotest-client-tests/commit/?id=6c4955b36b2806abb402ebafd1978245425581e2