md kernel thread hung in raid1_add_disk

md kernel thread hung in raid1_add_disk

[Matthias Eble]

Hi all,

last week, we had an issue where one md raid1 kernel thread got stuck.
It blocked while adding a new disk. No I/O could complete any more;
cat /proc/mdstat hung.

Interestingly "ps" commands also hung because reading the data of one
process (cat /proc/pid/cmdline) also blocked. To me it looks like a deadlock,
where the raid1 thread got stuck while raising a barrier, and
others (for example jbd2) were waiting for the completion.

The plan was to replace the existing 2 mirror disks with 2 new ones.
The commands that led to the problem were:
  mdadm --add /dev/md/PW1_bin_01 /dev/mapper/wwn-new-disk1
  mdadm --grow /dev/md/PW1_bin_01 -n 3
    ---> let it sync
  mdadm --fail /dev/md/PW1_bin_01 /dev/mapper/wwn-old-disk-1 (dm-8)
  mdadm --remove /dev/md/PW1_bin_01 /dev/mapper/wwn-old-disk-1 (dm-8)
  mdadm --add /dev/md/PW1_bin_01 /dev/mapper/wwn-new-disk2 (dm-115)
    ---> hung

Here are some strack traces:
(the entire log is at
http://pastie.org/pastes/9277512/text?key=e4ifnuef8nbsh5ricfu7sq)

2014-06-05T09:01:59.276852+02:00 myhost kernel: md/raid1:md119: Disk
failure on dm-8, disabling device.
2014-06-05T09:01:59.276876+02:00 myhost kernel: md/raid1:md119:
Operation continuing on 2 devices.
2014-06-05T09:02:27.319939+02:00 myhost kernel: md: unbind<dm-8>
2014-06-05T09:02:27.330942+02:00 myhost kernel: md: export_rdev(dm-8)
2014-06-05T09:02:44.591804+02:00 myhost kernel: md: bind<dm-115>
2014-06-05T09:03:41.647701+02:00 myhost rsyslogd-2177: imuxsock lost
104 messages from pid 48202 due to rate-limiting
2014-06-05T09:05:23.736908+02:00 myhost kernel: INFO: task
md119_raid1:52093 blocked for more than 120 seconds.
2014-06-05T09:05:23.736928+02:00 myhost kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
2014-06-05T09:05:23.736930+02:00 myhost kernel: md119_raid1   D
0000000000000007     0 52093      2 0x00000080
2014-06-05T09:05:23.736948+02:00 myhost kernel: ffff8817d790bba0
0000000000000046 ffff8817d790bb68 ffff8817d790bb64
2014-06-05T09:05:23.736953+02:00 myhost kernel: 0000000000000286
ffff88183fe71600 ffff88007d836700 0000000000000df3
2014-06-05T09:05:23.736956+02:00 myhost kernel: ffff881751477058
ffff8817d790bfd8 000000000000fb88 ffff881751477058
2014-06-05T09:05:23.736957+02:00 myhost kernel: Call Trace:
2014-06-05T09:05:23.736961+02:00 myhost kernel: [<ffffffffa02d73fd>]
raise_barrier+0x9d/0x1a0 [raid1]
2014-06-05T09:05:23.736963+02:00 myhost kernel: [<ffffffff81063310>] ?
default_wake_function+0x0/0x20
2014-06-05T09:05:23.736966+02:00 myhost kernel: [<ffffffff81092ae0>] ?
wakeme_after_rcu+0x0/0x20
2014-06-05T09:05:23.736983+02:00 myhost kernel: [<ffffffffa02d7dfc>]
raid1_add_disk+0x11c/0x1c0 [raid1]
2014-06-05T09:05:23.742128+02:00 myhost kernel: [<ffffffff8140d84b>]
md_check_recovery+0x54b/0x6c0
2014-06-05T09:05:23.742142+02:00 myhost kernel: [<ffffffffa02d878c>]
raid1d+0x4c/0x1800 [raid1]
2014-06-05T09:05:23.742144+02:00 myhost kernel: [<ffffffff8150db90>] ?
thread_return+0x4e/0x76e
2014-06-05T09:05:23.742146+02:00 myhost kernel: [<ffffffff8150ea05>] ?
schedule_timeout+0x215/0x2e0
2014-06-05T09:05:23.742150+02:00 myhost kernel: [<ffffffff81405c96>]
md_thread+0x116/0x150
2014-06-05T09:05:23.742153+02:00 myhost kernel: [<ffffffff81096ca0>] ?
autoremove_wake_function+0x0/0x40
2014-06-05T09:05:23.742154+02:00 myhost kernel: [<ffffffff81405b80>] ?
md_thread+0x0/0x150
2014-06-05T09:05:23.742155+02:00 myhost kernel: [<ffffffff81096936>]
kthread+0x96/0xa0
2014-06-05T09:05:23.742156+02:00 myhost kernel: [<ffffffff8100c0ca>]
child_rip+0xa/0x20
2014-06-05T09:05:23.742157+02:00 myhost kernel: [<ffffffff810968a0>] ?
kthread+0x0/0xa0
2014-06-05T09:05:23.742158+02:00 myhost kernel: [<ffffffff8100c0c0>] ?
child_rip+0x0/0x20

2014-06-05T09:05:23.742159+02:00 myhost kernel: INFO: task
jbd2/dm-48-8:55540 blocked for more than 120 seconds.
2014-06-05T09:05:23.742161+02:00 myhost kernel: "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
2014-06-05T09:05:23.742162+02:00 myhost kernel: jbd2/dm-48-8  D
000000000000000c     0 55540      2 0x00000080
2014-06-05T09:05:23.742163+02:00 myhost kernel: ffff8816d6c6b9a0
0000000000000046 0000000000000000 ffff8830182a2e50
2014-06-05T09:05:23.742164+02:00 myhost kernel: 0000000000000286
0000000000000003 0000000000000001 0000000000000286
2014-06-05T09:05:23.742165+02:00 myhost kernel: ffff881817765ab8
ffff8816d6c6bfd8 000000000000fb88 ffff881817765ab8
2014-06-05T09:05:23.742166+02:00 myhost kernel: Call Trace:
2014-06-05T09:05:23.748008+02:00 myhost kernel: [<ffffffffa02d769a>]
wait_barrier+0x13a/0x180 [raid1]
2014-06-05T09:05:23.748043+02:00 myhost kernel: [<ffffffff81063310>] ?
default_wake_function+0x0/0x20
2014-06-05T09:05:23.748047+02:00 myhost kernel: [<ffffffffa02d9fbe>]
make_request+0x7e/0xd50 [raid1]
2014-06-05T09:05:23.748049+02:00 myhost kernel: [<ffffffffa000167d>] ?
__map_bio+0xad/0x140 [dm_mod]
2014-06-05T09:05:23.748051+02:00 myhost kernel: [<ffffffff81404235>]
md_make_request+0xd5/0x210
2014-06-05T09:05:23.748054+02:00 myhost kernel: [<ffffffff8125ce0e>]
generic_make_request+0x25e/0x530
2014-06-05T09:05:23.748056+02:00 myhost kernel: [<ffffffff8111c575>] ?
mempool_alloc_slab+0x15/0x20
2014-06-05T09:05:23.748059+02:00 myhost kernel: [<ffffffffa00f460e>] ?
jbd2_journal_file_buffer+0x4e/0x90 [jbd2]
2014-06-05T09:05:23.748061+02:00 myhost kernel: [<ffffffff8125d16d>]
submit_bio+0x8d/0x120
2014-06-05T09:05:23.748064+02:00 myhost kernel: [<ffffffff811b4cb6>]
submit_bh+0xf6/0x150
2014-06-05T09:05:23.748067+02:00 myhost kernel: [<ffffffffa00f5bc8>]
jbd2_journal_commit_transaction+0x598/0x14b0 [jbd2]
2014-06-05T09:05:23.748073+02:00 myhost kernel: [<ffffffff810096f0>] ?
__switch_to+0xd0/0x320
2014-06-05T09:05:23.748076+02:00 myhost kernel: [<ffffffff81081a5b>] ?
try_to_del_timer_sync+0x7b/0xe0
2014-06-05T09:05:23.748078+02:00 myhost kernel: [<ffffffffa00fbf38>]
kjournald2+0xb8/0x220 [jbd2]
2014-06-05T09:05:23.748080+02:00 myhost kernel: [<ffffffff81096ca0>] ?
autoremove_wake_function+0x0/0x40
2014-06-05T09:05:23.748082+02:00 myhost kernel: [<ffffffffa00fbe80>] ?
kjournald2+0x0/0x220 [jbd2]
2014-06-05T09:05:23.748084+02:00 myhost kernel: [<ffffffff81096936>]
kthread+0x96/0xa0
2014-06-05T09:05:23.748086+02:00 myhost kernel: [<ffffffff8100c0ca>]
child_rip+0xa/0x20
2014-06-05T09:05:23.748090+02:00 myhost kernel: [<ffffffff810968a0>] ?
kthread+0x0/0xa0
2014-06-05T09:05:23.748092+02:00 myhost kernel: [<ffffffff8100c0c0>] ?
child_rip+0x0/0x20


Short facts:
   * All disks are dm-mp backed FC-SAN volumes.
   * On top are multiple LVM volumes with ext4 file systems
   * Files are used by an Oracle Database (binaries and redo logs, so
it should be direct io, if that matters)
      * the system was online and operational
   * OS is Rhel6, kernel is 2.6.32-358.6.2.el6.x86_64
   * no write intent bitmap is used

Now the questions:
   * does anybody have an idea what the problem could be?
   * or some ideas what I could do to narrow down problem, or find a workaround?

Any help is appreciated.

Thanks in advance
Matthias

Re: md kernel thread hung in raid1_add_disk

[NeilBrown]

[-- Attachment #1: Type: text/plain, Size: 881 bytes --]

On Tue, 10 Jun 2014 22:32:42 +0200 Matthias Eble <psychotrahe@gmail.com>
wrote:

>    * OS is Rhel6, kernel is 2.6.32-358.6.2.el6.x86_64

Presumably you are running such an ancient kernel because you have a support
contract with Redhat?  In that case it would be best to ask them.

If you have problems with a recent kernel this is certainly the best place to
ask...

NeilBrown


>    * no write intent bitmap is used
> 
> Now the questions:
>    * does anybody have an idea what the problem could be?
>    * or some ideas what I could do to narrow down problem, or find a workaround?
> 
> Any help is appreciated.
> 
> Thanks in advance
> Matthias
> --
> To unsubscribe from this list: send the line "unsubscribe linux-raid" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 828 bytes --]

Re: md kernel thread hung in raid1_add_disk

[Matthias Eble]

Hi Neil, hi list,

>>    * OS is Rhel6, kernel is 2.6.32-358.6.2.el6.x86_64
>
> Presumably you are running such an ancient kernel because you have a support
> contract with Redhat?  In that case it would be best to ask them.
>
> If you have problems with a recent kernel this is certainly the best place to
> ask...

understood. Still I'd like to post our current findings, if someone
with the same problem
will ever find this thread in the list archives:

* The Bug is very likely fixed by vanilla's
  e2d599252 md/raid1,raid10: use freeze_array in place of
raise_barrier in various places
* The commit was applied to RHEL's 2.6.32-407 kernel (RHEL 6.5; Fri Aug  2 2013)
* according to the commit message, the deadlock problem was
"particularly noticeable
  by commits 050b66152f87c7 (raid10) and 6b740b8d79252f13 (raid1)"
   * these were applied with RHEL's 2.6.32-300 (Fri Aug 17 2012)

Since we ran -358 and the call traces directed us exactly to the lines
of code that were
fixed by the freeze_array commit, we're quite confident that the
update fixed our issue.

Matthias