Soft lockup problem

Gerard Saraber gsaraber at gmail.com
Tue Feb 7 10:35:37 CST 2012


On Mon, Feb 6, 2012 at 4:51 PM, Jan Kara <jack at suse.cz> wrote:
> On Mon 06-02-12 09:40:45, Gerard Saraber wrote:
>> Greetings everyone,
>> I've been having a bit of a problem since upgrading to the linux 3.x
>> series, I have a machine that we're using as a NAS that runs various
>> rsync processes (mostly at night), lately after a day or two, I will
>> come in in the morning to a load average of 49, but the machine not
>> really doing anything, when trying to run 'dstat' the command just
>> hung with no output at all. there were no errors in the logs, or even
>> anything that would vaguely point at anything I could work with.
>> So needing to get the machine back to work I attempted to reboot it
>> "shutdown -r now" on console... it gives a nice message saying it's
>> going to reboot, but nothing ever happens.. the only way to reboot it
>> is by using ctrl + alt + sysrq + b. after which the machine reboots
>> and the raid array comes back clean.
>>
>> I'm not sure how to troubleshoot this, any pointers would be appreciated.
>>
>> I'm compiling 3.2.4 at the moment and found a bunch of possibly useful
>> options in the kernel debugging section:
>> detect hard/soft lockups and detect hung tasks, maybe it'll give me
>> something more to go on.
>>
>> Some details about the machine:
>> Linux xenbox 3.2.2 #1 SMP Sun Jan 29 10:28:22 CST 2012 x86_64 Intel(R)
>> Xeon(R) CPU 5140 @ 2.33GHz GenuineIntel GNU/Linux
>> It has 3 software raid arrays (2 x 5 drives and 1 x 4 drives) LVM'ed
>> together into a 23TB XFS filesystem.
>> 6GB memory and a pair of Intel Gigabit ethernet controllers bonded together.
>  Hmm, might be some deadlock in the filesystem. Adding XFS guys to CC.
> Can you run 'echo w >/proc/sysrq-trigger' and post output of dmesg here?
>
>                                                                Honza
> --
> Jan Kara <jack at suse.cz>
> SUSE Labs, CR

