kernel BUG at kernel/sched_rt.c:493!

kernel BUG at kernel/sched_rt.c:493!

[Shawn Bohrer]

We recently managed to crash 10 of our test machines at the same time.
Half of the machines were running a 3.1.9 kernel and half were running
3.4.9.  I realize that these are both fairly old kernels but I've
skimmed the list of fixes in the 3.4.* stable series and didn't see
anything that appeared to be relevant to this issue.

All we managed to get was some screenshots of the stacks from the
consoles. On one of the 3.1.9 machines you can see we hit the
BUG_ON(want) statement in __disable_runtime() at
kernel/sched_rt.c:493, and all of the machines had essentially the
same stack showing:

rt_offline_rt
rq_attach_root
cpu_attach_domain
partition_sched_domains
do_rebuild_sched_domains

Here is one of the screenshots of the 3.1.9 machines:

https://dl.dropbox.com/u/84066079/berbox38.png

And here is one from a 3.4.9 machine:

https://dl.dropbox.com/u/84066079/berbox18.png

Three of the five 3.4.9 machines also managed to print
"[sched_delayed] sched: RT throttling activated" ~7 minutes before the
machines locked up.

I've tried reproducing the issue, but so far I've been unsuccessful
but I believe that is because my RT tasks aren't using enough CPU
cause borrowing from the other runqueues.  Normally our RT tasks use
very little CPU so I'm not entirely sure what conditions caused them
to run into throttling on the day that this happened.

The details that I do know about the workload that caused this are as
follows.

1) These are all dual socket 4 core X5460 systems with no
hyperthreading.  Thus there are 8 cores total in the system.
2) We use the cpuset cgroup to apply CPU affinity to various types of
processes.  Initially everything starts out in a single cpuset and the
top level cpuset has cpuset.sched_load_balance=1 thus there is only a
single scheduling domain.
3) In this case tasks were then placed into four non overlapping
cpusets.  1 containing a single core and single SCHED_FIFO task, 2
containing two cores, and multiple SCHED_FIFO tasks, and 1 containing
3 cores and everything else on the system running as SCHED_OTHER.
4) In the case of cpusets that contain SCHED_FIFO tasks, the tasks
start out as SCHED_OTHER are placed into the cpuset then change their
policy to SCHED_FIFO.
5) Once all tasks are placed into non overlapping cpusets the top
level cpuset.sched_load_balance is set to 0 to split the system into
four scheduling domains.
6) The system ran like this for some unknown amount of time.
7) All the processes are then sent a signal to exit, and at the same
time the top level cpuset.sched_load_balance is set back to 1.  This
is when the systems locked up.

Hopefully that is enough information to give someone more familiar
with the scheduler code an idea of where the bug is here.  I will
point out that in step #5 above there is a small window where the RT
tasks could encounter runtime limits but are still in a single big
scheduling domain.  I don't know if that is what happened or if it is
simply sufficient to hit the runtime limits while the system is split
into four domains.  For the curious we are using the default RT
runtime limits:

# grep . /proc/sys/kernel/sched_rt_*
/proc/sys/kernel/sched_rt_period_us:1000000
/proc/sys/kernel/sched_rt_runtime_us:950000

Let me know if you anyone needs any more information about this issue.

Thanks,
Shawn

-- 

---------------------------------------------------------------
This email, along with any attachments, is confidential. If you 
believe you received this message in error, please contact the 
sender immediately and delete all copies of the message.  
Thank you.

Re: kernel BUG at kernel/sched_rt.c:493!

[Shawn Bohrer]

On Sat, Jan 05, 2013 at 11:46:32AM -0600, Shawn Bohrer wrote:
> I've tried reproducing the issue, but so far I've been unsuccessful
> but I believe that is because my RT tasks aren't using enough CPU
> cause borrowing from the other runqueues.  Normally our RT tasks use
> very little CPU so I'm not entirely sure what conditions caused them
> to run into throttling on the day that this happened.

I've managed to reproduce this a couple times now on 3.1.9 I'll give
this a try later with a more recent kernel.  Here is what I've done to
reproduce the issue.


# Setup in shell 1
root@berbox39:/cgroup/cpuset# mkdir package0
root@berbox39:/cgroup/cpuset# echo 0 > package0/cpuset.mems
root@berbox39:/cgroup/cpuset# echo 0,2,4,6 > package0/cpuset.cpus
root@berbox39:/cgroup/cpuset# cat cpuset.sched_load_balance
1
root@berbox39:/cgroup/cpuset# cat package0/cpuset.sched_load_balance
1
root@berbox39:/cgroup/cpuset# cat sysdefault/cpuset.sched_load_balance
1
root@berbox39:/cgroup/cpuset# echo 1,3,5,7 > sysdefault/cpuset.cpus
root@berbox39:/cgroup/cpuset# echo 0 > sysdefault/cpuset.mems
root@berbox39:/cgroup/cpuset# echo $$ > package0/tasks

# Setup in shell 2
root@berbox39:~# cd /cgroup/cpuset/
root@berbox39:/cgroup/cpuset# chrt -f -p 60 $$
root@berbox39:/cgroup/cpuset# echo $$ > sysdefault/tasks

