Bisection: Lost wakeups from b5179ac70de8

DISCUSSION Paul E. McKenney 2 participants 3 messages May 23, 2016 – May 24, 2016

Share & tools

Paul E. McKenney

author

2016-05-23 14:04 UTC #0 lore raw

Hello, Peter,

Current mainline doesn't do well with RCU torture testing, and the symptom once again looks like lost wakeups. Thankfully, this time each run takes only about an hour, and the false-positive/-negative rate is negligible. This means that for the first time ever, "git bisect" actually did something useful for me. The first bad commit is:

b5179ac70de8 ("sched/fair: Prepare to fix fairness problems on migration").

This patch also seems to result in softlockups:

http://permalink.gmane.org/gmane.linux.kernel/2225784

As always, this was on a virtualized environment, but the exact same environment was used for both the good and the bad runs. Sadly, the much lower-probability bugs appear to be alive and well, but I guess you can't have everything.

Please let me know if there is additional debug information that would be useful to you.

Thanx, Paul

PS: For whatever it is worth, the summary output from a good run and a
bad run is shown below.

------------------------------------------------------------------------
Good run:
------------------------------------------------------------------------

Results directory: /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-21:12:31 tools/testing/selftests/rcutorture/bin/kvm.sh --cpus 54 --duration 20
SRCU-N ------- 31383 grace periods (26.1525 per second)
SRCU-P ------- 451 grace periods (0.375833 per second)
TASKS01 ------- 820 grace periods (0.683333 per second)
TASKS02 ------- 845 grace periods (0.704167 per second)
TASKS03 ------- 766 grace periods (0.638333 per second)
TINY01 ------- 137261 grace periods (114.384 per second)
TINY02 ------- 386191 grace periods (321.826 per second)
TREE01 ------- 60501 grace periods (50.4175 per second)
TREE02 ------- 34814 grace periods (29.0117 per second)
TREE03 ------- 14581 grace periods (12.1508 per second)
no success message, 81 successful version messages
!!! PID 40003 hung at 1380 vs. 1200 seconds
TREE04 ------- 7856 grace periods (6.54667 per second)
TREE05 ------- 39473 grace periods (32.8942 per second)
TREE06 ------- 38812 grace periods (32.3433 per second)
TREE07 ------- 6874 grace periods (5.72833 per second)
TREE08 ------- 27803 grace periods (23.1692 per second)
TREE09 ------- 88783 grace periods (73.9858 per second)

------------------------------------------------------------------------
Bad run:
------------------------------------------------------------------------

Results directory: /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11 tools/testing/selftests/rcutorture/bin/kvm.sh --cpus 54 --duration 20
SRCU-N ------- 5108 grace periods (4.25667 per second)
no success message, 14 successful version messages
[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/SRCU-N/console.log [033mWARNING: [mSummary: Call Traces: 116 Stalls: 58
!!! PID 40837 hung at 1380 vs. 1200 seconds
SRCU-P ------- 580 grace periods (0.483333 per second)
[033mWARNING: [mBAD SEQ 384:384 last:578 version 33

    /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/SRCU-P/console.log

[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/SRCU-P/console.log [033mWARNING: [mSummary: Call Traces: 1 Stalls: 11
TASKS01 ------- [ grace periods (0 per second)
no success message, 1 successful version messages
[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TASKS01/console.log [033mWARNING: [mSummary: Call Traces: 36
!!! PID 40965 hung at 1380 vs. 1200 seconds
TASKS02 ------- 831 grace periods (0.6925 per second)
TASKS03 ------- 14 grace periods (0.0116667 per second)
no success message, 4 successful version messages
[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TASKS03/console.log [033mWARNING: [mSummary: Call Traces: 10
!!! PID 15654 hung at 1380 vs. 1200 seconds
TINY01 ------- 140482 grace periods (117.068 per second)
TINY02 ------- 416484 grace periods (347.07 per second)
TREE01 ------- 17599 grace periods (14.6658 per second)
[033mWARNING: [mBAD SEQ 2251:2251 last:17598 version 19

    /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE01/console.log

[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE01/console.log [033mWARNING: [mSummary: Stalls: 4
TREE02 ------- 15117 grace periods (12.5975 per second)
TREE03 ------- 4460 grace periods (3.71667 per second)
[033mWARNING: [mBAD SEQ 1846:1846 last:4456 version 29

    /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE03/console.log

[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE03/console.log [033mWARNING: [mSummary: Stalls: 2
!!! PID 40927 hung at 1380 vs. 1200 seconds
TREE04 ------- 1247 grace periods (1.03917 per second)
[033mWARNING: [mBAD SEQ 134:134 last:1247 version 6

    /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE04/console.log

[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE04/console.log [033mWARNING: [mSummary: Stalls: 7
TREE05 ------- 5543 grace periods (4.61917 per second)
[033mWARNING: [mBAD SEQ 1854:1854 last:5542 version 28

    /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE05/console.log

[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE05/console.log [033mWARNING: [mSummary: Call Traces: 2 Stalls: 28
TREE06 ------- 15510 grace periods (12.925 per second)
[033mWARNING: [mBAD SEQ 5445:5445 last:15457 version 29

    /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE06/console.log

[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE06/console.log [033mWARNING: [mSummary: Stalls: 2
TREE07 ------- 857 grace periods (0.714167 per second)
no success message, 78 successful version messages
[033mWARNING: [mBAD SEQ 211:211 last:857 version 9
[033mWARNING: [mAssertion failure in /home/paulmck/public_git/bisect-linux-rcu/tools/testing/selftests/rcutorture/res/2016.05.22-17:22:11/TREE07/console.log [033mWARNING: [mSummary: Stalls: 36
!!! PID 40988 hung at 1380 vs. 1200 seconds
TREE08 ------- 7868 grace periods (6.55667 per second)
TREE09 ------- 89784 grace periods (74.82 per second)

Peter Zijlstra

2016-05-24 09:05 UTC #1 lore raw

Quoted 10 lines · Paul E. McKenney

Hello, Peter,
Current mainline doesn't do well with RCU torture testing, and the symptom once again looks like lost wakeups. Thankfully, this time each run takes only about an hour, and the false-positive/-negative rate is negligible. This means that for the first time ever, "git bisect" actually did something useful for me. The first bad commit is:
b5179ac70de8 ("sched/fair: Prepare to fix fairness problems on migration").

Yeah, we have a patch for that.. I'll go writes a Changelog for it and put it to sched/urgent.

See lkml.kernel.org/r/[email protected]

Paul E. McKenney

author

2016-05-24 12:50 UTC #2 lore raw

Quoted 9 lines · Peter Zijlstra

Quoted 8 lines · Paul E. McKenney
Hello, Peter,
Current mainline doesn't do well with RCU torture testing, and the symptom once again looks like lost wakeups. Thankfully, this time each run takes only about an hour, and the false-positive/-negative rate is negligible. This means that for the first time ever, "git bisect" actually did something useful for me. The first bad commit is:

Quoted 7 lines

Quoted 2 lines
b5179ac70de8 ("sched/fair: Prepare to fix fairness problems on migration").
Yeah, we have a patch for that.. I'll go writes a Changelog for it and put it to sched/urgent.
See lkml.kernel.org/r/[email protected]

Thank you, will give it a shot.

Thanx, Paul