Thanks for the quick reply,
the machine is running good at the moment so I'm not sure if the
output helps, but here it is:
[I'll also be sure to grab this log the next time it locks]

-Gerard


Feb 07 10:32:04 [kernel] [88365.922121] SysRq : Show Blocked State
Feb 07 10:32:04 [kernel] [88365.922141]   task
PC stack   pid father
Feb 07 10:32:04 [kernel] [88365.922170] flush-253:0     D
0000000000000000  1320  2941      2 0x00000000
Feb 07 10:32:04 [kernel] [88365.922177]  ffff8801ada63570
0000000000000046 ffffffff8189813a ffff8801b554a800
Feb 07 10:32:04 [kernel] [88365.922182]  ffff880100000000
00000000001d2880 ffff8801ad8d8000 00000000001d2880
Feb 07 10:32:04 [kernel] [88365.922188]  ffff8801ada63fd8
ffff8801ada62000 00000000001d2880 00000000001d2880
Feb 07 10:32:04 [kernel] [88365.922193] Call Trace:
Feb 07 10:32:04 [kernel] [88365.922203]  [<ffffffff8189813a>] ?
__schedule+0x70a/0x920
Feb 07 10:32:04 [kernel] [88365.922207]  [<ffffffff8189841a>] schedule+0x3a/0x50
Feb 07 10:32:04 [kernel] [88365.922211]  [<ffffffff816bc640>]
get_active_stripe+0x2f0/0x660
Feb 07 10:32:04 [kernel] [88365.922217]  [<ffffffff810c0000>] ?
sysfs_show_available_clocksources+0x10/0xf0
Feb 07 10:32:04 [kernel] [88365.922222]  [<ffffffff81088560>] ?
try_to_wake_up+0x2d0/0x2d0
Feb 07 10:32:04 [kernel] [88365.922226]  [<ffffffff816c39b6>]
make_request+0x196/0x430
Feb 07 10:32:04 [kernel] [88365.922231]  [<ffffffff810b4e30>] ?
wake_up_bit+0x40/0x40
Feb 07 10:32:04 [kernel] [88365.922236]  [<ffffffff816da26b>] ?
dm_request+0x13b/0x230
Feb 07 10:32:04 [kernel] [88365.922239]  [<ffffffff816cf1a4>]
md_make_request+0x174/0x2b0
Feb 07 10:32:04 [kernel] [88365.922243]  [<ffffffff816cf098>] ?
md_make_request+0x68/0x2b0
Feb 07 10:32:04 [kernel] [88365.922247]  [<ffffffff810b9d5e>] ?
up_read+0x1e/0x40
Feb 07 10:32:04 [kernel] [88365.922250]  [<ffffffff816da26b>] ?
dm_request+0x13b/0x230
Feb 07 10:32:04 [kernel] [88365.922253]  [<ffffffff816da15e>] ?
dm_request+0x2e/0x230
Feb 07 10:32:04 [kernel] [88365.922259]  [<ffffffff8145c722>]
generic_make_request+0xc2/0x100
Feb 07 10:32:04 [kernel] [88365.922262]  [<ffffffff8145d4d5>]
submit_bio+0x75/0xf0
Feb 07 10:32:04 [kernel] [88365.922267]  [<ffffffff811ac88b>] ?
__mark_inode_dirty+0x3b/0x220
Feb 07 10:32:04 [kernel] [88365.922272]  [<ffffffff8133f512>]
xfs_submit_ioend_bio.clone.12+0x52/0x80
Feb 07 10:32:04 [kernel] [88365.922275]  [<ffffffff8133f62e>]
xfs_submit_ioend+0xee/0x110
Feb 07 10:32:04 [kernel] [88365.922278]  [<ffffffff8133f89c>]
xfs_vm_writepage+0x24c/0x520
Feb 07 10:32:04 [kernel] [88365.922284]  [<ffffffff81136115>]
__writepage+0x15/0x50
Feb 07 10:32:04 [kernel] [88365.922287]  [<ffffffff81136749>]
write_cache_pages+0x219/0x4c0
Feb 07 10:32:04 [kernel] [88365.922291]  [<ffffffff81136100>] ?
set_page_dirty+0x70/0x70
Feb 07 10:32:04 [kernel] [88365.922295]  [<ffffffff81136a3f>]
generic_writepages+0x4f/0x70
Feb 07 10:32:04 [kernel] [88365.922298]  [<ffffffff8133e4e8>]
xfs_vm_writepages+0x58/0x70
Feb 07 10:32:04 [kernel] [88365.922302]  [<ffffffff8113822f>]
do_writepages+0x1f/0x40
Feb 07 10:32:04 [kernel] [88365.922306]  [<ffffffff811ad5c9>]
writeback_single_inode+0x189/0x400
Feb 07 10:32:04 [kernel] [88365.922309]  [<ffffffff811adc28>]
writeback_sb_inodes+0x1a8/0x270
Feb 07 10:32:04 [kernel] [88365.922313]  [<ffffffff811add86>]
__writeback_inodes_wb+0x96/0xc0
Feb 07 10:32:04 [kernel] [88365.922316]  [<ffffffff811adf93>]
wb_writeback+0x1e3/0x2c0
Feb 07 10:32:04 [kernel] [88365.922319]  [<ffffffff811370e5>] ?
determine_dirtyable_memory+0x15/0x30
Feb 07 10:32:04 [kernel] [88365.922323]  [<ffffffff81137192>] ?
global_dirty_limits+0x32/0x160
Feb 07 10:32:04 [kernel] [88365.922326]  [<ffffffff811aee3e>]
wb_do_writeback+0x11e/0x210
Feb 07 10:32:04 [kernel] [88365.922330]  [<ffffffff811aefda>]
bdi_writeback_thread+0xaa/0x290
Feb 07 10:32:04 [kernel] [88365.922333]  [<ffffffff811aef30>] ?
wb_do_writeback+0x210/0x210
Feb 07 10:32:04 [kernel] [88365.922337]  [<ffffffff810b48c6>] kthread+0xa6/0xb0
Feb 07 10:32:04 [kernel] [88365.922342]  [<ffffffff8189e1b4>]
kernel_thread_helper+0x4/0x10
Feb 07 10:32:04 [kernel] [88365.922346]  [<ffffffff8189b8dd>] ?
retint_restore_args+0xe/0xe
Feb 07 10:32:04 [kernel] [88365.922350]  [<ffffffff810b4820>] ?
__init_kthread_worker+0x70/0x70
Feb 07 10:32:04 [kernel] [88365.922353]  [<ffffffff8189e1b0>] ?
gs_change+0xb/0xb
Feb 07 10:32:04 [kernel] [88365.922357] ssh             D
0000000000000000  4080 23086  23078 0x00000000
Feb 07 10:32:04 [kernel] [88365.922363]  ffff8801492d79a8
0000000000000046 ffffffff8189813a 0000000000000006
Feb 07 10:32:04 [kernel] [88365.922368]  0000000000000000
00000000001d2880 ffff8801b7902680 00000000001d2880
Feb 07 10:32:04 [kernel] [88365.922373]  ffff8801492d7fd8
ffff8801492d6000 00000000001d2880 00000000001d2880
Feb 07 10:32:04 [kernel] [88365.922379] Call Trace:
Feb 07 10:32:04 [kernel] [88365.922382]  [<ffffffff8189813a>] ?
__schedule+0x70a/0x920
Feb 07 10:32:04 [kernel] [88365.922385]  [<ffffffff8189841a>] schedule+0x3a/0x50
Feb 07 10:32:04 [kernel] [88365.922389]  [<ffffffff8189891e>]
schedule_timeout+0x18e/0x2e0
Feb 07 10:32:04 [kernel] [88365.922393]  [<ffffffff810a0a10>] ?
cascade+0xa0/0xa0
Feb 07 10:32:04 [kernel] [88365.922397]  [<ffffffff810be378>] ?
ktime_get_ts+0xa8/0xe0
Feb 07 10:32:04 [kernel] [88365.922401]  [<ffffffff8189871a>]
io_schedule_timeout+0x9a/0xf0
Feb 07 10:32:04 [kernel] [88365.922404]  [<ffffffff811372ec>] ?
bdi_dirty_limit+0x2c/0xc0
Feb 07 10:32:04 [kernel] [88365.922408]  [<ffffffff811379ea>]
balance_dirty_pages_ratelimited_nr+0x2ba/0x770
Feb 07 10:32:04 [kernel] [88365.922417]  [<ffffffff81348114>] ?
xfs_iunlock+0x74/0xf0
Feb 07 10:32:04 [kernel] [88365.922422]  [<ffffffff8112c349>]
generic_file_buffered_write+0x1b9/0x280
Feb 07 10:32:04 [kernel] [88365.922426]  [<ffffffff81345900>]
xfs_file_buffered_aio_write+0xf0/0x1a0
Feb 07 10:32:04 [kernel] [88365.922430]  [<ffffffff8114e7ab>] ?
might_fault+0x3b/0x90
Feb 07 10:32:04 [kernel] [88365.922434]  [<ffffffff81345b62>]
xfs_file_aio_write+0x1b2/0x2f0
Feb 07 10:32:04 [kernel] [88365.922439]  [<ffffffff81198677>] ?
core_sys_select+0x47/0x390
Feb 07 10:32:04 [kernel] [88365.922442]  [<ffffffff8114e7ab>] ?
might_fault+0x3b/0x90
Feb 07 10:32:04 [kernel] [88365.922446]  [<ffffffff8118432a>]
do_sync_write+0xda/0x120
Feb 07 10:32:04 [kernel] [88365.922452]  [<ffffffff8143f167>] ?
security_file_permission+0x27/0xb0
Feb 07 10:32:04 [kernel] [88365.922455]  [<ffffffff81184c46>]
vfs_write+0xc6/0x190
Feb 07 10:32:04 [kernel] [88365.922458]  [<ffffffff81184f7f>]
sys_write+0x4f/0xa0
Feb 07 10:32:04 [kernel] [88365.922462]  [<ffffffff8189bffb>]
system_call_fastpath+0x16/0x1b
Feb 07 10:32:04 [kernel] [88365.922465] ssh             D
0000000000000000  4080 23087  23078 0x00000000
Feb 07 10:32:04 [kernel] [88365.922471]  ffff88010e2159a8
0000000000000046 ffffffff8189813a 0000000000000006
Feb 07 10:32:04 [kernel] [88365.922476]  0000000000000000
00000000001d2880 ffff8801b32d2680 00000000001d2880
Feb 07 10:32:04 [kernel] [88365.922482]  ffff88010e215fd8
ffff88010e214000 00000000001d2880 00000000001d2880
Feb 07 10:32:04 [kernel] [88365.922487] Call Trace:
Feb 07 10:32:04 [kernel] [88365.922490]  [<ffffffff8189813a>] ?
__schedule+0x70a/0x920
Feb 07 10:32:04 [kernel] [88365.922493]  [<ffffffff8189841a>] schedule+0x3a/0x50
Feb 07 10:32:04 [kernel] [88365.922497]  [<ffffffff8189891e>]
schedule_timeout+0x18e/0x2e0
Feb 07 10:32:04 [kernel] [88365.922500]  [<ffffffff810a0a10>] ?
cascade+0xa0/0xa0
Feb 07 10:32:04 [kernel] [88365.922504]  [<ffffffff810be378>] ?
ktime_get_ts+0xa8/0xe0
Feb 07 10:32:04 [kernel] [88365.922507]  [<ffffffff8189871a>]
io_schedule_timeout+0x9a/0xf0
Feb 07 10:32:04 [kernel] [88365.922511]  [<ffffffff811372ec>] ?
bdi_dirty_limit+0x2c/0xc0
Feb 07 10:32:04 [kernel] [88365.922515]  [<ffffffff811379ea>]
balance_dirty_pages_ratelimited_nr+0x2ba/0x770
Feb 07 10:32:04 [kernel] [88365.922518]  [<ffffffff811ac88b>] ?
__mark_inode_dirty+0x3b/0x220
Feb 07 10:32:04 [kernel] [88365.922522]  [<ffffffff81348114>] ?
xfs_iunlock+0x74/0xf0
Feb 07 10:32:04 [kernel] [88365.922526]  [<ffffffff8112c349>]
generic_file_buffered_write+0x1b9/0x280
Feb 07 10:32:04 [kernel] [88365.922537]  [<ffffffff81345b62>]
xfs_file_aio_write+0x1b2/0x2f0
Feb 07 10:32:04 [kernel] [88365.922541]  [<ffffffff81198677>] ?
core_sys_select+0x47/0x390
Feb 07 10:32:04 [kernel] [88365.922544]  [<ffffffff8114e7ab>] ?
might_fault+0x3b/0x90
Feb 07 10:32:04 [kernel] [88365.922547]  [<ffffffff8118432a>]
do_sync_write+0xda/0x120
Feb 07 10:32:04 [kernel] [88365.922551]  [<ffffffff8143f167>] ?
security_file_permission+0x27/0xb0
Feb 07 10:32:04 [kernel] [88365.922555]  [<ffffffff81184c46>]
vfs_write+0xc6/0x190
Feb 07 10:32:04 [kernel] [88365.922558]  [<ffffffff81184f7f>]
sys_write+0x4f/0xa0
Feb 07 10:32:04 [kernel] [88365.922562]  [<ffffffff8189bffb>]
system_call_fastpath+0x16/0x1b
Feb 07 10:32:04 [kernel] [88365.922568] Sched Debug Version: v0.10, 3.2.4 #2
Feb 07 10:32:04 [kernel] [88365.922571] ktime
         : 88365922.568795
Feb 07 10:32:04 [kernel] [88365.922574] sched_clk
         : 88191370.131237
Feb 07 10:32:04 [kernel] [88365.922576] cpu_clk
         : 88365922.567625
Feb 07 10:32:04 [kernel] [88365.922578] jiffies
         : 4383033218
Feb 07 10:32:04 [kernel] [88365.922580] sched_clock_stable
         : 0
Feb 07 10:32:04 [kernel] [88365.922582]
Feb 07 10:32:04 [kernel] [88365.922583] sysctl_sched
Feb 07 10:32:04 [kernel] [88365.922585]   .sysctl_sched_latency
            : 18.000000
Feb 07 10:32:04 [kernel] [88365.922588]
.sysctl_sched_min_granularity            : 2.250000
Feb 07 10:32:04 [kernel] [88365.922590]
.sysctl_sched_wakeup_granularity         : 3.000000
Feb 07 10:32:04 [kernel] [88365.922592]
.sysctl_sched_child_runs_first           : 0
Feb 07 10:32:04 [kernel] [88365.922594]   .sysctl_sched_features
            : 24119
Feb 07 10:32:04 [kernel] [88365.922597]
.sysctl_sched_tunable_scaling            : 1 (logaritmic)
Feb 07 10:32:04 [kernel] [88365.922600]
Feb 07 10:32:04 [kernel] [88365.922600] cpu#0, 2333.231 MHz
Feb 07 10:32:04 [kernel] [88365.922602]   .nr_running                    : 2
Feb 07 10:32:04 [kernel] [88365.922605]   .load                          : 2048
Feb 07 10:32:04 [kernel] [88365.922607]   .nr_switches
  : 47384343
Feb 07 10:32:04 [kernel] [88365.922609]   .nr_load_updates
  : 27680552
Feb 07 10:32:04 [kernel] [88365.922611]   .nr_uninterruptible            : 5780
Feb 07 10:32:04 [kernel] [88365.922613]   .next_balance
  : 4383.033233
Feb 07 10:32:04 [kernel] [88365.922615]   .curr->pid                     : 26616
Feb 07 10:32:04 [kernel] [88365.922620]   .cpu_load[0]                   : 2048
Feb 07 10:32:04 [kernel] [88365.922622]   .cpu_load[1]                   : 1024
Feb 07 10:32:04 [kernel] [88365.922623]   .cpu_load[2]                   : 512
Feb 07 10:32:04 [kernel] [88365.922625]   .cpu_load[3]                   : 256
Feb 07 10:32:04 [kernel] [88365.922627]   .cpu_load[4]                   : 128
Feb 07 10:32:04 [kernel] [88365.922629]   .yld_count                     : 0
Feb 07 10:32:04 [kernel] [88365.922631]   .sched_switch                  : 0
Feb 07 10:32:04 [kernel] [88365.922633]   .sched_count
  : 47523458
Feb 07 10:32:04 [kernel] [88365.922635]   .sched_goidle
  : 22579080
Feb 07 10:32:04 [kernel] [88365.922637]   .avg_idle
  : 888834
Feb 07 10:32:04 [kernel] [88365.922639]   .ttwu_count
  : 25633221
Feb 07 10:32:04 [kernel] [88365.922641]   .ttwu_local
  : 19078353
Feb 07 10:32:04 [kernel] [88365.922645]
Feb 07 10:32:04 [kernel] [88365.922646] cfs_rq[0]:/autogroup-861
Feb 07 10:32:04 [kernel] [88365.922648]   .exec_clock
  : 13.544484
Feb 07 10:32:04 [kernel] [88365.922652]   .MIN_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922654]   .min_vruntime
  : 6.378969
