Bug 13506

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 ***