# In shell 1
root@berbox39:/cgroup/cpuset# chrt -f 1 /root/burn.sh &
root@berbox39:/cgroup/cpuset# chrt -f 1 /root/burn.sh &

# In shell 2
root@berbox39:/cgroup/cpuset# echo 0 > cpuset.sched_load_balance
root@berbox39:/cgroup/cpuset# echo 1 > cpuset.sched_load_balance
root@berbox39:/cgroup/cpuset# echo 0 > cpuset.sched_load_balance
root@berbox39:/cgroup/cpuset# echo 1 > cpuset.sched_load_balance

I haven't found the exact magic combination but I've been going back
and forth adding/killing burn.sh processes and toggling
cpuset.sched_load_balance and in a couple of minutes I can usually get
the machine to trigger the bug.

--
Shawn

-- 

---------------------------------------------------------------
This email, along with any attachments, is confidential. If you 
believe you received this message in error, please contact the 
sender immediately and delete all copies of the message.  
Thank you.

Re: kernel BUG at kernel/sched_rt.c:493!

[Shawn Bohrer]

On Mon, Jan 07, 2013 at 11:58:18AM -0600, Shawn Bohrer wrote:
> On Sat, Jan 05, 2013 at 11:46:32AM -0600, Shawn Bohrer wrote:
> > I've tried reproducing the issue, but so far I've been unsuccessful
> > but I believe that is because my RT tasks aren't using enough CPU
> > cause borrowing from the other runqueues.  Normally our RT tasks use
> > very little CPU so I'm not entirely sure what conditions caused them
> > to run into throttling on the day that this happened.
> 
> I've managed to reproduce this a couple times now on 3.1.9 I'll give
> this a try later with a more recent kernel.  Here is what I've done to
> reproduce the issue.
> 
> 
> # Setup in shell 1
> root@berbox39:/cgroup/cpuset# mkdir package0
> root@berbox39:/cgroup/cpuset# echo 0 > package0/cpuset.mems
> root@berbox39:/cgroup/cpuset# echo 0,2,4,6 > package0/cpuset.cpus
> root@berbox39:/cgroup/cpuset# cat cpuset.sched_load_balance
> 1
> root@berbox39:/cgroup/cpuset# cat package0/cpuset.sched_load_balance
> 1
> root@berbox39:/cgroup/cpuset# cat sysdefault/cpuset.sched_load_balance
> 1
> root@berbox39:/cgroup/cpuset# echo 1,3,5,7 > sysdefault/cpuset.cpus
> root@berbox39:/cgroup/cpuset# echo 0 > sysdefault/cpuset.mems
> root@berbox39:/cgroup/cpuset# echo $$ > package0/tasks
> 
> # Setup in shell 2
> root@berbox39:~# cd /cgroup/cpuset/
> root@berbox39:/cgroup/cpuset# chrt -f -p 60 $$
> root@berbox39:/cgroup/cpuset# echo $$ > sysdefault/tasks
> 
> # In shell 1
> root@berbox39:/cgroup/cpuset# chrt -f 1 /root/burn.sh &
> root@berbox39:/cgroup/cpuset# chrt -f 1 /root/burn.sh &
> 
> # In shell 2
> root@berbox39:/cgroup/cpuset# echo 0 > cpuset.sched_load_balance
> root@berbox39:/cgroup/cpuset# echo 1 > cpuset.sched_load_balance
> root@berbox39:/cgroup/cpuset# echo 0 > cpuset.sched_load_balance
> root@berbox39:/cgroup/cpuset# echo 1 > cpuset.sched_load_balance
> 
> I haven't found the exact magic combination but I've been going back
> and forth adding/killing burn.sh processes and toggling
> cpuset.sched_load_balance and in a couple of minutes I can usually get
> the machine to trigger the bug.

I've also managed to reproduce this on 3.8.0-rc2 so it appears the bug
is still present in the latest kernel.

Also just re-reading my instructions above /root/burn.sh is just a
simple:

while true; do : ; done

I've also had to make the kworker threads SCHED_FIFO with a higher
priority than burn.sh or as expected I can lock up the system due to
some xfs threads getting starved.

Let me know if anyone needs any more information, or needs me to try
anything since it appears I can trigger this fairly easily now.

--
Shawn

-- 

---------------------------------------------------------------
This email, along with any attachments, is confidential. If you 
believe you received this message in error, please contact the 
sender immediately and delete all copies of the message.  
Thank you.

Re: kernel BUG at kernel/sched_rt.c:493!

[Mike Galbraith]

