strace | 15 | 0 | 7 | 321 T https://autobuilder.yocto.io/pub/non-release/20190907-13/testresults/qemux86-64-ptest/strace.log https://autobuilder.yocto.io/pub/non-release/20190907-13/testresults/qemux86-64-ptest/testresults.json
This has regressed somewhere between kernels 5.0 and 5.2. Using the latest strace commit does not help.
To just make the tests complete, we could lower the timeout in run-ptest: root@qemux86-64:/usr/lib/strace/ptest# cat run-ptest #!/bin/sh export TIMEOUT_DURATION=20 make -B -C tests -k test-suite.log Then ptest-runner strace results in: ============================================================================ Testsuite summary for strace 5.2 ============================================================================ # TOTAL: 685 # PASS: 508 # SKIP: 152 # XFAIL: 0 # FAIL: 25 # XPASS: 0 # ERROR: 0 That doesn't get to the root cause but it might be useful. -- debugging notes: The logs are full of this sort of thing: PASS: times.gen.test PASS: trace_fstatfs.gen.test [ 1311.457169] futex_atomic_op_inuser: 2 callbacks suppressed [ 1311.457178] futex_wake_op: futex tries to shift op by -849; fix this program [ 1311.460925] futex_wake_op: futex tries to shift op by -849; fix this program [ 1311.462768] futex_wake_op: futex tries to shift op by -518; fix this program [ 1311.464530] futex_wake_op: futex tries to shift op by -518; fix this program [ 1311.466296] futex_wake_op: futex tries to shift op by -1; fix this program [ 1311.467958] futex_wake_op: futex tries to shift op by -1; fix this program [ 1311.662242] futex_wake_op: futex tries to shift op by -849; fix this program [ 1311.668765] futex_wake_op: futex tries to shift op by -849; fix this program [ 1311.758758] futex_wake_op: futex tries to shift op by -518; fix this program [ 1311.765137] futex_wake_op: futex tries to shift op by -518; fix this program ^[[5~^[[5~PASS: trace_lstat.gen.test [ 1548.103763] futex_atomic_op_inuser: 2 callbacks suppressed [ 1548.103766] futex_wake_op: futex tries to shift op by -849; fix this program [ 1548.108061] futex_wake_op: futex tries to shift op by -849; fix this program [ 1548.109854] futex_wake_op: futex tries to shift op by -518; fix this program [ 1548.111585] futex_wake_op: futex tries to shift op by -518; fix this program [ 1548.113231] futex_wake_op: futex tries to shift op by -1; fix this program [ 1548.114920] futex_wake_op: futex tries to shift op by -1; fix this program [ 1548.323078] futex_wake_op: futex tries to shift op by -849; fix this program [ 1548.329742] futex_wake_op: futex tries to shift op by -849; fix this program [ 1548.421786] futex_wake_op: futex tries to shift op by -518; fix this program [ 1548.427759] futex_wake_op: futex tries to shift op by -518; fix this program PASS: trace_personality_32.gen.test [ 1782.230746] futex_atomic_op_inuser: 2 callbacks suppressed [ 1782.230749] futex_wake_op: futex tries to shift op by -849; fix this program [ 1782.234645] futex_wake_op: futex tries to shift op by -849; fix this program [ 1782.236784] futex_wake_op: futex tries to shift op by -518; fix this program [ 1782.238965] futex_wake_op: futex tries to shift op by -518; fix this program [ 1782.240844] futex_wake_op: futex tries to shift op by -1; fix this program [ 1782.242583] futex_wake_op: futex tries to shift op by -1; fix this program [ 1782.437341] futex_wake_op: futex tries to shift op by -849; fix this program [ 1782.443768] futex_wake_op: futex tries to shift op by -849; fix this program [ 1782.533780] futex_wake_op: futex tries to shift op by -518; fix this program [ 1782.539765] futex_wake_op: futex tries to shift op by -518; fix this program PASS: trace_personality_64.gen.test [ 2005.687170] futex_atomic_op_inuser: 2 callbacks suppressed [ 2005.687179] futex_wake_op: futex tries to shift op by -849; fix this program [ 2005.690868] futex_wake_op: futex tries to shift op by -849; fix this program PASS: trace_personality_regex_32.gen.test [ 2234.836985] futex_atomic_op_inuser: 2 callbacks suppressed PASS: trace_personality_regex_64.gen.test [ 2466.070901] futex_atomic_op_inuser: 2 callbacks suppressed Doing a bit of math (in my head even!) 2466 - 2234 = 232 2234 - 2005 = 229 2005 - 1782 = 223 1782 - 1548 = 234 1548 - 1311 = 237 Looks like a common timeout making all the tests slow. Suspending the tests and looking around: root@qemux86-64:~# ps -aef --forest UID PID PPID C STIME TTY TIME CMD ... root 336 299 0 00:45 ttyS0 00:00:00 \_ -sh root 345 336 0 00:46 ? 00:00:00 \_ ptest-runner strace root 346 345 0 00:46 pts/0 00:00:00 | \_ /bin/sh /usr/lib/strace/ptest/run-ptest root 347 346 0 00:46 pts/0 00:00:00 | \_ make -B -C tests -k test-suite.log root 16738 347 0 01:41 pts/0 00:00:00 | \_ /bin/sh -c p='trace_stat_like.gen.test'; \ case 'trace_stat_like.gen.log' in */*) root 16742 16738 0 01:41 pts/0 00:00:00 | \_ /bin/sh ../test-driver --test-name trace_stat_like.gen.test --log-file trace_s root 16743 16742 0 01:41 pts/0 00:00:00 | \_ timeout -k 5 -s XCPU 600 ./trace_stat_like.gen.test root 16747 16743 0 01:41 pts/0 00:00:00 | \_ /bin/sh -efu ./trace_stat_like.gen.test root 18632 16747 3 01:42 pts/0 00:00:04 | \_ ../../strace -o log -qq -esignal=none -e%%stat -v -P stat.sample - root 18635 18632 3 01:42 pts/0 00:00:04 | \_ ../printpath-umovestr so from there it was simple to reduce the timeout from 600 to 20 and have the tests complete. That kernel log message isn't new: e78c38f6bdd90 (Jiri Slaby 2017-10-23 13:41:51 +0200 1660) pr_info_ratelimited("futex_wake_op: %s tries to shift op by %d; fix this program\n", All for now.
The futex stuff is present also with 5.0 kernel, and even 4.18 kernel in Ubuntu, but the tests run much faster with those kernels, so it isn't relevant. I'd rather find out where the problem is than hide the issue by lowering the timeout.
Hints for bisecting the issue are welcome btw! How does one do it with linux-yocto?
I have narrowed this down a bit further: root@qemux86-64:/usr/lib/strace/ptest/tests# time ../strace -o log -qq -esignal=none -e/clock ./printpath-umovestr>ttt The above line takes several minutes on kernel 5.2, but only a couple seconds on 5.0. Removing the '-e/clock' makes it go much faster on 5.2 as well. Will try to dig further tomorrow. Something has regressed about processing regexps in -e option (between the two kernels!).
The slowness happens in the kernel, but I am not sure where to start there. I tried to build the 5.2 kernel with 5.0 kernel config, but it didn't help. Also the same 5.2.10 kernel on my opensuse machine executes those ptests fine and without delays. I'm out of ideas at this point, other than try to bisect the kernel.
After a painful bisecting session, the winner was declared: 76f969e8948d82e78e1bc4beb6b9465908e74873 is the first bad commit commit 76f969e8948d82e78e1bc4beb6b9465908e74873 Author: Roman Gushchin <guro@fb.com> Date: Fri Apr 19 10:03:04 2019 -0700 cgroup: cgroup v2 freezer Cgroup v1 implements the freezer controller, which provides an ability to stop the workload in a cgroup and temporarily free up some resources (cpu, io, network bandwidth and, potentially, memory) for some other tasks. Cgroup v2 lacks this functionality. This patch implements freezer for cgroup v2.
Upstream report: https://lkml.org/lkml/2019/5/13/713
Actually, this may not be the case, as the latest kernel already has a 'fix'. Will try more on Monday.
Right, the 'fix' seems to fix one issue with the freezer, but does not actually address the performance regression of the testsuite.
I can now confirm that it is definitely this: 76f969e8948d82e78e1bc4beb6b9465908e74873 is the first bad commit commit 76f969e8948d82e78e1bc4beb6b9465908e74873 Author: Roman Gushchin <guro@fb.com> Date: Fri Apr 19 10:03:04 2019 -0700 cgroup: cgroup v2 freezer I believe we now have everything needed for an upstream bug report, and a workaround.
The workaround is now in master. What remains is diagnosing the issue properly with upstream developers.
We need to track the kernel fix and when it's resolved, revert this work-around. Do you want to re-open this bug or should I create a new one?
Maybe reopen this one is better? I am actually not sure if RP and/or Bruce have reported the issue yet.
Add Bruce to CC to find out if the bug is reported and/or being worked on.
Let's reopen too.
Duplicate *** This bug has been marked as a duplicate of bug 13556 ***