Feb 07 10:32:04 [kernel] [88365.922656]   .max_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922658]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922660]   .spread0
  : -3347531.515424
Feb 07 10:32:04 [kernel] [88365.922663]   .nr_spread_over                : 0
Feb 07 10:32:04 [kernel] [88365.922664]   .nr_running                    : 1
Feb 07 10:32:04 [kernel] [88365.922666]   .load                          : 1024
Feb 07 10:32:04 [kernel] [88365.922668]   .load_avg
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922671]   .load_period
  : 9.999999
Feb 07 10:32:04 [kernel] [88365.922673]   .load_contrib                  : 0
Feb 07 10:32:04 [kernel] [88365.922674]   .load_tg                       : 0
Feb 07 10:32:04 [kernel] [88365.922677]   .se->exec_start
  : 88365922.005056
Feb 07 10:32:04 [kernel] [88365.922679]   .se->vruntime
  : 3347529.024236
Feb 07 10:32:04 [kernel] [88365.922681]   .se->sum_exec_runtime
  : 13.544484
Feb 07 10:32:04 [kernel] [88365.922683]   .se->statistics.wait_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922686]   .se->statistics.sleep_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922688]   .se->statistics.block_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922690]   .se->statistics.sleep_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922692]   .se->statistics.block_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922694]   .se->statistics.exec_max
  : 1.397658