On Mon, 2013-01-07 at 17:02 -0600, Shawn Bohrer wrote: 
> On Mon, Jan 07, 2013 at 11:58:18AM -0600, Shawn Bohrer wrote:
> > On Sat, Jan 05, 2013 at 11:46:32AM -0600, Shawn Bohrer wrote:
> > > I've tried reproducing the issue, but so far I've been unsuccessful
> > > but I believe that is because my RT tasks aren't using enough CPU
> > > cause borrowing from the other runqueues.  Normally our RT tasks use
> > > very little CPU so I'm not entirely sure what conditions caused them
> > > to run into throttling on the day that this happened.
> > 
> > I've managed to reproduce this a couple times now on 3.1.9 I'll give
> > this a try later with a more recent kernel.  Here is what I've done to
> > reproduce the issue.
> > 
> > 
> > # Setup in shell 1
> > root@berbox39:/cgroup/cpuset# mkdir package0
> > root@berbox39:/cgroup/cpuset# echo 0 > package0/cpuset.mems
> > root@berbox39:/cgroup/cpuset# echo 0,2,4,6 > package0/cpuset.cpus
> > root@berbox39:/cgroup/cpuset# cat cpuset.sched_load_balance
> > 1
> > root@berbox39:/cgroup/cpuset# cat package0/cpuset.sched_load_balance
> > 1
> > root@berbox39:/cgroup/cpuset# cat sysdefault/cpuset.sched_load_balance
> > 1
> > root@berbox39:/cgroup/cpuset# echo 1,3,5,7 > sysdefault/cpuset.cpus
> > root@berbox39:/cgroup/cpuset# echo 0 > sysdefault/cpuset.mems
> > root@berbox39:/cgroup/cpuset# echo $$ > package0/tasks
> > 
> > # Setup in shell 2
> > root@berbox39:~# cd /cgroup/cpuset/
> > root@berbox39:/cgroup/cpuset# chrt -f -p 60 $$
> > root@berbox39:/cgroup/cpuset# echo $$ > sysdefault/tasks
> > 
> > # In shell 1
> > root@berbox39:/cgroup/cpuset# chrt -f 1 /root/burn.sh &
> > root@berbox39:/cgroup/cpuset# chrt -f 1 /root/burn.sh &
> > 
> > # In shell 2
> > root@berbox39:/cgroup/cpuset# echo 0 > cpuset.sched_load_balance
> > root@berbox39:/cgroup/cpuset# echo 1 > cpuset.sched_load_balance
> > root@berbox39:/cgroup/cpuset# echo 0 > cpuset.sched_load_balance
> > root@berbox39:/cgroup/cpuset# echo 1 > cpuset.sched_load_balance
> > 
> > I haven't found the exact magic combination but I've been going back
> > and forth adding/killing burn.sh processes and toggling
> > cpuset.sched_load_balance and in a couple of minutes I can usually get
> > the machine to trigger the bug.
> 
> I've also managed to reproduce this on 3.8.0-rc2 so it appears the bug
> is still present in the latest kernel.
> 
> Also just re-reading my instructions above /root/burn.sh is just a
> simple:
> 
> while true; do : ; done
> 
> I've also had to make the kworker threads SCHED_FIFO with a higher
> priority than burn.sh or as expected I can lock up the system due to
> some xfs threads getting starved.
> 
> Let me know if anyone needs any more information, or needs me to try
> anything since it appears I can trigger this fairly easily now.

I hit something very similar.

In my case, I had booted with sched_debug, and a 57600 serial console
connected to my local box via a horribly slow internet link, which led
to it taking 40 seconds to get 2 of 80 cpus down for reboot.  There were
a gaggle of CPUs with pilfered rt_runtime, a matching gaggle of bandits,
no runqueues were throttled, nor were there any with rt_time accrued at
crash time, but as CPU4 tried to go down, it couldn't find its property,
so cleverly fired a thermonuclear pop-flare, lest thieves escape unseen,
precious rt_runtime in hand.

     runqueues 
     0xffff88047f811180      rt_runtime = 888192922   cpu0
     0xffff880c7f811180      rt_runtime = RUNTIME_INF cpu1
     0xffff88087f811180      rt_runtime = RUNTIME_INF cpu2
     0xffff880e7f811180      rt_runtime = 699462573   cpu3
     0xffff88047f851180      rt_runtime = 841094505   cpu4
     0xffff880c7f851180      rt_runtime = 926250000   cpu5
     0xffff88087f851180      rt_runtime = 926250000   cpu6
     0xffff880e7f851180      rt_runtime = 926250000   cpu7
     0xffff88047f891180      rt_runtime = 926250000   cpu8
     0xffff880c7f891180      rt_runtime = 926250000   cpu9
     0xffff88087f891180      rt_runtime = 926250000   cpu10
     0xffff880e7f891180      rt_runtime = 926250000   cpu11
     0xffff88047f8d1180      rt_runtime = 926250000   cpu12
     0xffff880c7f8d1180      rt_runtime = 926250000   cpu13
     0xffff88087f8d1180      rt_runtime = 1000000000  cpu14
     0xffff880e7f8d1180      rt_runtime = 1000000000  cpu15
     0xffff88047f911180      rt_runtime = 1000000000  cpu16
     0xffff880c7f911180      rt_runtime = 1000000000  cpu17
     0xffff88087f911180      rt_runtime = 1000000000  cpu18
     0xffff880e7f911180      rt_runtime = 1000000000  cpu19
     0xffff88047f951180      rt_runtime = 1000000000  cpu20
     0xffff880c7f951180      rt_runtime = 1000000000  cpu21
     0xffff88087f951180      rt_runtime = 1000000000  cpu23
     0xffff880e7f951180      rt_runtime = 1000000000  cpu24
     0xffff88047f991180      rt_runtime = 1000000000  cpu25
     0xffff880c7f991180      rt_runtime = 950000000   cpu26
     0xffff88087f991180      rt_runtime = 1000000000  cpu27
     0xffff880e7f991180      rt_runtime = 950000000   cpu28
     ....
     0xffff88087fcd1180      rt_runtime = 950000000   cpu79

