Asked this question on on stackoverflow, reposting:
Have an xlarge instance in AWS running 9 Tomcats with heaps from 256M to 4G. With Ubuntu 10.04 the box sporadically hangs for a few hours with huge run queue (30-40), and nothing on CPU, then recovers. Was suspecting GC, but reproed both with and without CMS GC.
After upgrading to 10.10, machine goes into 100% wait in a couple of hours after start, again with no processes on CPU. Here is output from top:
top - 18:33:44 up 3:11, 2 users, load average: 26.99, 26.80, 25.82
Tasks: 126 total, 1 running, 125 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.0%us, 0.0%sy, 0.0%ni, 0.0%id,100.0%wa, 0.0%hi, 0.0%si, 0.0%st
Mem: 15373736k total, 15174780k used, 198956k free, 51288k buffers
Swap: 0k total, 0k used, 0k free, 6208956k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
5910 tomcat6 20 0 746m 361m 9872 S 0 2.4 2:01.32 java
10147 tomcat6 20 0 919m 173m 9.8m S 0 1.2 0:22.60 java
12328 ubuntu 20 0 19276 1320 968 R 0 0.0 0:01.41 top
1 root 20 0 23864 2012 1300 S 0 0.0 0:00.38 init
2 root 20 0 0 0 0 S 0 0.0 0:00.00 kthreadd
...
Nothing useful in GC log (on larger instances, with MarkSweep, major GC occurs every 5 min and takes ~4s, incremental is completing in .1 - .2s, plenty of free memory in all generations).
Here is dstat output:
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai hiq siq| read writ| recv send| in out | int csw
5 1 51 43 0 0| 63k 512k| 0 0 | 0 0 | 435 401
0 0 0 100 0 0| 0 0 | 52B 834B| 0 0 | 185 315
0 0 0 100 0 0| 0 0 |4997B 14k| 0 0 | 247 360
0 0 0 100 0 0| 0 0 | 52B 354B| 0 0 | 146 318
0 0 0 100 0 0| 0 0 | 52B 354B| 0 0 | 149 314
0 0 0 100 0 0| 0 0 | 52B 354B| 0 0 | 145 318
0 0 0 100 0 0| 0 0 |4997B 14k| 0 0 | 227 345
0 0 0 100 0 0| 0 0 | 52B 354B| 0 0 | 158 325
0 0 0 100 0 0| 0 0 | 52B 354B| 0 0 | 160 306
0 0 0 100 0 0| 0 0 | 52B 354B| 0 0 | 148 319
0 0 0 100 0 0| 0 0 |4619B 14k| 0 0 | 224 353
At the time when wait started going through the roof, it was at the end of downloading/parsing a bunch of large files from s3 and writing them locally to disk (instance store). Thread dump (on jconsole, can't kill -3 on the box - hangs), shows single thread blocked at writing to disk.
I am lost. Which rock to turn next? What may be going on here?
UPDATE:
This appears to be related to Ubuntu Maverick hanging with "task blocked for more than 120 seconds", on both 10.04 and 10.10. From kernel.log on 10.04:
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909553] INFO: task kjournald:91 blocked for more than 120 seconds.
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909565] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909571] kjournald D ffff8803be10c424 0 91 2 0x00000000
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909575] ffff8803be147d50 0000000000000246 0000000000000000 ffff8803be147cd0
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909579] 0000000000000000 ffff8803be147d18 ffff8803be1448b8 ffff8803be147fd8
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909581] ffff8803be144500 ffff8803be144500 ffff8803be144500 ffff8803be147fd8
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909584] Call Trace:
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909595] [<ffffffff811ff29d>] journal_commit_transaction+0x18d/0xf20
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909601] [<ffffffff81059d50>] ? autoremove_wake_function+0x0/0x40
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909606] [<ffffffff8104c1be>] ? try_to_del_timer_sync+0x6e/0xd0
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909610] [<ffffffff812040da>] kjournald+0xfa/0x290
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909613] [<ffffffff81059d50>] ? autoremove_wake_function+0x0/0x40
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909615] [<ffffffff81203fe0>] ? kjournald+0x0/0x290
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909617] [<ffffffff8105986e>] kthread+0x8e/0xa0
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909622] [<ffffffff8100a70a>] child_rip+0xa/0x20
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909625] [<ffffffff810597e0>] ? kthread+0x0/0xa0
Apr 19 02:47:11 ip-10-110-67-175 kernel: [51985.909627] [<ffffffff8100a700>] ? child_rip+0x0/0x20
From kernel.log on 10.10:
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462810] INFO: task kjournald:716 blocked for more than 120 seconds.
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462834] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462842] kjournald D ffff880005bfb980 0 716 2 0x00000000
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462849] ffff8803aee4ba20 0000000000000246 ffff880300000000 0000000000015980
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462855] ffff8803aee4bfd8 0000000000015980 ffff8803aee4bfd8 ffff8803aef1c4a0
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462861] 0000000000015980 0000000000015980 ffff8803aee4bfd8 0000000000015980
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462867] Call Trace:
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462880] [<ffffffff815a20f3>] io_schedule+0x73/0xc0
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462887] [<ffffffff812a2f1c>] get_request_wait+0xcc/0x1a0
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462893] [<ffffffff8107f080>] ? autoremove_wake_function+0x0/0x40
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462897] [<ffffffff812a3083>] __make_request+0x93/0x4b0
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462903] [<ffffffff81102cc5>] ? mempool_alloc_slab+0x15/0x20
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462907] [<ffffffff812a1c63>] generic_make_request+0x1b3/0x540
Apr 18 05:58:07 ip-10-70-147-162 kernel: [899447.462911] [<ffffffff81102cc5>] ? mempool_alloc_slab+0x15/0x20
This appears to always start with kjournald, and then other process show up with similar message (flush, java, etc.)