0

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.)

1

3 Answers 3

1

EC2 is down right now, and the behavior you are experiencing is almost identical to the one I am experiencing, so it's probably the outage that is affecting you, and not your actual setup. Try moving to a different zone, if that's an option for you.

1

See answer here. In short, downgrading to Ubuntu 8.04 LTS solved the problem.

0

Turned out to be related to incompatibility between Ubuntu 10.* kernels and certain CPU models used in EC2 large/xlarge instances: https://bugs.launchpad.net/ubuntu/+source/linux-ec2/+bug/708920

Our AWS contact also pointed out the following issue that may be related: https://forums.aws.amazon.com/thread.jspa?threadID=59753

Downgrading to Ubuntu 8.04 LTS solved the problem for now.

You must log in to answer this question.

Not the answer you're looking for? Browse other questions tagged .