13506 2019-09-07 23:02:13 +0000 [master-next] strace ptest timed out 2019-09-26 15:13:29 +0000 1 1 7 Build System, Metadata & Runtime OE-Core core 3.0 x86 Multiple RESOLVED DUPLICATE 13556 High normal 2.8 M4 1 akuster alex.kanavin bruce.ashfield meta.mr.watcher meta.watcher randy.macleod richard.purdie --- --- Don't know oldest_to_newest 84902 0 akuster 2019-09-07 23:02:13 +0000 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 84910 1 alex.kanavin 2019-09-10 17:18:01 +0000 This has regressed somewhere between kernels 5.0 and 5.2. Using the latest strace commit does not help. 84923 2 randy.macleod 2019-09-11 02:21:42 +0000 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. 84925 3 alex.kanavin 2019-09-11 10:07:56 +0000 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. 84944 4 alex.kanavin 2019-09-12 15:43:35 +0000 Hints for bisecting the issue are welcome btw! How does one do it with linux-yocto? 84950 5 alex.kanavin 2019-09-12 17:53:13 +0000 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!). 84951 6 alex.kanavin 2019-09-13 13:36:51 +0000 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. 84953 7 alex.kanavin 2019-09-13 17:08:23 +0000 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. 84954 8 alex.kanavin 2019-09-13 17:21:31 +0000 Upstream report: https://lkml.org/lkml/2019/5/13/713 84955 9 alex.kanavin 2019-09-13 17:27:21 +0000 Actually, this may not be the case, as the latest kernel already has a 'fix'. Will try more on Monday. 84956 10 alex.kanavin 2019-09-13 17:38:02 +0000 Right, the 'fix' seems to fix one issue with the freezer, but does not actually address the performance regression of the testsuite. 84957 11 alex.kanavin 2019-09-13 18:49:30 +0000 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. 85051 12 alex.kanavin 2019-09-24 10:39:53 +0000 The workaround is now in master. What remains is diagnosing the issue properly with upstream developers. 85053 13 randy.macleod 2019-09-24 14:50:36 +0000 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? 85054 14 alex.kanavin 2019-09-24 14:54:14 +0000 Maybe reopen this one is better? I am actually not sure if RP and/or Bruce have reported the issue yet. 85055 15 randy.macleod 2019-09-24 15:14:43 +0000 Add Bruce to CC to find out if the bug is reported and/or being worked on. 85056 16 alex.kanavin 2019-09-24 15:16:05 +0000 Let's reopen too. 85098 17 sjolley.yp.pm 2019-09-26 15:13:29 +0000 Duplicate *** This bug has been marked as a duplicate of bug 13556 ***