Feb 07 10:32:04 [kernel] [88365.922698]   .se->statistics.wait_max
  : 0.037956
Feb 07 10:32:04 [kernel] [88365.922700]   .se->statistics.wait_sum
  : 0.405641
Feb 07 10:32:04 [kernel] [88365.922702]   .se->statistics.wait_count     : 43
Feb 07 10:32:04 [kernel] [88365.922704]   .se->load.weight               : 1024
Feb 07 10:32:04 [kernel] [88365.922707]
Feb 07 10:32:04 [kernel] [88365.922707] cfs_rq[0]:/
Feb 07 10:32:04 [kernel] [88365.922709]   .exec_clock
  : 3857099.252074
Feb 07 10:32:04 [kernel] [88365.922712]   .MIN_vruntime
  : 3347528.894393
Feb 07 10:32:04 [kernel] [88365.922714]   .min_vruntime
  : 3347537.894393
Feb 07 10:32:04 [kernel] [88365.922716]   .max_vruntime
  : 3347528.894393
Feb 07 10:32:04 [kernel] [88365.922719]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922721]   .spread0
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922723]   .nr_spread_over                : 278
Feb 07 10:32:04 [kernel] [88365.922725]   .nr_running                    : 2
Feb 07 10:32:04 [kernel] [88365.922727]   .load                          : 2048
Feb 07 10:32:04 [kernel] [88365.922729]   .load_avg
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922731]   .load_period
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922733]   .load_contrib                  : 0
Feb 07 10:32:04 [kernel] [88365.922734]   .load_tg                       : 0
Feb 07 10:32:04 [kernel] [88365.922737]
Feb 07 10:32:04 [kernel] [88365.922737] rt_rq[0]:
Feb 07 10:32:04 [kernel] [88365.922739]   .rt_nr_running                 : 0
Feb 07 10:32:04 [kernel] [88365.922741]   .rt_throttled                  : 0
Feb 07 10:32:04 [kernel] [88365.922743]   .rt_time
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922745]   .rt_runtime
  : 950.000000
