title: MySQL database hangs due to disk journaling?
body: <p>Occasionally one of our Linux MySQL database servers will hang for a while, creating a long queue of active queries. After 10-20 mins, service resumes as normally.</p>
  
  <p>This happens in kern.log:</p>
  
  <pre><code>May 14 13:58:05 edu02 kernel: [2375521.716786] INFO: task jbd2/md2-8:1419 blocked for more than 120 seconds.
  May 14 13:58:05 edu02 kernel: [2375521.716870] "echo 0 &gt; /proc/sys/kernel/hung_task_timeout_secs" disables this message.
  May 14 13:58:05 edu02 kernel: [2375521.716953] jbd2/md2-8    D ffff88043b5a23f0     0  1419      2 0x00000000
  May 14 13:58:05 edu02 kernel: [2375521.716958]  ffff88043b5a23f0 0000000000000046 00000000000000ff ffff88043b4e69c0
  May 14 13:58:05 edu02 kernel: [2375521.716963]  00000000ffffffff ffffffff8118bac3 000000000000f9e0 ffff88043d099fd8
  May 14 13:58:05 edu02 kernel: [2375521.716967]  00000000000157c0 00000000000157c0 ffff88043a411cc0 ffff88043a411fb8
  May 14 13:58:05 edu02 kernel: [2375521.716971] Call Trace:
  May 14 13:58:05 edu02 kernel: [2375521.716981]  [&lt;ffffffff8118bac3&gt;] ? generic_make_request+0x299/0x2f9
  May 14 13:58:05 edu02 kernel: [2375521.716988]  [&lt;ffffffff810168ec&gt;] ? read_tsc+0xa/0x20
  May 14 13:58:05 edu02 kernel: [2375521.716994]  [&lt;ffffffff810757f6&gt;] ? timekeeping_get_ns+0xe/0x2e
  May 14 13:58:05 edu02 kernel: [2375521.716999]  [&lt;ffffffff8111a5f2&gt;] ? sync_buffer+0x0/0x40
  May 14 13:58:05 edu02 kernel: [2375521.717004]  [&lt;ffffffff8130b4a2&gt;] ? io_schedule+0x73/0xb7
  May 14 13:58:05 edu02 kernel: [2375521.717007]  [&lt;ffffffff8111a62d&gt;] ? sync_buffer+0x3b/0x40
  May 14 13:58:05 edu02 kernel: [2375521.717010]  [&lt;ffffffff8130b9af&gt;] ? __wait_on_bit+0x41/0x70
  May 14 13:58:05 edu02 kernel: [2375521.717014]  [&lt;ffffffff8111a5f2&gt;] ? sync_buffer+0x0/0x40
  May 14 13:58:05 edu02 kernel: [2375521.717017]  [&lt;ffffffff8130ba49&gt;] ? out_of_line_wait_on_bit+0x6b/0x77
  May 14 13:58:05 edu02 kernel: [2375521.717021]  [&lt;ffffffff81066210&gt;] ? wake_bit_function+0x0/0x23
  May 14 13:58:05 edu02 kernel: [2375521.717035]  [&lt;ffffffffa0138a22&gt;] ? jbd2_journal_commit_transaction+0xbe5/0x115b [jbd2]
  May 14 13:58:05 edu02 kernel: [2375521.717043]  [&lt;ffffffffa013e8c1&gt;] ? kjournald2+0xbe/0x206 [jbd2]
  May 14 13:58:05 edu02 kernel: [2375521.717046]  [&lt;ffffffff810661e2&gt;] ? autoremove_wake_function+0x0/0x2e
  May 14 13:58:05 edu02 kernel: [2375521.717052]  [&lt;ffffffffa013e803&gt;] ? kjournald2+0x0/0x206 [jbd2]
  May 14 13:58:05 edu02 kernel: [2375521.717055]  [&lt;ffffffff81065f15&gt;] ? kthread+0x79/0x81
  May 14 13:58:05 edu02 kernel: [2375521.717058]  [&lt;ffffffff81011baa&gt;] ? child_rip+0xa/0x20
  May 14 13:58:05 edu02 kernel: [2375521.717062]  [&lt;ffffffff81065e9c&gt;] ? kthread+0x0/0x81
  May 14 13:58:05 edu02 kernel: [2375521.717064]  [&lt;ffffffff81011ba0&gt;] ? child_rip+0x0/0x20
  May 14 13:58:05 edu02 kernel: [2375521.717080] INFO: task mysqld:5879 blocked for more than 120 seconds.
  May 14 13:58:05 edu02 kernel: [2375521.717132] "echo 0 &gt; /proc/sys/kernel/hung_task_timeout_secs" disables this message.
  May 14 13:58:05 edu02 kernel: [2375521.717215] mysqld        D ffff88000facfb30     0  5879   2279 0x00000000
  May 14 13:58:05 edu02 kernel: [2375521.717219]  ffff88043e46f300 0000000000000082 ffff88043c703d08 ffff88043c703d04
  May 14 13:58:05 edu02 kernel: [2375521.717223]  0000000000000008 ffffffffa017942a 000000000000f9e0 ffff88043c703fd8
  May 14 13:58:05 edu02 kernel: [2375521.717226]  00000000000157c0 00000000000157c0 ffff88043ad09cc0 ffff88043ad09fb8
  May 14 13:58:05 edu02 kernel: [2375521.717230] Call Trace:
  May 14 13:58:05 edu02 kernel: [2375521.717247]  [&lt;ffffffffa017942a&gt;] ? ext4_journal_start_sb+0xd4/0x10e [ext4]
  May 14 13:58:05 edu02 kernel: [2375521.717256]  [&lt;ffffffffa0179350&gt;] ? __ext4_journal_stop+0x63/0x69 [ext4]
  May 14 13:58:05 edu02 kernel: [2375521.717264]  [&lt;ffffffffa01634de&gt;] ? ext4_da_writepages+0x4e2/0x65c [ext4]
  May 14 13:58:05 edu02 kernel: [2375521.717269]  [&lt;ffffffff810be235&gt;] ? sync_page+0x0/0x46
  May 14 13:58:05 edu02 kernel: [2375521.717272]  [&lt;ffffffff8130b4a2&gt;] ? io_schedule+0x73/0xb7
  May 14 13:58:05 edu02 kernel: [2375521.717275]  [&lt;ffffffff810be276&gt;] ? sync_page+0x41/0x46
  May 14 13:58:05 edu02 kernel: [2375521.717278]  [&lt;ffffffff8130b9af&gt;] ? __wait_on_bit+0x41/0x70
  May 14 13:58:05 edu02 kernel: [2375521.717282]  [&lt;ffffffff810be3fa&gt;] ? wait_on_page_bit+0x6b/0x71
  May 14 13:58:05 edu02 kernel: [2375521.717285]  [&lt;ffffffff81066210&gt;] ? wake_bit_function+0x0/0x23
  May 14 13:58:05 edu02 kernel: [2375521.717289]  [&lt;ffffffff810c6222&gt;] ? pagevec_lookup_tag+0x1a/0x21
  May 14 13:58:05 edu02 kernel: [2375521.717293]  [&lt;ffffffff810bebda&gt;] ? wait_on_page_writeback_range+0x69/0x11b
  May 14 13:58:05 edu02 kernel: [2375521.717297]  [&lt;ffffffff810bed00&gt;] ? __filemap_fdatawrite_range+0x4b/0x54
  May 14 13:58:05 edu02 kernel: [2375521.717301]  [&lt;ffffffff810bed4c&gt;] ? filemap_write_and_wait_range+0x43/0x52
  May 14 13:58:05 edu02 kernel: [2375521.717305]  [&lt;ffffffff81118106&gt;] ? vfs_fsync_range+0x55/0x9e
  May 14 13:58:05 edu02 kernel: [2375521.717308]  [&lt;ffffffff811181ce&gt;] ? do_fsync+0x28/0x39
  May 14 13:58:05 edu02 kernel: [2375521.717311]  [&lt;ffffffff811181fd&gt;] ? sys_fsync+0xb/0x10
  May 14 13:58:05 edu02 kernel: [2375521.717315]  [&lt;ffffffff81010b42&gt;] ? system_call_fastpath+0x16/0x1b
  May 14 14:04:05 edu02 kernel: [2375881.716569] INFO: task mysqld:20799 blocked for more than 120 seconds.
  May 14 14:04:05 edu02 kernel: [2375881.716626] "echo 0 &gt; /proc/sys/kernel/hung_task_timeout_secs" disables this message.
  May 14 14:04:05 edu02 kernel: [2375881.716710] mysqld        D 0000000000000000     0 20799   2279 0x00000000
  May 14 14:04:05 edu02 kernel: [2375881.716716]  ffff88043e46d640 0000000000000082 0000000000000000 ffff8800839be930
  May 14 14:04:05 edu02 kernel: [2375881.716720]  ffff88043b4e4680 ffff88043b4e4680 000000000000f9e0 ffff88009592ffd8
  May 14 14:04:05 edu02 kernel: [2375881.716724]  00000000000157c0 00000000000157c0 ffff880014059cc0 ffff880014059fb8
  May 14 14:04:05 edu02 kernel: [2375881.716729] Call Trace:
  May 14 14:04:05 edu02 kernel: [2375881.716740]  [&lt;ffffffff81066103&gt;] ? bit_waitqueue+0x10/0xa0
  May 14 14:04:05 edu02 kernel: [2375881.716766]  [&lt;ffffffffa01371ba&gt;] ? do_get_write_access+0x22c/0x452 [jbd2]
  May 14 14:04:05 edu02 kernel: [2375881.716771]  [&lt;ffffffff81066210&gt;] ? wake_bit_function+0x0/0x23
  May 14 14:04:05 edu02 kernel: [2375881.716777]  [&lt;ffffffffa0137402&gt;] ? jbd2_journal_get_write_access+0x22/0x33 [jbd2]
  May 14 14:04:05 edu02 kernel: [2375881.716796]  [&lt;ffffffffa017fee6&gt;] ? __ext4_journal_get_write_access+0x4e/0x56 [ext4]
  May 14 14:04:05 edu02 kernel: [2375881.716804]  [&lt;ffffffffa015fe4c&gt;] ? ext4_reserve_inode_write+0x37/0x73 [ext4]
  May 14 14:04:05 edu02 kernel: [2375881.716811]  [&lt;ffffffffa015fec3&gt;] ? ext4_mark_inode_dirty+0x3b/0x1c4 [ext4]
  May 14 14:04:05 edu02 kernel: [2375881.716820]  [&lt;ffffffffa017942a&gt;] ? ext4_journal_start_sb+0xd4/0x10e [ext4]
  May 14 14:04:05 edu02 kernel: [2375881.716826]  [&lt;ffffffff8130b4c2&gt;] ? io_schedule+0x93/0xb7
  May 14 14:04:05 edu02 kernel: [2375881.716833]  [&lt;ffffffffa016016e&gt;] ? ext4_dirty_inode+0x30/0x46 [ext4]
  May 14 14:04:05 edu02 kernel: [2375881.716840]  [&lt;ffffffff811148f1&gt;] ? __mark_inode_dirty+0x25/0x14a
  May 14 14:04:05 edu02 kernel: [2375881.716844]  [&lt;ffffffff8110b958&gt;] ? touch_atime+0x10a/0x133
  May 14 14:04:05 edu02 kernel: [2375881.716850]  [&lt;ffffffff810bf8f0&gt;] ? generic_file_aio_read+0x499/0x536
  May 14 14:04:05 edu02 kernel: [2375881.716855]  [&lt;ffffffff810f9c45&gt;] ? do_sync_read+0xce/0x113
  May 14 14:04:05 edu02 kernel: [2375881.716858]  [&lt;ffffffff810661e2&gt;] ? autoremove_wake_function+0x0/0x2e
  May 14 14:04:05 edu02 kernel: [2375881.716862]  [&lt;ffffffff81105a05&gt;] ? user_path_at+0x52/0x79
  May 14 14:04:05 edu02 kernel: [2375881.716866]  [&lt;ffffffff810fa668&gt;] ? vfs_read+0xa6/0xff
  May 14 14:04:05 edu02 kernel: [2375881.716869]  [&lt;ffffffff810fa77d&gt;] ? sys_read+0x45/0x6e
  May 14 14:04:05 edu02 kernel: [2375881.716873]  [&lt;ffffffff81010b42&gt;] ? system_call_fastpath+0x16/0x1b
  </code></pre>
  
  <p>The stack trace leads me to think it is file system/journaling or disk related, but I cannot be sure. There will usually be other errors in dmesg when a drive is failing, and the S.M.A.R.T. status is fine for both drives in the server.</p>
  
  <p>What would cause such hangs?</p>