[linux-lvm] deadlock during lvm snapshot

[Tomaz Beltram]

Hi,

I'm doing backup of a running mongodb using LVM snapshot. Sometimes I
run into a deadlock situation and kernel reports blocked tasks for jbd2,
mongod, dmeventd and my tar doing backup.

This happens very rarely (one in a thousand) but the effect is rather
severe as mongodb stops working. I also can't remove and unmount the
snapshot. I have attached syslog of two occurrences. The stack traces of
the blocked tasks are very similar so I suspect a potential race
condition between the affected tasks.

Sep 15 17:06:53 dss2 kernel: [719277.567904] INFO: task jbd2/dm-2-8:9048
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568130] INFO: task mongod:23239
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568267] INFO: task mongod:23242
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568350] INFO: task mongod:23243
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568397] INFO: task dmeventd:12427
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568523] INFO: task
kworker/u16:2:31890 blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568713] INFO: task tar:12446
blocked for more than 120 seconds.
Sep 15 17:08:53 dss2 kernel: [719397.567614] INFO: task jbd2/dm-2-8:9048
blocked for more than 120 seconds.
Sep 15 17:08:53 dss2 kernel: [719397.567731] INFO: task mongod:23239
blocked for more than 120 seconds.
Sep 15 17:08:53 dss2 kernel: [719397.567870] INFO: task mongod:23240
blocked for more than 120 seconds.

Nov 25 17:10:56 dss2 kernel: [282360.865020] INFO: task jbd2/dm-4-8:878
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.865624] INFO: task mongod:1652
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.866279] INFO: task mongod:1655
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.866771] INFO: task mongod:1656
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.867294] INFO: task dmeventd:3504
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.867783] INFO: task
kworker/u16:2:8016 blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.868351] INFO: task tar:3560 blocked
for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.868865] INFO: task
kworker/u16:1:5561 blocked for more than 120 seconds.
Nov 25 17:12:56 dss2 kernel: [282480.868656] INFO: task jbd2/dm-4-8:878
blocked for more than 120 seconds.
Nov 25 17:12:56 dss2 kernel: [282480.869015] INFO: task mongod:1652
blocked for more than 120 seconds.

Full syslogs of two occurrences are attached.

I have Ubuntu 16.04.1 (lvm2 2.02.133-1ubuntu10) with mongod 3.2.9 on a
64bit system.

wbr Tomaz

[Zdenek Kabelac]

Post by Tomaz Beltram
Hi,
I'm doing backup of a running mongodb using LVM snapshot. Sometimes I
run into a deadlock situation and kernel reports blocked tasks for jbd2,
mongod, dmeventd and my tar doing backup.
This happens very rarely (one in a thousand) but the effect is rather
severe as mongodb stops working. I also can't remove and unmount the
snapshot. I have attached syslog of two occurrences. The stack traces of
the blocked tasks are very similar so I suspect a potential race
condition between the affected tasks.
Sep 15 17:06:53 dss2 kernel: [719277.567904] INFO: task jbd2/dm-2-8:9048
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568130] INFO: task mongod:23239
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568267] INFO: task mongod:23242
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568350] INFO: task mongod:23243
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568397] INFO: task dmeventd:12427
blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568523] INFO: task
kworker/u16:2:31890 blocked for more than 120 seconds.
Sep 15 17:06:53 dss2 kernel: [719277.568713] INFO: task tar:12446
blocked for more than 120 seconds.
Sep 15 17:08:53 dss2 kernel: [719397.567614] INFO: task jbd2/dm-2-8:9048
blocked for more than 120 seconds.
Sep 15 17:08:53 dss2 kernel: [719397.567731] INFO: task mongod:23239
blocked for more than 120 seconds.
Sep 15 17:08:53 dss2 kernel: [719397.567870] INFO: task mongod:23240
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.865020] INFO: task jbd2/dm-4-8:878
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.865624] INFO: task mongod:1652
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.866279] INFO: task mongod:1655
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.866771] INFO: task mongod:1656
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.867294] INFO: task dmeventd:3504
blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.867783] INFO: task
kworker/u16:2:8016 blocked for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.868351] INFO: task tar:3560 blocked
for more than 120 seconds.
Nov 25 17:10:56 dss2 kernel: [282360.868865] INFO: task
kworker/u16:1:5561 blocked for more than 120 seconds.
Nov 25 17:12:56 dss2 kernel: [282480.868656] INFO: task jbd2/dm-4-8:878
blocked for more than 120 seconds.
Nov 25 17:12:56 dss2 kernel: [282480.869015] INFO: task mongod:1652
blocked for more than 120 seconds.
Full syslogs of two occurrences are attached.
I have Ubuntu 16.04.1 (lvm2 2.02.133-1ubuntu10) with mongod 3.2.9 on a
64bit system.

Please switch to newer version of lvm2.

Sequence with snapshot activation had been reworked to minimize possibility
to hit this kernel race - race is still there even with the latest kernel,
but in the real world you should not have a much chance to hit it.
If you still do - please report again - we will take more closer look and your
workflow.

Regards

Zdenek

[Tomaz Beltram]

Post by Zdenek Kabelac
Please switch to newer version of lvm2.
Sequence with snapshot activation had been reworked to minimize
possibility to hit this kernel race - race is still there even with
the latest kernel, but in the real world you should not have a much chance to hit it.

Thanks for the explanation. I reported this to Ubuntu launchpad. Please
add your votes.

https://bugs.launchpad.net/ubuntu/+source/lvm2/+bug/1645636

[Zdenek Kabelac]

Post by Zdenek Kabelac
Please switch to newer version of lvm2.
Sequence with snapshot activation had been reworked to minimize possibility
to hit this kernel race - race is still there even with the latest kernel, but in the real world you should not have a much chance to hit it.

Thanks for the explanation. I reported this to Ubuntu launchpad. Please add
your votes.
https://bugs.launchpad.net/ubuntu/+source/lvm2/+bug/1645636

Yep just a minor comment - it's not 'fixed' - but the chance to hit the race
have been considerably decreased - but we still have an example where it could
be demonstrated (and it's not just 'dm' - it's more generic - see Mikulas's post)

Regards

Zdenek