Feb 07 10:32:04 [kernel] [88365.922747]
Feb 07 10:32:04 [kernel] [88365.922748] runnable tasks:
Feb 07 10:32:04 [kernel] [88365.922749]             task   PID
tree-key  switches  prio     exec-runtime         sum-exec
sum-sleep
Feb 07 10:32:04 [kernel] [88365.922750]
----------------------------------------------------------------------------------------------------------
Feb 07 10:32:04 [kernel] [88365.922759]      kworker/0:1 25833
3347528.894393     19293   120   3347528.894393      1314.935421
2056117.209075 /
Feb 07 10:32:04 [kernel] [88365.922767] R           bash 26616
5.470536        54   120         5.470536        18.185136
37388.063060 /autogroup-861
Feb 07 10:32:04 [kernel] [88365.922777]
Feb 07 10:32:04 [kernel] [88365.922777] cpu#1, 2333.231 MHz
Feb 07 10:32:04 [kernel] [88365.922779]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.922781]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.922783]   .nr_switches
  : 48208480
Feb 07 10:32:04 [kernel] [88365.922785]   .nr_load_updates
  : 28422632
Feb 07 10:32:04 [kernel] [88365.922788]   .nr_uninterruptible            : 6243
Feb 07 10:32:04 [kernel] [88365.922790]   .next_balance
  : 4383.033438
