13257 2019-04-02 01:49:32 +0000 [2.7 M3 rc1] python3 ptest facing timeout issue 2019-05-09 15:23:06 +0000 1 1 11 Runtime General Runtime General Runtime 2.7 x86 Multiple RESOLVED FIXED Medium+ normal 2.7 M4 1 ee.peng.yeoh ross.burton alex.kanavin bruce.ashfield richard.purdie --- --- Don't know oldest_to_newest 83398 0 ee.peng.yeoh 2019-04-02 01:49:32 +0000 Using qemux86 to boot core-image-sato-sdk-ptest_qemux86-64, python3 ptest facing timeout issue. Refer to report at: https://autobuilder.yocto.io/pub/releases/yocto-2.7_M3.rc1/testresults/testresult-report.txt 83449 1 alex.kanavin 2019-04-04 16:42:47 +0000 After applying this patch to ptest-runner: https://lists.yoctoproject.org/pipermail/yocto/2019-April/044725.html the timeout issue that still remains is that httplib test of python3 takes more than 5 minutes to execute (5 minutes is ptest-runner's default that we probably should increase): 0:06:39 load avg: 0.76 [177/416/1] test_http_cookies 0:06:39 load avg: 0.76 [178/416/1] test_httplib ERROR: Exit status is 9 DURATION: 701 TIMEOUT: /usr/lib/python3/ptest END: /usr/lib/python3/ptest 2019-04-04T16:40 STOP: /home/root/ptest-runner 83451 2 alex.kanavin 2019-04-04 17:25:28 +0000 It seems that httplib is genuinely stuck. With additional verbosity it stops here: PASS: test_readinto_head (test.test_httplib.BasicTest) PASS: test_readline_bound_content_length (test.test_httplib.BasicTest) PASS: test_readlines_content_length (test.test_httplib.BasicTest) 83465 3 alex.kanavin 2019-04-06 09:55:33 +0000 After a bit of bisecting, I can confirm that this commit is introducing the issue :( a7ba3a7a3e134fd9bfd5c700c2f34edcdf3a689b is the first bad commit commit a7ba3a7a3e134fd9bfd5c700c2f34edcdf3a689b Author: Bruce Ashfield <bruce.ashfield@gmail.com> Date: Tue Mar 5 21:26:45 2019 -0500 poky/kernel: make default 5.0 (From meta-yocto rev: a1b111f742ac781cf35769e52cac29125569cb9b) Signed-off-by: Bruce Ashfield <bruce.ashfield@gmail.com> Signed-off-by: Richard Purdie <richard.purdie@linuxfoundation.org> How to reproduce: root@qemux86-64:~# python3 -m test test_httplib Run tests sequentially 0:00:00 load avg: 0.00 [1/1] test_httplib (blocks forever here, in roughly 9 attempts out of 10) ^CWarning -- threading._dangling was modified by test_httplib Before: <_weakrefset.WeakSet object at 0x7f44a1a8a8d0> After: <_weakrefset.WeakSet object at 0x7f44a1a8a6a0> == Tests result: INTERRUPTED == Test suite interrupted by signal SIGINT. 1 test omitted: test_httplib Total duration: 926 ms Tests result: INTERRUPTED ^CException ignored in: <module 'threading' from '/usr/lib/python3.7/threading.py'> Traceback (most recent call last): File "/usr/lib/python3.7/threading.py", line 1273, in _shutdown t.join() File "/usr/lib/python3.7/threading.py", line 1032, in join self._wait_for_tstate_lock() File "/usr/lib/python3.7/threading.py", line 1048, in _wait_for_tstate_lock elif lock.acquire(block, timeout): KeyboardInterrupt 83466 4 alex.kanavin 2019-04-06 10:01:34 +0000 The specific issue with the unit test is that it's closing a socket connection, but it has no effect: netstat still shows the connection as ESTABLISHED on 5.0 kernel. root@qemux86-64:~# python3 -m test test_httplib -v == CPython 3.7.2 (default, Apr 5 2019, 15:17:15) [GCC 8.3.0] == Linux-5.0.0-yocto-standard-x86_64-with-glibc2.2.5 little-endian == cwd: /var/volatile/tmp/test_python_288 == CPU count: 1 == encodings: locale=UTF-8, FS=utf-8 ... test_response_fileno (test.test_httplib.BasicTest) ... ^^^^ blocks forever. On 4.18 kernel: root@qemux86-64:~# python3 -m test test_httplib -v == CPython 3.7.2 (default, Apr 5 2019, 15:17:15) [GCC 8.3.0] == Linux-4.18.27-yocto-standard-x86_64-with-glibc2.2.5 little-endian == cwd: /var/volatile/tmp/test_python_309 == CPU count: 1 == encodings: locale=UTF-8, FS=utf-8 .... test_response_fileno (test.test_httplib.BasicTest) ... ok .... 83468 5 richard.purdie 2019-04-06 23:18:35 +0000 I couldn't reproduce this with 4.19, I could with 5.0. I tried reverting https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=3c82a21f4320c8d54cf6456b27c8d49e5ffb722e and I think that stopped the hangs. I'd need more test runs to be 100% sure. Adding Bruce to cc. 83469 6 richard.purdie 2019-04-06 23:46:41 +0000 Having mentioned the commit, it all started working. Will look into it more tomorrow 83470 7 richard.purdie 2019-04-07 10:02:10 +0000 Can't get it to fail at all now! :( 83471 8 alex.kanavin 2019-04-07 10:17:59 +0000 For me, the failures weren’t 100%, more like 9 out of 10. 83472 9 richard.purdie 2019-04-07 12:59:54 +0000 Found a more reliable way to brute force reproduce it: meta/lib/oeqa/runtime/cases/python.py: + def test_python3_httplib(self): + for _ in range(50): + cmd = "python3 -m test test_httplib -v" + status, output = self.target.run(cmd) + msg = 'Exit status was not 0. Output: %s' % output + self.assertEqual(status, 0, msg=msg) Confirmed that reverting the commit I mentioned doesn't fix it. Also confirmed its not fixed by v5.0.7 83473 10 richard.purdie 2019-04-07 13:30:33 +0000 v4.20.17 doesn't have the issue v5.1-rc3 does v5.0-rc3 does v5.0-rc1 does 83474 11 richard.purdie 2019-04-07 20:56:23 +0000 Bisect suggests the commit which introduces the problem is: commit 4f693b55c3d2d2239b8a0094b518a1e533cf75d5 (HEAD, refs/bisect/bad) Author: Eric Dumazet <edumazet@google.com> Date: Tue Nov 27 14:42:03 2018 -0800 tcp: implement coalescing on backlog queue In case GRO is not as efficient as it should be or disabled, we might have a user thread trapped in __release_sock() while softirq handler flood packets up to the point we have to drop. This patch balances work done from user thread and softirq, to give more chances to __release_sock() to complete its work before new packets are added the the backlog. This also helps if we receive many ACK packets, since GRO does not aggregate them. This patch brings ~60% throughput increase on a receiver without GRO, but the spectacular gain is really on 1000x release_sock() latency reduction I have measured. Signed-off-by: Eric Dumazet <edumazet@google.com> Cc: Neal Cardwell <ncardwell@google.com> Cc: Yuchung Cheng <ycheng@google.com> Acked-by: Neal Cardwell <ncardwell@google.com> Signed-off-by: David S. Miller <davem@davemloft.net> 83475 12 richard.purdie 2019-04-07 22:03:34 +0000 I've asked for advice https://lore.kernel.org/netdev/85aabf9d4f41b6c57629e736993233f80a037e59.camel@linuxfoundation.org/T/#u 83477 13 bruce.ashfield 2019-04-08 02:53:20 +0000 I can't say that I understand why that is triggering the hang completely either, but is clearly mucking in the right part of the kernel to be the suspect commit. I'm following your upstream question as well. We can of course easily revert that commit in the linux-yocto 5.x branches, but as we all know, this really doesn't look oe/yocto/test specific, so getting a root cause from -netdev would be ideal, since this will just be waiting for us on all future kernel versions. 83769 14 ross.burton 2019-05-09 15:23:06 +0000 Root caused, worked around in python3, fixed in the kernel, and work around removed. All sorted as of 21bfbef23e1f4c90070017e19f70e488e6ff64be.