crash> bt
PID: 14735  TASK: ffff880e75e86500  CPU: 4   COMMAND: "reboot"
 #0 [ffff880e74b3d890] machine_kexec at ffffffff8102676e
 #1 [ffff880e74b3d8e0] crash_kexec at ffffffff810a3a3a
 #2 [ffff880e74b3d9b0] oops_end at ffffffff81446238
 #3 [ffff880e74b3d9d0] do_invalid_op at ffffffff810035d4
 #4 [ffff880e74b3da70] invalid_op at ffffffff8144d9bb
    [exception RIP: __disable_runtime+494]
    RIP: ffffffff81045dae  RSP: ffff880e74b3db28  RFLAGS: 00010082
    RAX: 000000000000046a  RBX: ffff880e7fcd1310  RCX: ffffffff81d88a90
    RDX: 000000000000046a  RSI: 0000000000000050  RDI: ffff880e7fcd19b0
    RBP: ffff880e74b3db98   R8: 0000000000000010   R9: ffff88047f423408
    R10: 0000000000000050  R11: ffffffff81250190  R12: 0000000000000050
    R13: fffffffffde9f140  R14: ffff880e7fcd1310  R15: 000000000000122f
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
 #5 [ffff880e74b3dba0] rq_offline_rt at ffffffff8104b36a
 #6 [ffff880e74b3dbc0] set_rq_offline at ffffffff81043c9e
 #7 [ffff880e74b3dbe0] rq_attach_root at ffffffff8104c130
 #8 [ffff880e74b3dc10] cpu_attach_domain at ffffffff81054f44
 #9 [ffff880e74b3dc80] build_sched_domains at ffffffff81055525
#10 [ffff880e74b3dcd0] partition_sched_domains at ffffffff81055835
#11 [ffff880e74b3dd70] cpuset_cpu_inactive at ffffffff81055a0d
#12 [ffff880e74b3dd80] notifier_call_chain at ffffffff81448907
#13 [ffff880e74b3ddb0] _cpu_down at ffffffff8142b57b
#14 [ffff880e74b3de10] disable_nonboot_cpus at ffffffff8105ba23
#15 [ffff880e74b3de40] kernel_restart at ffffffff81071dde
#16 [ffff880e74b3de50] sys_reboot at ffffffff81071fc3
#17 [ffff880e74b3df80] system_call_fastpath at ffffffff8144ca12
    RIP: 00007fed35778316  RSP: 00007fff23f7e198  RFLAGS: 00010202
    RAX: 00000000000000a9  RBX: ffffffff8144ca12  RCX: 00007fed35771130
    RDX: 0000000001234567  RSI: 0000000028121969  RDI: fffffffffee1dead
    RBP: 0000000000000000   R8: 0000000000020fd0   R9: 000000000060d120
    R10: 00007fff23f7df40  R11: 0000000000000202  R12: 0000000000000000
    R13: 0000000000000000  R14: 0000000000000001  R15: 0000000000000000
    ORIG_RAX: 00000000000000a9  CS: 0033  SS: 002b

Re: kernel BUG at kernel/sched_rt.c:493!

[Steven Rostedt]

> 
> I've also managed to reproduce this on 3.8.0-rc2 so it appears the bug
> is still present in the latest kernel.

Shawn,

Can you send me your .config file.

Thanks,

-- Steve

Re: kernel BUG at kernel/sched_rt.c:493!

[Shawn Bohrer]