Feb 07 10:32:04 [kernel] [88365.922792]   .curr->pid                     : 0
Feb 07 10:32:04 [kernel] [88365.922794]   .clock
  : 88365922.005609
Feb 07 10:32:04 [kernel] [88365.922796]   .cpu_load[0]                   : 0
Feb 07 10:32:04 [kernel] [88365.922798]   .cpu_load[1]                   : 30
Feb 07 10:32:04 [kernel] [88365.922800]   .cpu_load[2]                   : 78
Feb 07 10:32:04 [kernel] [88365.922802]   .cpu_load[3]                   : 74
Feb 07 10:32:04 [kernel] [88365.922803]   .cpu_load[4]                   : 62
Feb 07 10:32:04 [kernel] [88365.922805]   .yld_count                     : 2
Feb 07 10:32:04 [kernel] [88365.922807]   .sched_switch                  : 0
Feb 07 10:32:04 [kernel] [88365.922809]   .sched_count
  : 48351933
Feb 07 10:32:04 [kernel] [88365.922811]   .sched_goidle
  : 22985997
Feb 07 10:32:04 [kernel] [88365.922813]   .avg_idle
  : 988263
Feb 07 10:32:04 [kernel] [88365.922815]   .ttwu_count
  : 26052282
Feb 07 10:32:04 [kernel] [88365.922817]   .ttwu_local
  : 19528683
Feb 07 10:32:04 [kernel] [88365.922820]
Feb 07 10:32:04 [kernel] [88365.922821] cfs_rq[1]:/autogroup-776
Feb 07 10:32:04 [kernel] [88365.922823]   .exec_clock
  : 358297.296203
Feb 07 10:32:04 [kernel] [88365.922826]   .MIN_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922828]   .min_vruntime
  : 299834.428916
Feb 07 10:32:04 [kernel] [88365.922831]   .max_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922833]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922835]   .spread0
  : -3047703.465477
Feb 07 10:32:04 [kernel] [88365.922837]   .nr_spread_over                : 322
Feb 07 10:32:04 [kernel] [88365.922839]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.922841]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.922843]   .load_avg
  : 943.694796
Feb 07 10:32:04 [kernel] [88365.922845]   .load_period
  : 8.490465
Feb 07 10:32:04 [kernel] [88365.922849]   .load_tg                       : 214
Feb 07 10:32:04 [kernel] [88365.922854]   .se->vruntime
  : 3442136.706757
Feb 07 10:32:04 [kernel] [88365.922856]   .se->sum_exec_runtime
  : 358335.275642
Feb 07 10:32:04 [kernel] [88365.922858]   .se->statistics.wait_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922860]   .se->statistics.sleep_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922862]   .se->statistics.block_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922864]   .se->statistics.sleep_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922866]   .se->statistics.block_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922869]   .se->statistics.exec_max
  : 6.979434
Feb 07 10:32:04 [kernel] [88365.922871]   .se->statistics.slice_max
  : 8.909837
Feb 07 10:32:04 [kernel] [88365.922873]   .se->statistics.wait_max
  : 335.735845
Feb 07 10:32:04 [kernel] [88365.922875]   .se->statistics.wait_sum
  : 4606.806398
Feb 07 10:32:04 [kernel] [88365.922877]   .se->statistics.wait_count
  : 318111
Feb 07 10:32:04 [kernel] [88365.922879]   .se->load.weight               : 2
Feb 07 10:32:04 [kernel] [88365.922881]
Feb 07 10:32:04 [kernel] [88365.922882] cfs_rq[1]:/
Feb 07 10:32:04 [kernel] [88365.922883]   .exec_clock
  : 3999784.031074
Feb 07 10:32:04 [kernel] [88365.922886]   .MIN_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922888]   .min_vruntime
  : 3442142.654334
Feb 07 10:32:04 [kernel] [88365.922891]   .max_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922893]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922895]   .spread0
  : 94604.759941
