On Sat, Nov 17, 2007 at 08:10:35PM +0100, Dmitry Adamushko wrote:
> Micah,
>
> ok, would it be possible to get "cat /proc/schedstat" output at the
> moment when you observe the 'problem'? So we could try to analyze
> behavior of the load balancer (yeah, we should have probably started
> with this step)
No problem. Here are the two schedstat snapshots. With my priosched.c
test program running with one CPU idle, I did a "cat /proc/schedstat",
waited a couple seconds, then repeated:
micah@micah-64:~$ cat /proc/schedstat
version 14
timestamp 4366722208
cpu0 0 0 0 785868111 0 828020771 12621812 22703872 14096041 9504937730116 23603703739504 815398959
domain0 03 8766051 8760123 95 14544377 6374 0 13 8760110 7369 6771 0 20835105 605 0 1 6770 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 7026998 0 24826
cpu1 0 0 0 783505304 0 860700497 26129151 41776419 34749418 10682815341474 1753703225423 834571346
domain0 03 8685595 8677710 224 7037051 8127 0 76 8677634 7500 7320 7 471762 179 0 8 7312 0 0 0 0 0 0 0 0 1 0 1 0 0 0 0 0 0 8607831 0 36753
micah@micah-64:~$ cat /proc/schedstat
version 14
timestamp 4366723231
cpu0 0 0 0 785868111 0 828021128 12621812 22703965 14096130 9509029340381 23603703795868 815399316
domain0 03 8766051 8760123 95 14544377 6374 0 13 8760110 7374 6776 0 20835105 605 0 1 6775 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 7027010 0 24826
cpu1 0 0 0 783505304 0 860708521 26132612 41780521 34753508 10683770853336 1753758309667 834575909
domain0 03 8685718 8677833 224 7037051 8127 0 76 8677757 7500 7320 7 471762 179 0 8 7312 0 0 0 0 0 0 0 0 1 0 1 0 0 0 0 0 0 8607835 0 36753
I had been experimenting with both schedstat and sched_debug while
trying to identify the original problem I observed with VMware's
code. During the course of that investigation, I wrote a little tool
to graph schedstat output in real-time.
The tool itself is in a public Subversion reporitory:
http://svn.navi.cx/misc/trunk/rtgraph/schedstat-grapher.py
(Requires the other Python modules in that directory, and PyGTK)
This screenshot was taken just after the priosched.c test program
flipped from the "bad" state to the "good" state. It had been running
on one CPU for a while, and something caused it to rebalance properly
onto both CPUs while this graph was being recorded. You can see that
in the "bad" state, cpu0 was trying to rebalance but it was failing
because there was no busier group (idle_nobusyg):
http://navi.cx/~micah/priosched-graph-1.png
While in the "bad" state, the sched_debug output shows clearly why we
were hitting idle_nobusyg. One CPU has both busy-loop threads in its
runqueue, the other CPU is mostly idle but it has an elevated CPU load
proportional to the high priority thread's priority boost.
micah@micah-64:~$ cat /proc/sched_debug
Sched Debug Version: v0.05-v20, 2.6.23.1 #1
now at 287991360677873 nsecs
cpu#0, 2593.095 MHz
.nr_running : 0
.load : 0
.ls.delta_fair : 27950
.ls.delta_exec : 1958562
.nr_switches : 42562597
.nr_load_updates : 71998668
.nr_uninterruptible : 2731
.jiffies : 4366886827
.next_balance : 4366886830
.curr->pid : 0
.clock : 288012673563036
.idle_clock : 0
.prev_clock_raw : 287377858327690
.clock_warps : 0
.clock_overflows : 50589
.clock_deep_idle_events : 0
.clock_max_delta : 4000250
.cpu_load[0] : 58784
.cpu_load[1] : 64246
.cpu_load[2] : 65333
.cpu_load[3] : 63586
.cpu_load[4] : 61992
cfs_rq
.fair_clock : 9034352848909
.exec_clock : 10184480087500
.wait_runtime : 0
.wait_runtime_overruns : 10356815
.wait_runtime_underruns : 1551195
.sleeper_bonus : 33752273
.wait_runtime_rq_sum : 0
runnable tasks:
task PID tree-key delta waiting switches prio sum-exec sum-wait sum-sleep wait-overrun wait-underrun
------------------------------------------------------------------------------------------------------------------------------------------------------------------
cpu#1, 2593.095 MHz
.nr_running : 3
.load : 3072
.ls.delta_fair : 247507
.ls.delta_exec : 1148874
.nr_switches : 78415958
.nr_load_updates : 71998585
.nr_uninterruptible : -2731
.jiffies : 4366886827
.next_balance : 4366886976
.curr->pid : 16252
.clock : 288012340795477
.idle_clock : 0
.prev_clock_raw : 287377857592876
.clock_warps : 0
.clock_overflows : 18670
.clock_deep_idle_events : 0
.clock_max_delta : 4000250
.cpu_load[0] : 7136
.cpu_load[1] : 4591
.cpu_load[2] : 3319
.cpu_load[3] : 2691
.cpu_load[4] : 2391
cfs_rq
.fair_clock : 10089416808778
.exec_clock : 11099173384388
.wait_runtime : -74868320
.wait_runtime_overruns : 18282511
.wait_runtime_underruns : 1233484
.sleeper_bonus : 3602202
.wait_runtime_rq_sum : -74868320
runnable tasks:
task PID tree-key delta waiting switches prio sum-exec sum-wait sum-sleep wait-overrun wait-underrun
------------------------------------------------------------------------------------------------------------------------------------------------------------------
priosched 16248 10089447384328 30575550 -31397913 172 120 1665860833 -80591108 0 0 17
priosched 16249 10089453683739 36874961 -39698014 148 120 1670430581 -63070307 0 0 13
R cat 16252 10089420581171 3772393 -3772393 1 120 73354 -22393 90430 0 0
Thanks,
--Micah
-
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
[Index of Archives]
[Kernel Newbies]
[Netfilter]
[Bugtraq]
[Photo]
[Stuff]
[Gimp]
[Yosemite News]
[MIPS Linux]
[ARM Linux]
[Linux Security]
[Linux RAID]
[Video 4 Linux]
[Linux for the blind]
[Linux Resources]