[-- Attachment #1: Type: text/plain, Size: 653 bytes --]

On Tue, Jan 08, 2013 at 09:36:05AM -0500, Steven Rostedt wrote:
> > 
> > I've also managed to reproduce this on 3.8.0-rc2 so it appears the bug
> > is still present in the latest kernel.
> 
> Shawn,
> 
> Can you send me your .config file.

I've attached the 3.8.0-rc2 config that I used to reproduce this in an
8 core kvm image.  Let me know if you need anything else.

Thanks,
Shawn

-- 

---------------------------------------------------------------
This email, along with any attachments, is confidential. If you 
believe you received this message in error, please contact the 
sender immediately and delete all copies of the message.  
Thank you.

[-- Attachment #2: 3.8.0-rc2.config.gz --]
[-- Type: application/x-gzip, Size: 23143 bytes --]

Re: kernel BUG at kernel/sched_rt.c:493!

[Mike Galbraith]

On Tue, 2013-01-08 at 09:01 -0600, Shawn Bohrer wrote: 
> On Tue, Jan 08, 2013 at 09:36:05AM -0500, Steven Rostedt wrote:
> > > 
> > > I've also managed to reproduce this on 3.8.0-rc2 so it appears the bug
> > > is still present in the latest kernel.
> > 
> > Shawn,
> > 
> > Can you send me your .config file.
> 
> I've attached the 3.8.0-rc2 config that I used to reproduce this in an
> 8 core kvm image.  Let me know if you need anything else.

I tried beating on my little Q6600 with no success.  I even tried
setting the entire box rt, GUI and all, nada.

Hm, maybe re-installing systemd..

-Mike

Re: kernel BUG at kernel/sched_rt.c:493!

[Shawn Bohrer]

[-- Attachment #1: Type: text/plain, Size: 8439 bytes --]

On Thu, Jan 10, 2013 at 05:13:11AM +0100, Mike Galbraith wrote:
> On Tue, 2013-01-08 at 09:01 -0600, Shawn Bohrer wrote: 
> > On Tue, Jan 08, 2013 at 09:36:05AM -0500, Steven Rostedt wrote:
> > > > 
> > > > I've also managed to reproduce this on 3.8.0-rc2 so it appears the bug
> > > > is still present in the latest kernel.
> > > 
> > > Shawn,
> > > 
> > > Can you send me your .config file.
> > 
> > I've attached the 3.8.0-rc2 config that I used to reproduce this in an
> > 8 core kvm image.  Let me know if you need anything else.
> 
> I tried beating on my little Q6600 with no success.  I even tried
> setting the entire box rt, GUI and all, nada.
> 
> Hm, maybe re-installing systemd..

I don't know if Steve has had any success.  I can reproduce this easily
now so I'm happy to do some debugging if anyone has some things they
want me to try.

Here is some info on my setup at the moment.  I'm using an 8 core KVM
image now with an xfs file system.  We do use systemd if that is
relevant.  My cpuset controller is mounted on /cgroup/cpuset and we
use libcgroup-tools to move everything on the system that can be moved
into /cgroup/cpuset/sysdefault/  I've also boosted all kworker threads
to run as SCHED_FIFO with a priority of 51.  From there I just drop
the three attached shell scripts (burn.sh, sched_domain_bug.sh and
sched_domain_burn.sh) in /root/ and run /root/sched_domain_bug.sh as
root.  Usually the bug triggers in less than a minute.  You may need
to tweak my shell scripts if your setup is different but they are very
rudimentary.

In order to try digging up some more info I applied the following
patch, and triggered the bug a few times.  The results are always
essentially the same:

---
 kernel/sched/rt.c |    9 ++++++++-
 1 files changed, 8 insertions(+), 1 deletions(-)

diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
index 418feb0..fba7f01 100644
--- a/kernel/sched/rt.c
+++ b/kernel/sched/rt.c
@@ -650,6 +650,8 @@ static void __disable_runtime(struct rq *rq)
 		 * we lend and now have to reclaim.
 		 */
 		want = rt_b->rt_runtime - rt_rq->rt_runtime;
+		printk(KERN_INFO "Initial want: %lld rt_b->rt_runtime: %llu rt_rq->rt_runtime: %llu\n",
+		       want, rt_b->rt_runtime, rt_rq->rt_runtime);
 
 		/*
 		 * Greedy reclaim, take back as much as we can.
@@ -684,7 +686,12 @@ static void __disable_runtime(struct rq *rq)
 		 * We cannot be left wanting - that would mean some runtime
 		 * leaked out of the system.
 		 */
-		BUG_ON(want);
+		if (want) {
+			printk(KERN_ERR "BUG triggered, want: %lld\n", want);
+			for_each_cpu(i, rd->span) {
+				print_rt_stats(NULL, i);
+			}
+		}
 balanced:
 		/*
 		 * Disable all the borrow logic by pretending we have inf
---

Here is the output:

[   81.278842] SysRq : Changing Loglevel
[   81.279027] Loglevel set to 9
[   83.285456] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   85.286452] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   85.289625] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   87.287435] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
[   87.290718] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   89.288469] Initial want: -50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1000000000
[   89.291550] Initial want: 150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 800000000
[   89.292940] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
[   89.294082] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
[   89.295194] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   89.296274] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   90.959004] [sched_delayed] sched: RT throttling activated
[   91.289470] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   91.292767] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   91.294037] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   91.295364] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   91.296355] BUG triggered, want: 200000000
[   91.296355] 
[   91.296355] rt_rq[7]:
[   91.296355]   .rt_nr_running                 : 0
[   91.296355]   .rt_throttled                  : 0
[   91.296355]   .rt_time                       : 0.000000
[   91.296355]   .rt_runtime                    : 750.000000
[   91.307332] Initial want: -50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1000000000
[   91.308440] Initial want: -100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1050000000
[   91.309586] Initial want: -150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1100000000
[   91.310716] Initial want: -200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1150000000
[   91.311707] BUG triggered, want: -200000000
[   91.311707] 
[   91.311707] rt_rq[6]:
[   91.311707]   .rt_nr_running                 : 1
[   91.311707]   .rt_throttled                  : 0
[   91.311707]   .rt_time                       : 307.209987
[   91.311707]   .rt_runtime                    : 1150.000000
[   93.293733] Initial want: -43802666 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 993802666
[   93.296601] Initial want: 150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 800000000
[   93.299600] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
[   93.301068] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
[   93.302075] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   93.303063] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   95.294857] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   95.298568] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   95.300016] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   95.301204] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
[   95.302161] BUG triggered, want: 200000000
[   95.302180] 
[   95.302180] rt_rq[7]:
[   95.302180]   .rt_nr_running                 : 0
[   95.302180]   .rt_throttled                  : 0
[   95.302180]   .rt_time                       : 0.000000
[   95.302180]   .rt_runtime                    : 750.000000
[   95.309281] Initial want: -50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1000000000
[   95.311185] Initial want: -100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1050000000
[   95.312115] Initial want: -150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1100000000
[   95.312980] Initial want: -200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1150000000
[   95.313107] BUG triggered, want: -200000000
[   95.313107] 
[   95.313107] rt_rq[6]:
[   95.313107]   .rt_nr_running                 : 1
[   95.313107]   .rt_throttled                  : 0
[   95.313107]   .rt_time                       : 309.317451
[   95.313107]   .rt_runtime                    : 1150.000000
[   97.300908] Initial want: -43805084 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 993805084
[   97.303466] Initial want: 150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 800000000
[   97.304429] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
[   97.305333] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
[   97.307685] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   97.308977] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
[   99.301776] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000

Every time I've triggered this 'want' has always been 200000000, and it
is always rt_rq[7] and rt_rq[6].  Perhaps this will point folks in the
right direction.  If not I'll keep poking at this.

Thanks,
Shawn

-- 

---------------------------------------------------------------
This email, along with any attachments, is confidential. If you 
believe you received this message in error, please contact the 
sender immediately and delete all copies of the message.  
Thank you.

[-- Attachment #2: burn.sh --]
[-- Type: application/x-sh, Size: 40 bytes --]

[-- Attachment #3: sched_domain_burn.sh --]
[-- Type: application/x-sh, Size: 611 bytes --]

[-- Attachment #4: sched_domain_bug.sh --]
[-- Type: application/x-sh, Size: 390 bytes --]

Re: kernel BUG at kernel/sched_rt.c:493!

[Mike Galbraith]

On Thu, 2013-01-10 at 13:58 -0600, Shawn Bohrer wrote:

> Here is the output:
> 
> [   81.278842] SysRq : Changing Loglevel
> [   81.279027] Loglevel set to 9
> [   83.285456] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> [   85.286452] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> [   85.289625] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> [   87.287435] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
> [   87.290718] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> [   89.288469] Initial want: -50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1000000000
> [   89.291550] Initial want: 150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 800000000
> [   89.292940] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
> [   89.294082] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
> [   89.295194] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> [   89.296274] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> [   90.959004] [sched_delayed] sched: RT throttling activated
> [   91.289470] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> [   91.292767] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> [   91.294037] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> [   91.295364] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> [   91.296355] BUG triggered, want: 200000000
> [   91.296355] 
> [   91.296355] rt_rq[7]:
> [   91.296355]   .rt_nr_running                 : 0
> [   91.296355]   .rt_throttled                  : 0
> [   91.296355]   .rt_time                       : 0.000000
> [   91.296355]   .rt_runtime                    : 750.000000
> [   91.307332] Initial want: -50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1000000000
> [   91.308440] Initial want: -100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1050000000
> [   91.309586] Initial want: -150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1100000000
> [   91.310716] Initial want: -200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1150000000
> [   91.311707] BUG triggered, want: -200000000
> [   91.311707] 
> [   91.311707] rt_rq[6]:
> [   91.311707]   .rt_nr_running                 : 1
> [   91.311707]   .rt_throttled                  : 0
> [   91.311707]   .rt_time                       : 307.209987
> [   91.311707]   .rt_runtime                    : 1150.000000

That makes about as much sense as my crash did.  There is no leak, but
cpu found nada.  So rd/span is changing on us?  We saw nada as we
traversed, release locks, poof, it's there.  In my dump, at crash time,
rd/span was fine, but at the top of the stack, I found a mighty
suspicious reference to def_root_domain.span.  At _crash_ time, both it
and rq->rd.span had pilfer-able goodies, but whatever it was that we
traversed had nada just a wee bit earlier.

If the darn thing would trigger for me again, I'd use trace_printk(),
check rd and cpumask_weight(rd->span) before/after traverse, print cpu
and rt_runtime as we traverse, set /proc/sys/kernel/ftrace_dump_on_oops
to 1.. and hope bug doesn't like to play heisenbug games.

-Mike 

Re: kernel BUG at kernel/sched_rt.c:493!

[Mike Galbraith]

On Fri, 2013-01-11 at 06:22 +0100, Mike Galbraith wrote: 
> On Thu, 2013-01-10 at 13:58 -0600, Shawn Bohrer wrote:
> 
> > Here is the output:
> > 
> > [   81.278842] SysRq : Changing Loglevel
> > [   81.279027] Loglevel set to 9
> > [   83.285456] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> > [   85.286452] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> > [   85.289625] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> > [   87.287435] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
> > [   87.290718] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> > [   89.288469] Initial want: -50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1000000000
> > [   89.291550] Initial want: 150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 800000000
> > [   89.292940] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
> > [   89.294082] Initial want: 100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 850000000
> > [   89.295194] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> > [   89.296274] Initial want: 50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 900000000
> > [   90.959004] [sched_delayed] sched: RT throttling activated
> > [   91.289470] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> > [   91.292767] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> > [   91.294037] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> > [   91.295364] Initial want: 200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 750000000
> > [   91.296355] BUG triggered, want: 200000000
> > [   91.296355] 
> > [   91.296355] rt_rq[7]:
> > [   91.296355]   .rt_nr_running                 : 0
> > [   91.296355]   .rt_throttled                  : 0
> > [   91.296355]   .rt_time                       : 0.000000
> > [   91.296355]   .rt_runtime                    : 750.000000
> > [   91.307332] Initial want: -50000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1000000000
> > [   91.308440] Initial want: -100000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1050000000
> > [   91.309586] Initial want: -150000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1100000000
> > [   91.310716] Initial want: -200000000 rt_b->rt_runtime: 950000000 rt_rq->rt_runtime: 1150000000
> > [   91.311707] BUG triggered, want: -200000000
> > [   91.311707] 
> > [   91.311707] rt_rq[6]:
> > [   91.311707]   .rt_nr_running                 : 1
> > [   91.311707]   .rt_throttled                  : 0
> > [   91.311707]   .rt_time                       : 307.209987
> > [   91.311707]   .rt_runtime                    : 1150.000000
> 
> That makes about as much sense as my crash did.  There is no leak, but
> cpu found nada.  So rd/span is changing on us?

So I looked at the locking (yet again), and (for the umpteenth time) see
no way in the world that can happen.  Hrmph.

-Mike

[PATCH] sched_rt: Use root_domain of rt_rq not current processor

[Shawn Bohrer]

When the system has multiple domains do_sched_rt_period_timer() can run
on any CPU and may iterate over all rt_rq in cpu_online_mask.  This
means when balance_runtime() is run for a given rt_rq that rt_rq may be
in a different rd than the current processor.  Thus if we use
smp_processor_id() to get rd in do_balance_runtime() we may borrow
runtime from a rt_rq that is not part of our rd.

This changes do_balance_runtime to get the rd from the passed in rt_rq
ensuring that we borrow runtime only from the correct rd for the given
rt_rq.

This fixes a BUG at kernel/sched/rt.c:687! in __disable_runtime when we
try reclaim runtime lent to other rt_rq but runtime has been lent to
a rt_rq in another rd.

Signed-off-by: Shawn Bohrer <sbohrer@rgmadvisors.com>
---
 kernel/sched/rt.c |    2 +-
 1 files changed, 1 insertions(+), 1 deletions(-)

diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
index 418feb0..4f02b28 100644
--- a/kernel/sched/rt.c
+++ b/kernel/sched/rt.c
@@ -566,7 +566,7 @@ static inline struct rt_bandwidth *sched_rt_bandwidth(struct rt_rq *rt_rq)
 static int do_balance_runtime(struct rt_rq *rt_rq)
 {
 	struct rt_bandwidth *rt_b = sched_rt_bandwidth(rt_rq);
-	struct root_domain *rd = cpu_rq(smp_processor_id())->rd;
+	struct root_domain *rd = rq_of_rt_rq(rt_rq)->rd;
 	int i, weight, more = 0;
 	u64 rt_period;
 
-- 
1.7.7.6


-- 

---------------------------------------------------------------
This email, along with any attachments, is confidential. If you 
believe you received this message in error, please contact the 
sender immediately and delete all copies of the message.  
Thank you.

Re: [PATCH] sched_rt: Use root_domain of rt_rq not current processor

[Mike Galbraith]

On Mon, 2013-01-14 at 11:55 -0600, Shawn Bohrer wrote: 
> When the system has multiple domains do_sched_rt_period_timer() can run
> on any CPU and may iterate over all rt_rq in cpu_online_mask.  This
> means when balance_runtime() is run for a given rt_rq that rt_rq may be
> in a different rd than the current processor.  Thus if we use
> smp_processor_id() to get rd in do_balance_runtime() we may borrow
> runtime from a rt_rq that is not part of our rd.
> 
> This changes do_balance_runtime to get the rd from the passed in rt_rq
> ensuring that we borrow runtime only from the correct rd for the given
> rt_rq.
> 
> This fixes a BUG at kernel/sched/rt.c:687! in __disable_runtime when we
> try reclaim runtime lent to other rt_rq but runtime has been lent to
> a rt_rq in another rd.

Ah, so there was only one cpu in span when the bug fired in your case.
Good fix.  Damn throttle bugs are at least as deadly as the bugs the
thing tries to protect you from.  (Yet) another one bites the dust ;-)

> Signed-off-by: Shawn Bohrer <sbohrer@rgmadvisors.com>

That wants a Cc: stable@vger.kernel.org too.

-Mike

[tip:sched/urgent] sched/rt: Use root_domain of rt_rq not current processor

[tip-bot for Shawn Bohrer]

Commit-ID:  df42ae62b3a0bd1a04b68f467a84150af6274a09
Gitweb:     http://git.kernel.org/tip/df42ae62b3a0bd1a04b68f467a84150af6274a09
Author:     Shawn Bohrer <sbohrer@rgmadvisors.com>
AuthorDate: Mon, 14 Jan 2013 11:55:31 -0600
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Thu, 24 Jan 2013 16:37:57 +0100

sched/rt: Use root_domain of rt_rq not current processor

When the system has multiple domains do_sched_rt_period_timer()
can run on any CPU and may iterate over all rt_rq in
cpu_online_mask.  This means when balance_runtime() is run for a
given rt_rq that rt_rq may be in a different rd than the current
processor.  Thus if we use smp_processor_id() to get rd in
do_balance_runtime() we may borrow runtime from a rt_rq that is
not part of our rd.

This changes do_balance_runtime to get the rd from the passed in
rt_rq ensuring that we borrow runtime only from the correct rd
for the given rt_rq.

This fixes a BUG at kernel/sched/rt.c:687! in __disable_runtime
when we try reclaim runtime lent to other rt_rq but runtime has
been lent to a rt_rq in another rd.

Signed-off-by: Shawn Bohrer <sbohrer@rgmadvisors.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Acked-by: Mike Galbraith <bitbucket@online.de>
Cc: peterz@infradead.org
Cc: <stable@kernel.org>
Link: http://lkml.kernel.org/r/1358186131-29494-1-git-send-email-sbohrer@rgmadvisors.com
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/sched/rt.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
index 418feb0..4f02b28 100644
--- a/kernel/sched/rt.c
+++ b/kernel/sched/rt.c
@@ -566,7 +566,7 @@ static inline struct rt_bandwidth *sched_rt_bandwidth(struct rt_rq *rt_rq)
 static int do_balance_runtime(struct rt_rq *rt_rq)
 {
 	struct rt_bandwidth *rt_b = sched_rt_bandwidth(rt_rq);
-	struct root_domain *rd = cpu_rq(smp_processor_id())->rd;
+	struct root_domain *rd = rq_of_rt_rq(rt_rq)->rd;
 	int i, weight, more = 0;
 	u64 rt_period;
 

[tip:sched/urgent] sched/rt: Use root_domain of rt_rq not current processor

[tip-bot for Shawn Bohrer]

Commit-ID:  aa7f67304d1a03180f463258aa6f15a8b434e77d
Gitweb:     http://git.kernel.org/tip/aa7f67304d1a03180f463258aa6f15a8b434e77d
Author:     Shawn Bohrer <sbohrer@rgmadvisors.com>
AuthorDate: Mon, 14 Jan 2013 11:55:31 -0600
Committer:  Ingo Molnar <mingo@kernel.org>
CommitDate: Fri, 25 Jan 2013 08:20:47 +0100

sched/rt: Use root_domain of rt_rq not current processor

When the system has multiple domains do_sched_rt_period_timer()
can run on any CPU and may iterate over all rt_rq in
cpu_online_mask.  This means when balance_runtime() is run for a
given rt_rq that rt_rq may be in a different rd than the current
processor.  Thus if we use smp_processor_id() to get rd in
do_balance_runtime() we may borrow runtime from a rt_rq that is
not part of our rd.

This changes do_balance_runtime to get the rd from the passed in
rt_rq ensuring that we borrow runtime only from the correct rd
for the given rt_rq.

This fixes a BUG at kernel/sched/rt.c:687! in __disable_runtime
when we try reclaim runtime lent to other rt_rq but runtime has
been lent to a rt_rq in another rd.

Signed-off-by: Shawn Bohrer <sbohrer@rgmadvisors.com>
Acked-by: Steven Rostedt <rostedt@goodmis.org>
Acked-by: Mike Galbraith <bitbucket@online.de>
Cc: peterz@infradead.org
Cc: <stable@kernel.org>
Link: http://lkml.kernel.org/r/1358186131-29494-1-git-send-email-sbohrer@rgmadvisors.com
Signed-off-by: Ingo Molnar <mingo@kernel.org>
---
 kernel/sched/rt.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/kernel/sched/rt.c b/kernel/sched/rt.c
index 418feb0..4f02b28 100644
--- a/kernel/sched/rt.c
+++ b/kernel/sched/rt.c
@@ -566,7 +566,7 @@ static inline struct rt_bandwidth *sched_rt_bandwidth(struct rt_rq *rt_rq)
 static int do_balance_runtime(struct rt_rq *rt_rq)
 {
 	struct rt_bandwidth *rt_b = sched_rt_bandwidth(rt_rq);
-	struct root_domain *rd = cpu_rq(smp_processor_id())->rd;
+	struct root_domain *rd = rq_of_rt_rq(rt_rq)->rd;
 	int i, weight, more = 0;
 	u64 rt_period;