Feb 07 10:32:04 [kernel] [88365.922897]   .nr_spread_over                : 267
Feb 07 10:32:04 [kernel] [88365.922899]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.922901]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.922903]   .load_avg
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922905]   .load_period
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922907]   .load_contrib                  : 0
Feb 07 10:32:04 [kernel] [88365.922909]   .load_tg                       : 0
Feb 07 10:32:04 [kernel] [88365.922911]
Feb 07 10:32:04 [kernel] [88365.922911] rt_rq[1]:
Feb 07 10:32:04 [kernel] [88365.922913]   .rt_nr_running                 : 0
Feb 07 10:32:04 [kernel] [88365.922915]   .rt_throttled                  : 0
Feb 07 10:32:04 [kernel] [88365.922917]   .rt_time
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922919]   .rt_runtime
  : 950.000000
Feb 07 10:32:04 [kernel] [88365.922921]
Feb 07 10:32:04 [kernel] [88365.922922] runnable tasks:
Feb 07 10:32:04 [kernel] [88365.922922]             task   PID
tree-key  switches  prio     exec-runtime         sum-exec
sum-sleep
Feb 07 10:32:04 [kernel] [88365.922924]
----------------------------------------------------------------------------------------------------------
Feb 07 10:32:04 [kernel] [88365.922932]
Feb 07 10:32:04 [kernel] [88365.922932] cpu#2, 2333.231 MHz
Feb 07 10:32:04 [kernel] [88365.922934]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.922936]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.922938]   .nr_switches
  : 46035661
Feb 07 10:32:04 [kernel] [88365.922940]   .nr_load_updates
  : 27665281
Feb 07 10:32:04 [kernel] [88365.922942]   .nr_uninterruptible            : -5740
Feb 07 10:32:04 [kernel] [88365.922944]   .next_balance
  : 4383.033403
Feb 07 10:32:04 [kernel] [88365.922946]   .curr->pid                     : 0
Feb 07 10:32:04 [kernel] [88365.922949]   .clock
  : 88365922.005806
Feb 07 10:32:04 [kernel] [88365.922951]   .cpu_load[0]                   : 0
Feb 07 10:32:04 [kernel] [88365.922953]   .cpu_load[1]                   : 256
Feb 07 10:32:04 [kernel] [88365.922954]   .cpu_load[2]                   : 197
Feb 07 10:32:04 [kernel] [88365.922956]   .cpu_load[3]                   : 134
Feb 07 10:32:04 [kernel] [88365.922958]   .cpu_load[4]                   : 94
Feb 07 10:32:04 [kernel] [88365.922960]   .yld_count                     : 1
Feb 07 10:32:04 [kernel] [88365.922962]   .sched_switch                  : 0
Feb 07 10:32:04 [kernel] [88365.922964]   .sched_count
  : 46171251
Feb 07 10:32:04 [kernel] [88365.922966]   .sched_goidle
  : 22169750
Feb 07 10:32:04 [kernel] [88365.922968]   .avg_idle
  : 674493
Feb 07 10:32:04 [kernel] [88365.922970]   .ttwu_count
  : 22246832
Feb 07 10:32:04 [kernel] [88365.922972]   .ttwu_local
  : 17360455
Feb 07 10:32:04 [kernel] [88365.922975]
Feb 07 10:32:04 [kernel] [88365.922976] cfs_rq[2]:/autogroup-860
Feb 07 10:32:04 [kernel] [88365.922978]   .exec_clock
  : 11.396092
Feb 07 10:32:04 [kernel] [88365.922981]   .MIN_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922983]   .min_vruntime
  : 9.488006
Feb 07 10:32:04 [kernel] [88365.922985]   .max_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.922987]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.922989]   .spread0
  : -3347528.406387
Feb 07 10:32:04 [kernel] [88365.922991]   .nr_spread_over                : 0
Feb 07 10:32:04 [kernel] [88365.922993]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.923002]   .load_contrib                  : 1021
Feb 07 10:32:04 [kernel] [88365.923004]   .load_tg                       : 1021
Feb 07 10:32:04 [kernel] [88365.923004]   .se->exec_start
  : 88365921.858706
Feb 07 10:32:04 [kernel] [88365.923004]   .se->vruntime
  : 2777211.488892
Feb 07 10:32:04 [kernel] [88365.923004]   .se->sum_exec_runtime
  : 11.396092
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.sleep_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.block_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.sleep_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.block_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.exec_max
  : 0.999893
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.slice_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_max
  : 0.051092
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_sum
  : 0.064620
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_count     : 36
Feb 07 10:32:04 [kernel] [88365.923004]   .se->load.weight               : 2
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] cfs_rq[2]:/autogroup-776
Feb 07 10:32:04 [kernel] [88365.923004]   .exec_clock
  : 342105.615121
Feb 07 10:32:04 [kernel] [88365.923004]   .MIN_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.923004]   .min_vruntime
  : 289931.479153
