Bug 13556

Created attachment 4569 [details]
2.8_M3_RC1_Report

make this strace only

*** Bug 13506 has been marked as a duplicate of this bug. ***

We do have a patch to upgrade strace to version 5.3, test run here:
https://autobuilder.yocto.io/pub/non-release/20190926-14/testresults/qemux86-64-ptest/strace.log
however the failures are still present.

There's a thread on lkml: 
   https://lkml.org/lkml/2019/10/1/1486

I was curious about what was going wrong in the kernel in this case so I tried using 'perf trace' as a first warm-up step since my perf-foo is not good.
I was surprised to see:

# time strace -o log -qq -esignal=none -e/clock ./printpath-umovestr > ttt
-- 4m11s
# time perf trace -o perf-stace-printpath.log strace -o under-perf-log -qq -esignal=none -e/clock ./printpath-umovestr > ttt-perf
--> 8 seconds

but

# cmp ttt ttt-perf
ttt ttt-perf differ: char 126658361, line 61426

the ttt-perf log line reads:
   chdir(0x7f6c80e99001) = -1 EFAULT (Bad address)

This happens when the length of the string passed to chdir() and maybe memmove() in:
test_printpath_at(char *const p, const unsigned int test_max)
...
		memmove(eop - i, eop - i_1, i_1);
		eop[-1] = "/.."[i_1 % 3];
		if (chdir(eop - i))
...
goes over the PATH_MAX limit of 4096.

That's likely where the slowdown starts but I haven't confirmed that yet.
I could change the test code to run 2 tests rather than 8192. I'd do N loops at length 4096-128 and at 4096+128 and time each or something simpler. I expect the times to be close on an older kernel and quite different on a newer buggy kernel. 

More tomorrow, albeit in between meetings. :-(

Patch sent to list.

Here is the discussing detail on upstream mailing list

https://lkml.org/lkml/2019/10/8/450
https://lkml.org/lkml/2019/10/8/783
https://lkml.org/lkml/2019/10/8/495
https://lkml.org/lkml/2019/10/8/783

Here is the quick reproduce way

$ cat >> test.c << ENDOF
#include <stdio.h>
#include <string.h>

int main(int argc, char *argv[])
{
#define TEST_MAX 4096
    char p[TEST_MAX] = {0};
    char *const eop = p + (TEST_MAX - 1); 
    int i;
    for (i = 1; i < TEST_MAX; ++i) {
        const int i_1 = i - 1;
        memmove(eop - i, eop - i_1, i_1);
        eop[-1] = "/.."[i_1 % 3]; 
        printf("%s\n", eop - i); 
    }   

  return 0;
}
ENDOF

$ gcc test.c -o test

$ time strace  -e/clock ./test >ttt
real	0m8.386s
user	0m0.227s
sys	0m0.128s

$ time strace  -e/clock ./test >/dev/null
real	0m0.338s
user	0m0.033s
sys	0m0.043s

After applying the fix on kernel source
--- a/kernel/signal.c
+++ b/kernel/signal.c
@@ -2155,8 +2155,8 @@ static void ptrace_stop(int exit_code, int why, int clear_code, kernel_siginfo_t
                 */
                preempt_disable();
                read_unlock(&tasklist_lock);
-               preempt_enable_no_resched();
                cgroup_enter_frozen();
+               preempt_enable_no_resched();
                freezable_schedule();
                cgroup_leave_frozen(true);
        } else {

Here is the test result:
root@qemux86-64:~# time strace  -e/clock ./test >ttt
+++ exited with 0 +++

real	0m0.132s
user	0m0.028s
sys	0m0.100s
root@qemux86-64:~# time strace  -e/clock ./test >/dev/null
+++ exited with 0 +++

real	0m0.074s
user	0m0.022s
sys	0m0.050s

I'm not sure why the status of this was changed back to NEW, but Richard has the patches for this and they are in the M4 build. Moving it back to "in progress review".

(In reply to comment #10)
> I'm not sure why the status of this was changed back to NEW, but Richard has
> the patches for this and they are in the M4 build. Moving it back to "in
> progress review".

Sorry, I incorrectly click on the save button

Thanks everyone for the work on this, a good one to fix!

http://git.yoctoproject.org/cgit.cgi/poky/commit/?id=cdb9ea2a8b74d6675bd1af31835995a8f983bbf3

Also note that we are intentionally leaving the timeout in run-ptest at 30 seconds.