Feb 07 10:32:04 [kernel] [88365.923004]   .max_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.923004]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .spread0
  : -3057606.415240
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_spread_over                : 307
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load_avg
  : 525.511404
Feb 07 10:32:04 [kernel] [88365.923004]   .load_period
  : 5.090393
Feb 07 10:32:04 [kernel] [88365.923004]   .load_contrib                  : 103
Feb 07 10:32:04 [kernel] [88365.923004]   .load_tg                       : 214
Feb 07 10:32:04 [kernel] [88365.923004]   .se->exec_start
  : 88365920.891042
Feb 07 10:32:04 [kernel] [88365.923004]   .se->vruntime
  : 2777220.245050
Feb 07 10:32:04 [kernel] [88365.923004]   .se->sum_exec_runtime
  : 342139.770710
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.sleep_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.block_start
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.sleep_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.block_max
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.exec_max
  : 6.074755
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.slice_max
  : 15.625920
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_max
  : 16.153034
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_sum
  : 4251.654869
Feb 07 10:32:04 [kernel] [88365.923004]   .se->statistics.wait_count
  : 308775
Feb 07 10:32:04 [kernel] [88365.923004]   .se->load.weight               : 2
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] cfs_rq[2]:/
Feb 07 10:32:04 [kernel] [88365.923004]   .exec_clock
  : 3362268.845416
Feb 07 10:32:04 [kernel] [88365.923004]   .MIN_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.923004]   .min_vruntime
  : 2777220.368423
Feb 07 10:32:04 [kernel] [88365.923004]   .max_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.923004]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .spread0
  : -570317.525970
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_spread_over                : 500
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load_avg
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .load_period
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .load_contrib                  : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load_tg                       : 0
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] rt_rq[2]:
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_nr_running                 : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_throttled                  : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_time
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_runtime
  : 950.000000
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] runnable tasks:
Feb 07 10:32:04 [kernel] [88365.923004]             task   PID
tree-key  switches  prio     exec-runtime         sum-exec
sum-sleep
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] cpu#3, 2333.231 MHz
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_switches
  : 45074548
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_load_updates
  : 27257305
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_uninterruptible            : -6280
Feb 07 10:32:04 [kernel] [88365.923004]   .next_balance
  : 4383.033407
Feb 07 10:32:04 [kernel] [88365.923004]   .curr->pid                     : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .clock
  : 88365923.004961
Feb 07 10:32:04 [kernel] [88365.923004]   .cpu_load[0]                   : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .cpu_load[1]                   : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .cpu_load[2]                   : 2
Feb 07 10:32:04 [kernel] [88365.923004]   .cpu_load[3]                   : 31
Feb 07 10:32:04 [kernel] [88365.923004]   .cpu_load[4]                   : 71
Feb 07 10:32:04 [kernel] [88365.923004]   .yld_count                     : 1
Feb 07 10:32:04 [kernel] [88365.923004]   .sched_switch                  : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .sched_count
  : 45213014
Feb 07 10:32:04 [kernel] [88365.923004]   .sched_goidle
  : 21712500
Feb 07 10:32:04 [kernel] [88365.923004]   .avg_idle
  : 1000000
Feb 07 10:32:04 [kernel] [88365.923004]   .ttwu_count
  : 21742662
Feb 07 10:32:04 [kernel] [88365.923004]   .ttwu_local
  : 16876989
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] cfs_rq[3]:/
Feb 07 10:32:04 [kernel] [88365.923004]   .exec_clock
  : 3311584.271942
Feb 07 10:32:04 [kernel] [88365.923004]   .MIN_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.923004]   .min_vruntime
  : 2796366.160205
Feb 07 10:32:04 [kernel] [88365.923004]   .max_vruntime
  : 0.000001
Feb 07 10:32:04 [kernel] [88365.923004]   .spread
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .spread0
  : -551171.734188
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_spread_over                : 1027
Feb 07 10:32:04 [kernel] [88365.923004]   .nr_running                    : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load                          : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load_avg
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .load_period
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .load_contrib                  : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .load_tg                       : 0
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] rt_rq[3]:
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_nr_running                 : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_throttled                  : 0
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_time
  : 0.000000
Feb 07 10:32:04 [kernel] [88365.923004]   .rt_runtime
  : 950.000000
Feb 07 10:32:04 [kernel] [88365.923004]
Feb 07 10:32:04 [kernel] [88365.923004] runnable tasks:
Feb 07 10:32:04 [kernel] [88365.923004]             task   PID
tree-key  switches  prio     exec-runtime         sum-exec
sum-sleep
Feb 07 10:32:04 [kernel] [88365.923004]
----------------------------------------------------------------------------------------------------------
Feb 07 10:32:04 [kernel] [88365.923004]



More information about the xfs mailing list