Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3 /Debian 5.0 - lenny 2.6.26 kernel

Hi,

I have a box with a relatively simple setup:

sda + sdb are 1TB SATA drives attached to an Intel ICH10.
Three partitions on each drive, three md raid1s built on top of these:

md0 /
md1 swap
md2 LVM PV


During resync about a week ago, processes seemed to deadlock on I/O, the
machine was still alive but with a load of 100+. A USB drive happened
to be mounted, so I managed to save /var/log/kern.log At the time of
the problem, the monthly RAID check was in progress. On reboot, a
rebuild commenced, and the same deadlock seemed to occur between roughly
2 minutes and 15 minutes after boot.

At this point, the server was running on a Dell PE R300 (12G RAM,
quad-core), with an LSI SAS controller and 2x 500G SATA drives. I
shifted all the data onto a spare box (Dell PE R210, ICH10R, 1x1TB
drive, 8G RAM, quad-core+HT), with only a single drive, so I created the
md RAID1s with just a single drive in each. The original box was put
offline with the idea of me debugging it "soon".

This morning, I added in a second 1TB drive, and during the resync
(approx 1 hour in), the deadlock up occurred again. The resync had
stopped, and any attempt to write to md2 would deadlock the process in
question. I think it was doing an rsnaphot backup to a USB drive at the
time the initial problem occurred - this creates an LVM snapshot device
on top of md2 for the duration of the backup for each filesystem backed
up (there are two at the moment), and I suppose this results in lots of
read-copy-update operations - the mounting of the snapshots shows up in
the logs as the fs-mounts, and subsequent orphan_cleanups. As the
snapshot survives the reboot, I assume this is what triggers the
subsequent lockup after the machine has rebooted.

I got a couple of 'echo w > /proc/sysrq-trigger' sets of output this
time... Edited copies of kern.log are attached - looks like it's
barrier related. I'd guess the combination of the LVM CoW snapshot, and
the RAID resync are tickling this bug.


Any thoughts? Maybe this is related to Debian bug #584881 -
http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=584881

.... since the kernel is essentially the same.

I can do some debugging on this out-of-office-hours, or can probably
resurrect the original hardware to debug that too.

Logs are here:

http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/

I think vger binned the first version of this email (with the logs
attached) - so apologies if you've ended up with two copies of this email...

Tim.


--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309



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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On Fri, 17 Sep 2010 15:53:55 +0100
Tim Small wrote:

> Hi,
>
> I have a box with a relatively simple setup:
>
> sda + sdb are 1TB SATA drives attached to an Intel ICH10.
> Three partitions on each drive, three md raid1s built on top of these:
>
> md0 /
> md1 swap
> md2 LVM PV
>
>
> During resync about a week ago, processes seemed to deadlock on I/O, the
> machine was still alive but with a load of 100+. A USB drive happened
> to be mounted, so I managed to save /var/log/kern.log At the time of
> the problem, the monthly RAID check was in progress. On reboot, a
> rebuild commenced, and the same deadlock seemed to occur between roughly
> 2 minutes and 15 minutes after boot.
>
> At this point, the server was running on a Dell PE R300 (12G RAM,
> quad-core), with an LSI SAS controller and 2x 500G SATA drives. I
> shifted all the data onto a spare box (Dell PE R210, ICH10R, 1x1TB
> drive, 8G RAM, quad-core+HT), with only a single drive, so I created the
> md RAID1s with just a single drive in each. The original box was put
> offline with the idea of me debugging it "soon".
>
> This morning, I added in a second 1TB drive, and during the resync
> (approx 1 hour in), the deadlock up occurred again. The resync had
> stopped, and any attempt to write to md2 would deadlock the process in
> question. I think it was doing an rsnaphot backup to a USB drive at the
> time the initial problem occurred - this creates an LVM snapshot device
> on top of md2 for the duration of the backup for each filesystem backed
> up (there are two at the moment), and I suppose this results in lots of
> read-copy-update operations - the mounting of the snapshots shows up in
> the logs as the fs-mounts, and subsequent orphan_cleanups. As the
> snapshot survives the reboot, I assume this is what triggers the
> subsequent lockup after the machine has rebooted.
>
> I got a couple of 'echo w > /proc/sysrq-trigger' sets of output this
> time... Edited copies of kern.log are attached - looks like it's
> barrier related. I'd guess the combination of the LVM CoW snapshot, and
> the RAID resync are tickling this bug.
>
>
> Any thoughts? Maybe this is related to Debian bug #584881 -
> http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=584881
>
> ... since the kernel is essentially the same.
>
> I can do some debugging on this out-of-office-hours, or can probably
> resurrect the original hardware to debug that too.
>
> Logs are here:
>
> http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/
>
> I think vger binned the first version of this email (with the logs
> attached) - so apologies if you've ended up with two copies of this email...
>
> Tim.
>
>

Hi Tim,

unfortunately I need more that just the set of blocked tasks to diagnose the
problem. If you could get the result of
echo t > /proc/sysrq-trigger
that might help a lot. This might be bigger than the dmesg buffer, so you
might try booting with 'log_buf_len=1M' just to be sure.

It looks a bit like a bug that was fixed in prior to the release of 2.6.26,
but as you are running 2.6.26, it cannot be that..

NeilBrown
--
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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

> unfortunately I need more that just the set of blocked tasks to diagnose the
> problem. If you could get the result of
> echo t > /proc/sysrq-trigger
> that might help a lot. This might be bigger than the dmesg buffer, so you
> might try booting with 'log_buf_len=1M' just to be sure.
>


Hi Neil,

Thanks for the feedback. I've stuck the sysrq-t output here:

http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/i odeadlock-sysrq-t.txt

.... this was soon after the io to md2 stopped - md0 seems fine...

oldshoreham:~# cat /proc/mdstat
Personalities : [raid1]
md2 : active raid1 sda6[0] sdb6[1]
404600128 blocks [2/2] [UU]
[>....................] resync = 0.1% (437056/404600128)
finish=343321.2min speed=19K/sec


.... I also tried an older Debian 5.0.x kernel from Mar 2009, which is a
less-patched 2.6.26, and got the same results. 2.6.32 hasn't deadlocked
after 10 minutes (2.6.26 usually does within a minute of boot-up), so
I'll leave it re-syncing overnight...

Cheers!

Tim.

--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

Tim Small wrote:
> http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/i odeadlock-sysrq-t.txt
>
> ... this was soon after the io to md2 stopped - md0 seems fine...
>
> oldshoreham:~# cat /proc/mdstat
> Personalities : [raid1]
> md2 : active raid1 sda6[0] sdb6[1]
> 404600128 blocks [2/2] [UU]
> [>....................] resync = 0.1% (437056/404600128)
> finish=343321.2min speed=19K/sec
>
>
> ... I also tried an older Debian 5.0.x kernel from Mar 2009, which is a
> less-patched 2.6.26, and got the same results. 2.6.32 hasn't deadlocked
> after 10 minutes (2.6.26 usually does within a minute of boot-up), so
> I'll leave it re-syncing overnight...
>

2.6.32 resynced to completion, but if possible I'd really like to get
2.6.26 running on this box, as it uses openvz, and the 2.6.32 openvz
patches are still pretty green, I think. Is their anything in the
sysrq-t output in that link of any use? Are there any patches I should
try, or would it be better to start bisecting between 2.6.26 and 2.6.32
(assuming I can reproduce the problem without the load pattern which
openvz is producing - which I probably can).

Cheers,

Tim.


--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On Mon, 20 Sep 2010 20:59:29 +0100
Tim Small wrote:

>
> > unfortunately I need more that just the set of blocked tasks to diagnose the
> > problem. If you could get the result of
> > echo t > /proc/sysrq-trigger
> > that might help a lot. This might be bigger than the dmesg buffer, so you
> > might try booting with 'log_buf_len=1M' just to be sure.
> >
>
>
> Hi Neil,
>
> Thanks for the feedback. I've stuck the sysrq-t output here:
>
> http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/i odeadlock-sysrq-t.txt

Unfortunately this log is not complete. As I suggested, you need to boot
with a larger log_buf_len (you seem to have 128K) to get able to capture the
whole thing.

NeilBrown


>
> ... this was soon after the io to md2 stopped - md0 seems fine...
>
> oldshoreham:~# cat /proc/mdstat
> Personalities : [raid1]
> md2 : active raid1 sda6[0] sdb6[1]
> 404600128 blocks [2/2] [UU]
> [>....................] resync = 0.1% (437056/404600128)
> finish=343321.2min speed=19K/sec
>
>
> ... I also tried an older Debian 5.0.x kernel from Mar 2009, which is a
> less-patched 2.6.26, and got the same results. 2.6.32 hasn't deadlocked
> after 10 minutes (2.6.26 usually does within a minute of boot-up), so
> I'll leave it re-syncing overnight...
>
> Cheers!
>
> Tim.
>

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On Tue, 21 Sep 2010 22:02:25 +0100
Tim Small wrote:

> Tim Small wrote:
> > http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/i odeadlock-sysrq-t.txt
> >
> > ... this was soon after the io to md2 stopped - md0 seems fine...
> >
> > oldshoreham:~# cat /proc/mdstat
> > Personalities : [raid1]
> > md2 : active raid1 sda6[0] sdb6[1]
> > 404600128 blocks [2/2] [UU]
> > [>....................] resync = 0.1% (437056/404600128)
> > finish=343321.2min speed=19K/sec
> >
> >
> > ... I also tried an older Debian 5.0.x kernel from Mar 2009, which is a
> > less-patched 2.6.26, and got the same results. 2.6.32 hasn't deadlocked
> > after 10 minutes (2.6.26 usually does within a minute of boot-up), so
> > I'll leave it re-syncing overnight...
> >
>
> 2.6.32 resynced to completion, but if possible I'd really like to get
> 2.6.26 running on this box, as it uses openvz, and the 2.6.32 openvz
> patches are still pretty green, I think. Is their anything in the
> sysrq-t output in that link of any use? Are there any patches I should
> try, or would it be better to start bisecting between 2.6.26 and 2.6.32
> (assuming I can reproduce the problem without the load pattern which
> openvz is producing - which I probably can).
>
> Cheers,
>
> Tim.
>
>

It is odd that 2.6.32 works and 2.6.26 doesn't as I cannot find any change
between the two that could be related.
There were some deadlock issues if a read-error was detected during resync
but I don't think you are getting read errors are you?

A bisect would of course be easier for me, though not particularly easy for
you....

Maybe if you can get me a full sysrq-T list that might help.

NeilBrown

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On 21/09/10 23:30, Neil Brown wrote:
>
> Maybe if you can get me a full sysrq-T list that might help.
>

Just thought I'd follow up on this - it's being a right bastard...

sysrq-T and a 1M buffer works fine when the box isn't in the IO-hung
state, but makes it crash immediately when it is. sysrq-T without the
1M buffer works fine.

I tried getting the console output using a serial console (+IPMI over
LAN), but the box doesn't seem to work correctly with serial console
(output is fine til part-way through the boot process, thereafter is
stops, and anything to /dev/console doesn't appear on the serial port,
although I/O to /dev/ttyS1 works fine).

OK, so I'll use netconsole - nope, netconsole doesn't work on this box
either - all I see on the remote machine is a perfectly fine UDP header,
but the body of the packet is all 0x0s.

I'll try and see what it's doing when I'm physically in front of a VGA
console at some point.

Thanks,

Tim.

--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

Sorry, hit send too soon...


On 21/09/10 23:30, Neil Brown wrote:
> It is odd that 2.6.32 works and 2.6.26 doesn't as I cannot find any change
> between the two that could be related.
> There were some deadlock issues if a read-error was detected during resync
> but I don't think you are getting read errors are you?
>

Nope, no read errors.

> A bisect would of course be easier for me, though not particularly easy for
> you....
>

I haven't as-yet been able to reproduce the issue without running OpenVZ
on the box - I suppose the two possibilities are:

1. The bug is in the OpenVZ patches (seems unlikely given the nature of
the hang, but possible I suppose).
2. The bug is only triggered by the workload which the VZ container is
producing

.... so without this, a bisect is a non-starter.

Grrr.

Tim.

--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3 /Debian 5.0 - lenny 2.6.26 kernel

On Tue, Oct 12, 2010 at 6:06 PM, Tim Small wrote:
> Sorry, hit send too soon...
>
>
> On 21/09/10 23:30, Neil Brown wrote:
>>
>> It is odd that 2.6.32 works and 2.6.26 doesn't as I cannot find any =
change
>> between the two that could be related.
>> There were some deadlock issues if a read-error was detected during =
resync
>> but I don't think you are getting read errors are you?
>>
>
> Nope, no read errors.
>
>> A bisect would of course be easier for me, though not particularly e=
asy
>> for
>> you....
>>
>
> I haven't as-yet been able to reproduce the issue without running Ope=
nVZ on
> the box - I suppose the two possibilities are:
>
> 1. The bug is in the OpenVZ patches (seems unlikely given the nature =
of the
> hang, but possible I suppose).
Just in case you don't know 2.6.26 branch is "frozen, not maintained"
- http://wiki.openvz.org/Download/kernel/2.6.26/2.6.26-gogol.1
The only stable for now is 2.6.18 & 2.6.9 , any other is
outdated/testing http://wiki.openvz.org/Download/kernel . Ongoin start
is 2.6.32 as being new RHEL6 kernel. So i'd suggest you to go down to
18 or take .32 from backports.

> 2. The bug is only triggered by the workload which the VZ container i=
s
> producing
>
> ... so without this, a bisect is a non-starter.
>
> Grrr.
>
> Tim.
>
> --
> South East Open Source Solutions Limited
> Registered in England and Wales with company number 06134732.
> Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
> VAT number: 900 6633 53 =A0http://seoss.co.uk/ +44-(0)1273-808309
>
> --
> 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 =A0http://vger.kernel.org/majordomo-info.html
>



--=20
Best regards,
[COOLCOLD-RIPN]
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" i=
n
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

Hi,

On 12/10/10 17:48, CoolCold wrote:
> Just in case you don't know 2.6.26 branch is "frozen, not maintained"
> - http://wiki.openvz.org/Download/kernel/2.6.26/2.6.26-gogol.1
>

Yep, but that's by OpenVZ, I'm using the Debian kernel, and 2.6.26 is
Debian stable, and so supported by the Debian kernel team....

> The only stable for now is 2.6.18& 2.6.9 , any other is
> outdated/testing http://wiki.openvz.org/Download/kernel . Ongoin start
> is 2.6.32 as being new RHEL6 kernel. So i'd suggest you to go down to
> .18 or take .32 from backports.
>

Once RHEL6 and/or Debian6.0 has been out for a few months, I'll probably
switch to 2.6.32, but I don't feel sufficiently confident to do that yet
(not for OpenVZ boxes anyway - OpenVZ+2.6.32 just hasn't had enough
testing-time yet for production IMO) - I also look after plenty of
non-openvz 2.6.26 Debian 5.0 boxes, and if this bug is md+lvm+ext3
(which in my semi-educated opinion looks most likely, partly because
there have been some similar looking deadlocks reported on non-OpenVZ
Debian 5.0 systems), then it'd be preferable to track-down the cause of
this and get it fixed....

Cheers,

Tim.

--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3 /Debian 5.0 - lenny 2.6.26 kernel

On Wed, Oct 13, 2010 at 12:51 PM, Tim Small wrote:
> Hi,
>
> On 12/10/10 17:48, CoolCold wrote:
>>
>> Just in case you don't know 2.6.26 branch is "frozen, not maintained=
"
>> - http://wiki.openvz.org/Download/kernel/2.6.26/2.6.26-gogol.1
>>
>
> Yep, but that's by OpenVZ, I'm using the Debian kernel, and 2.6.26 is=
Debian
> stable, and so supported by the Debian kernel team....
well..at least it should

>
>> The only stable for now is 2.6.18& =A02.6.9 , any other is
>> outdated/testing http://wiki.openvz.org/Download/kernel . Ongoin sta=
rt
>> is 2.6.32 as being new RHEL6 kernel. So i'd suggest you to go down t=
o
>> .18 or take .32 from backports.
>>
>
> Once RHEL6 and/or Debian6.0 has been out for a few months, I'll proba=
bly
> switch to 2.6.32, but I don't feel sufficiently confident to do that =
yet
> (not for OpenVZ boxes anyway - OpenVZ+2.6.32 just hasn't had enough
> testing-time yet for production IMO) - I also look after plenty of
> non-openvz 2.6.26 Debian 5.0 boxes, and if this bug is md+lvm+ext3 (w=
hich in
> my semi-educated opinion looks most likely, partly because there have=
been
> some similar looking deadlocks reported on non-OpenVZ Debian 5.0 syst=
ems),
> then it'd be preferable to track-down the cause of this and get it fi=
xed....
I got your point, good luck! As for me, i've switched to 2.6.32 from
backports, but still has 2.6.18 on openvz boxes.

>
> Cheers,
>
> Tim.
>
> --
> South East Open Source Solutions Limited
> Registered in England and Wales with company number 06134732.
> Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
> VAT number: 900 6633 53 =A0http://seoss.co.uk/ +44-(0)1273-808309
>
>



--=20
Best regards,
[COOLCOLD-RIPN]
--
To unsubscribe from this list: send the line "unsubscribe linux-raid" i=
n
the body of a message to majordomo@vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

Neil Brown wrote:
> Maybe if you can get me a full sysrq-T list that might help.
>

At last, yes, courtesy of Ben Hutchings...

http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/d eadlock-openvz-2.6.26-Debian5.txt

.... any use?

Cheers,

Tim.

--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On Mon, 18 Oct 2010 19:52:36 +0100
Tim Small wrote:

> Neil Brown wrote:
> > Maybe if you can get me a full sysrq-T list that might help.
> >
>
> At last, yes, courtesy of Ben Hutchings...
>
> http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/d eadlock-openvz-2.6.26-Debian5.txt

Thanks!

>
> ... any use?

Only in as much as that it excludes some possible avenues of investigation,
which has some value.

But I'm out of ideas. I cannot think of anything that could keep
->nr_pending or ->barrier elevated such that raise_barrier would
block for a long time.

Maybe you could try adding printks to print
conf->{barrier,nr_pending,nr_waiting,nr_queued}
just before and after the second wait_event_lock_irq in raise_barrier().

That might help...

NeilBrown




>
> Cheers,
>
> Tim.
>

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On 19/10/10 07:16, Neil Brown wrote:
>
>> ... any use?
>>
> Only in as much as that it excludes some possible avenues of investigation,
> which has some value.
>
> But I'm out of ideas. I cannot think of anything that could keep
> ->nr_pending or ->barrier elevated such that raise_barrier would
> block for a long time.
>
> Maybe you could try adding printks to print
> conf->{barrier,nr_pending,nr_waiting,nr_queued}
> just before and after the second wait_event_lock_irq in raise_barrier().
>
>

run1:

[ 130.168389] Pre wait barrier: 1, pend: 30, wait: 0, queued: 0
[ 130.209456] Post wait barrier: 1, pend: 0, wait: 4, queued: 0
[ 130.228814] Pre wait barrier: 1, pend: 82, wait: 0, queued: 0
[ 130.267475] Post wait barrier: 1, pend: 0, wait: 5, queued: 0
[ 130.290556] Pre wait barrier: 1, pend: 57, wait: 0, queued: 0
[ 130.348259] Post wait barrier: 1, pend: 0, wait: 4, queued: 0
[ 130.376040] Pre wait barrier: 1, pend: 42, wait: 0, queued: 0
[ 130.414694] Post wait barrier: 1, pend: 0, wait: 5, queued: 0
[ 130.438693] Pre wait barrier: 1, pend: 46, wait: 0, queued: 0
[ 130.490211] Post wait barrier: 1, pend: 0, wait: 4, queued: 0
[ 130.510371] Pre wait barrier: 1, pend: 57, wait: 0, queued: 0
[ 130.551321] Post wait barrier: 1, pend: 0, wait: 4, queued: 0
[ 130.564969] Pre wait barrier: 1, pend: 16, wait: 0, queued: 0


run2:

[ 155.947067] Pre wait barrier: 1, pend: 8, wait: 0, queued: 0
[ 156.000027] Post wait barrier: 1, pend: 0, wait: 5, queued: 0
[ 156.011959] Pre wait barrier: 1, pend: 13, wait: 0, queued: 0
[ 156.059050] Post wait barrier: 1, pend: 0, wait: 5, queued: 0
[ 156.076866] Pre wait barrier: 1, pend: 13, wait: 0, queued: 0
[ 156.108234] Post wait barrier: 1, pend: 0, wait: 4, queued: 0
[ 156.118437] Pre wait barrier: 1, pend: 93, wait: 0, queued: 0
[ 156.140136] Post wait barrier: 1, pend: 0, wait: 4, queued: 0
[ 156.140506] Pre wait barrier: 1, pend: 4, wait: 0, queued: 0
[ 156.157644] Post wait barrier: 1, pend: 0, wait: 3, queued: 0
[ 156.260883] Pre wait barrier: 1, pend: 51, wait: 0, queued: 0


run3:

[ 113.862479] Pre wait barrier: 1, pend: 6, wait: 0, queued: 0
[ 113.892445] Post wait barrier: 1, pend: 0, wait: 2, queued: 0
[ 113.912622] Pre wait barrier: 1, pend: 6, wait: 0, queued: 0
[ 113.921417] Post wait barrier: 1, pend: 0, wait: 2, queued: 0
[ 113.947774] Pre wait barrier: 1, pend: 22, wait: 0, queued: 0
[ 113.970322] Post wait barrier: 1, pend: 0, wait: 2, queued: 0
[ 114.024782] Pre wait barrier: 1, pend: 2, wait: 0, queued: 0
[ 114.039825] Post wait barrier: 1, pend: 0, wait: 2, queued: 0
[ 114.055788] Pre wait barrier: 1, pend: 33, wait: 0, queued: 0
[ 114.071059] Post wait barrier: 1, pend: 0, wait: 2, queued: 0
[ 114.076240] Pre wait barrier: 1, pend: 5, wait: 0, queued: 0
[ 114.103378] Post wait barrier: 1, pend: 0, wait: 2, queued: 0
[ 114.118969] Pre wait barrier: 1, pend: 27, wait: 0, queued: 0



md2 : active raid1 sda6[0] sdb6[1]
404600128 blocks [2/2] [UU]
[>....................] resync = 0.5% (2246720/404600128)
finish=256573.1min speed=26K/sec




I then stuck a few more printks in both wait_event_lock_irq and
raise_barrier,

static void raise_barrier(conf_t *conf)
{
spin_lock_irq(&conf->resync_lock);

/* Wait until no block IO is waiting */
printk(KERN_DEBUG "%i: Pre wait until no IO waiting: %d, pend:
%d, wait: %d, queued: %d\n", current->pid, conf->barrier,
conf->nr_pending, conf->nr_waiting, conf->nr_queued);
wait_event_lock_irq(conf->wait_barrier, !conf->nr_waiting,
conf->resync_lock,
raid1_unplug(conf->mddev->queue));
printk(KERN_DEBUG "%i: Post wait until no IO waiting: %d, pend:
%d, wait: %d, queued: %d\n", current->pid, conf->barrier,
conf->nr_pending, conf->nr_waiting, conf->nr_queued);

/* block any new IO from starting */
conf->barrier++;

/* No wait for all pending IO to complete */
printk(KERN_DEBUG "%i: Pre wait pending to complete: %d, pend:
%d, wait: %d, queued: %d\n", current->pid, conf->barrier,
conf->nr_pending, conf->nr_waiting, conf->nr_queued);
wait_event_lock_irq(conf->wait_barrier,
!conf->nr_pending && conf->barrier <
RESYNC_DEPTH,
conf->resync_lock,
raid1_unplug(conf->mddev->queue));
printk(KERN_DEBUG "%i: Post wait pending to complete: %d, pend:
%d, wait: %d, queued: %d\n", current->pid, conf->barrier,
conf->nr_pending, conf->nr_waiting, conf->nr_queued);

spin_unlock_irq(&conf->resync_lock);
}

#define __wait_event_lock_irq(wq, condition, lock, cmd) \
do { \
wait_queue_t __wait; \
int ourpid; \
ourpid = current->pid; \
printk(KERN_DEBUG "%i is pid in wait_event_lock_irq.\n",
ourpid); \
init_waitqueue_entry(&__wait, current); \
\
add_wait_queue(&wq, &__wait); \
for (;;) { \
set_current_state(TASK_UNINTERRUPTIBLE); \
if (condition) \
break; \
spin_unlock_irq(&lock); \
printk(KERN_DEBUG "%i Calling cmd\n",
ourpid); \
cmd; \
printk(KERN_DEBUG "%i Returned from cmd\n",
ourpid); \
schedule(); \
spin_lock_irq(&lock); \
} \
if (ourpid != (current->pid)) \
printk(KERN_DEBUG "PID changed! Old: %i, new: %i\n",
ourpid, current->pid); \
current->state = TASK_RUNNING; \
remove_wait_queue(&wq, &__wait); \
} while (0)




and got this:



[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410 Calling cmd
[ 112.240838] 2410 Returned from cmd
[ 112.240838] 2410: Post wait until no IO waiting: 0, pend: 448, wait:
0, queued: 0
[ 112.240838] 2410: Pre wait pending to complete: 1, pend: 448, wait:
0, queued: 0
[ 112.240838] 2410 is pid in wait_event_lock_irq.
[ 112.240838] 2410 Calling cmd
[ 112.243066] 5950 is pid in wait_event_lock_irq.
[ 112.243066] 5950 Calling cmd
[ 112.243066] 5950 Returned from cmd
[ 112.240838] 2410 Returned from cmd
[ 112.243066] 2430 is pid in wait_event_lock_irq.
[ 112.243066] 2430 Calling cmd
[ 112.243066] 2430 Returned from cmd
[ 112.257942] 2430 Calling cmd
[ 112.258447] 2410 Calling cmd
[ 112.258447] 5950 Calling cmd
[ 112.258453] 2410 Returned from cmd
[ 112.258447] 5950 Returned from cmd
[ 112.257942] 2430 Returned from cmd
[ 112.258447] 5745 is pid in wait_event_lock_irq.
[ 112.258451] 5745 Calling cmd
[ 112.258454] 5745 Returned from cmd
[ 112.262495] 5745 Calling cmd
[ 112.262495] 2430 Calling cmd
[ 112.262495] 2410 Calling cmd
[ 112.262495] 5745 Returned from cmd
[ 112.262495] 2430 Returned from cmd
[ 112.262495] 2410 Returned from cmd
[ 112.262495] 5950 Calling cmd
[ 112.262495] 5950 Returned from cmd
[ 112.263422] 2430 Calling cmd
[ 112.263422] 2430 Returned from cmd
[ 112.264770] 2410 Calling cmd
[ 112.264772] 2410 Returned from cmd






--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On 19/10/10 17:24, Tim Small wrote:
>
> and got this:
>

.... sorry meant to say, got this as the last partial call through
raise_barrier, but I haven't been able to draw any further conclusions.
Got to head off now for the day, so I thought I'd punt this out and have
another stare at the code tomorrow.

Cheers,

Tim.

--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

Sprinkled a few more printks....

http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/d mesg-deadlock-instrumented.txt

Cheers,

Tim.


--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On 19/10/10 20:29, Tim Small wrote:
> Sprinkled a few more printks....
>
> http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/d mesg-deadlock-instrumented.txt
>

It seems that when the system is hung, conf->nr_pending gets stuck with
a value of 2. The resync task ends up stuck in the second
wait_event_lock_irq within raise barrier, and everything else gets stuck
in the first wait_event_lock_irq when waiting for that to complete..

So my assumption is that some IOs either get stuck incomplete, or take a
path through the code such that they complete without calling allow_barrier.

Does that make any sense?

Cheers,

Tim.


--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On Wed, 20 Oct 2010 21:34:47 +0100
Tim Small wrote:

> On 19/10/10 20:29, Tim Small wrote:
> > Sprinkled a few more printks....
> >
> > http://buttersideup.com/files/md-raid1-lockup-lvm-snapshot/d mesg-deadlock-instrumented.txt
> >
>
> It seems that when the system is hung, conf->nr_pending gets stuck with
> a value of 2. The resync task ends up stuck in the second
> wait_event_lock_irq within raise barrier, and everything else gets stuck
> in the first wait_event_lock_irq when waiting for that to complete..
>
> So my assumption is that some IOs either get stuck incomplete, or take a
> path through the code such that they complete without calling allow_barrier.
>
> Does that make any sense?
>

Yes, it is pretty much the same place that my thinking has reached.

I am quite confident that IO requests cannot complete without calling
allow_barrier - if that were possible I think we would be seeing a lot more
problems, and in any case it is a fairly easy code path to verify by
inspection.

So the mostly likely avenue or exploration is that the IO's get stuck
somewhere. But where?

They could get stuck in the device queue while the queue is plugged. But
queues are meant to auto-unplug after 3msec. And in any case the
raid1_unplug call in wait_event_lock_irq will make sure everything is
unplugged.

If there was an error (which according to the logs there wasn't) the request
could be stuck in the retry queue, but raid1d will take things off that queue
and handle them. raid1_unplug wakes up raid1d, and the stack traces show
that raid1d is simply waiting to be woken, it isn't blocking on anything.
I guess there could be an attempt to do a barrier write that failed and
needed to be retried. Maybe you could add a printk if RIBIO_BarrierRetry
ever gets set. I don't expect it tell us much though.

They could be in pending_bio_list, but that is flushed by raid1d too.


Maybe you could add a could of global atomic variables, one for reads and one
for writes.
Then on each call to generic_make_request in:
flush_pending_writes, make_request, raid1d
increment one or the other depending on whether it is a read or a write.
Then in raid1_end_read_request and raid1_end_write_request decrement them
appropriately.

Then in raid1_unplug (which is called just before the schedule in the
event_wait code) print out these two numbers.
Possibly also print something when you decrement them if they become zero.

That would tell us if the requests were stuck in the underlying devices, or
if they were stuck in raid1 somewhere.

Maybe you could also check that the retry list and the pending list are empty
and print that status somewhere suitable...

NeilBrown
--
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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On 10/21/10 00:04, Neil Brown wrote:
>
> Maybe you could add a could of global atomic variables, one for reads and one
> for writes.
> Then on each call to generic_make_request in:
> flush_pending_writes, make_request, raid1d
> increment one or the other depending on whether it is a read or a write.
> Then in raid1_end_read_request and raid1_end_write_request decrement them
> appropriately.
>


Ended up with runs like this:

[ 464.244109] 0 Obtaining resync_lock and disabling interrupts for
allow_barrier
[ 464.244109] conf nr_pending is 5
[ 464.244109] 0 Released resync_lock and enabling interrupts for
allow_barrier
[ 464.244109] 2216: Post wait until no IO waiting - barrier: 0, pend:
5, wait: 0, queued: 0
[ 464.244113] 2216: Pre wait pending to complete - barrier: 1, pend: 5,
wait: 0, queued: 0
[ 464.244116] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 464.244469] 5113 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.244469] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
allow_barrier
[ 464.244469] conf nr_pending is 4
[ 464.244469] 5127 Released resync_lock and enabling interrupts for
allow_barrier
[ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
allow_barrier
[ 464.246176] In raid1_unplug debug read count: 4 write count: 0
conf->nr_queued: 0
[ 464.244469] conf nr_pending is 3
[ 464.244469] 5127 Released resync_lock and enabling interrupts for
allow_barrier
[ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
allow_barrier
[ 464.244469] conf nr_pending is 2
[ 464.244469] 5127 Released resync_lock and enabling interrupts for
allow_barrier
[ 464.246176] In raid1_unplug debug read count: 2 write count: 0
conf->nr_queued: 0
[ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
allow_barrier
[ 464.244469] conf nr_pending is 1
[ 464.244469] 5127 Released resync_lock and enabling interrupts for
allow_barrier
[ 464.246176] In raid1_unplug debug read count: 1 write count: 0
conf->nr_queued: 0
[ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
allow_barrier
[ 464.244469] conf nr_pending is 0
[ 464.244469] 5127 Released resync_lock and enabling interrupts for
allow_barrier
[ 464.244469] In raid1_unplug debug read count: 0 write count: 0
conf->nr_queued: 0
[ 464.246176] 2216: Post wait pending to complete - barrier: 1, pend:
0, wait: 1, queued: 0
[ 464.246176] In raid1_unplug debug read count: 0 write count: 0
conf->nr_queued: 0
[ 464.246176] 2216: Pre wait until no IO waiting - barrier: 1, pend: 0,
wait: 1, queued: 0
[ 464.246176] In raid1_unplug debug read count: 0 write count: 0
conf->nr_queued: 0
[ 464.246176] 5118 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.246176] In raid1_unplug debug read count: 0 write count: 0
conf->nr_queued: 0
[ 464.246633] In raid1_unplug debug read count: 0 write count: 0
conf->nr_queued: 1
[ 464.244469] In raid1_unplug debug read count: 0 write count: 0
conf->nr_queued: 0
[ 464.246176] In raid1_unplug debug read count: 0 write count: 0
conf->nr_queued: 0
[ 464.246990] 5118 Released resync_lock and enabling interrupts for
wait_barrier
[ 464.244469] 5113 Released resync_lock and enabling interrupts for
wait_barrier
[ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.246990] 5118 Released resync_lock and enabling interrupts for
wait_barrier
[ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.246990] 5118 Released resync_lock and enabling interrupts for
wait_barrier
[ 464.244469] In raid1_unplug debug read count: 3 write count: 0
conf->nr_queued: 0
[ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.246990] 5118 Released resync_lock and enabling interrupts for
wait_barrier
[ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.246990] 5118 Released resync_lock and enabling interrupts for
wait_barrier
[ 464.246176] 2216: Post wait until no IO waiting - barrier: 0, pend:
6, wait: 0, queued: 0
[ 464.246176] 2216: Pre wait pending to complete - barrier: 1, pend: 6,
wait: 0, queued: 0
[ 464.246176] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.246990] In raid1_unplug debug read count: 6 write count: 0
conf->nr_queued: 0
[ 464.247091] 0 Obtaining resync_lock and disabling interrupts for
allow_barrier
[ 464.247091] conf nr_pending is 5
[ 464.247091] 0 Released resync_lock and enabling interrupts for
allow_barrier
[ 464.247091] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 464.244469] 5113 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.246176] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 464.244469] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 464.328828] 3639 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 464.328834] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 466.065137] 2479 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 466.065137] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 467.051970] 2478 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 467.051975] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 471.293667] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 471.525081] 220 Obtaining resync_lock and disabling interrupts for
wait_barrier
[ 471.525081] In raid1_unplug debug read count: 5 write count: 0
conf->nr_queued: 0
[ 505.308962] 2216 WARNING, schedule_timeout timed out for raise_barrier
[ 505.308076] 5118 WARNING, schedule_timeout timed out for wait_barrier


.... so does that mean that there are are read requests going awol in the
block layer?

If so, then the circumstantial evidence from when the lockups occur make
it look to me like this is probably an OpenVZ bug, but I'll try and do
some more digging tomorrow...

Does that make sense?

Cheers,

Tim.

--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On Thu, 18 Nov 2010 18:04:25 +0000
Tim Small wrote:

> On 10/21/10 00:04, Neil Brown wrote:
> >
> > Maybe you could add a could of global atomic variables, one for reads and one
> > for writes.
> > Then on each call to generic_make_request in:
> > flush_pending_writes, make_request, raid1d
> > increment one or the other depending on whether it is a read or a write.
> > Then in raid1_end_read_request and raid1_end_write_request decrement them
> > appropriately.
> >
>
>
> Ended up with runs like this:
>
> [ 464.244109] 0 Obtaining resync_lock and disabling interrupts for
> allow_barrier
> [ 464.244109] conf nr_pending is 5
> [ 464.244109] 0 Released resync_lock and enabling interrupts for
> allow_barrier
> [ 464.244109] 2216: Post wait until no IO waiting - barrier: 0, pend:
> 5, wait: 0, queued: 0
> [ 464.244113] 2216: Pre wait pending to complete - barrier: 1, pend: 5,
> wait: 0, queued: 0
> [ 464.244116] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 464.244469] 5113 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.244469] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
> allow_barrier
> [ 464.244469] conf nr_pending is 4
> [ 464.244469] 5127 Released resync_lock and enabling interrupts for
> allow_barrier
> [ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
> allow_barrier
> [ 464.246176] In raid1_unplug debug read count: 4 write count: 0
> conf->nr_queued: 0
> [ 464.244469] conf nr_pending is 3
> [ 464.244469] 5127 Released resync_lock and enabling interrupts for
> allow_barrier
> [ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
> allow_barrier
> [ 464.244469] conf nr_pending is 2
> [ 464.244469] 5127 Released resync_lock and enabling interrupts for
> allow_barrier
> [ 464.246176] In raid1_unplug debug read count: 2 write count: 0
> conf->nr_queued: 0
> [ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
> allow_barrier
> [ 464.244469] conf nr_pending is 1
> [ 464.244469] 5127 Released resync_lock and enabling interrupts for
> allow_barrier
> [ 464.246176] In raid1_unplug debug read count: 1 write count: 0
> conf->nr_queued: 0
> [ 464.244469] 5127 Obtaining resync_lock and disabling interrupts for
> allow_barrier
> [ 464.244469] conf nr_pending is 0
> [ 464.244469] 5127 Released resync_lock and enabling interrupts for
> allow_barrier
> [ 464.244469] In raid1_unplug debug read count: 0 write count: 0
> conf->nr_queued: 0
> [ 464.246176] 2216: Post wait pending to complete - barrier: 1, pend:
> 0, wait: 1, queued: 0
> [ 464.246176] In raid1_unplug debug read count: 0 write count: 0
> conf->nr_queued: 0
> [ 464.246176] 2216: Pre wait until no IO waiting - barrier: 1, pend: 0,
> wait: 1, queued: 0
> [ 464.246176] In raid1_unplug debug read count: 0 write count: 0
> conf->nr_queued: 0
> [ 464.246176] 5118 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.246176] In raid1_unplug debug read count: 0 write count: 0
> conf->nr_queued: 0
> [ 464.246633] In raid1_unplug debug read count: 0 write count: 0
> conf->nr_queued: 1
> [ 464.244469] In raid1_unplug debug read count: 0 write count: 0
> conf->nr_queued: 0
> [ 464.246176] In raid1_unplug debug read count: 0 write count: 0
> conf->nr_queued: 0
> [ 464.246990] 5118 Released resync_lock and enabling interrupts for
> wait_barrier
> [ 464.244469] 5113 Released resync_lock and enabling interrupts for
> wait_barrier
> [ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.246990] 5118 Released resync_lock and enabling interrupts for
> wait_barrier
> [ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.246990] 5118 Released resync_lock and enabling interrupts for
> wait_barrier
> [ 464.244469] In raid1_unplug debug read count: 3 write count: 0
> conf->nr_queued: 0
> [ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.246990] 5118 Released resync_lock and enabling interrupts for
> wait_barrier
> [ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.246990] 5118 Released resync_lock and enabling interrupts for
> wait_barrier
> [ 464.246176] 2216: Post wait until no IO waiting - barrier: 0, pend:
> 6, wait: 0, queued: 0
> [ 464.246176] 2216: Pre wait pending to complete - barrier: 1, pend: 6,
> wait: 0, queued: 0
> [ 464.246176] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 464.246990] 5118 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.246990] In raid1_unplug debug read count: 6 write count: 0
> conf->nr_queued: 0
> [ 464.247091] 0 Obtaining resync_lock and disabling interrupts for
> allow_barrier
> [ 464.247091] conf nr_pending is 5
> [ 464.247091] 0 Released resync_lock and enabling interrupts for
> allow_barrier
> [ 464.247091] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 464.244469] 5113 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.246176] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 464.244469] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 464.328828] 3639 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 464.328834] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 466.065137] 2479 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 466.065137] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 467.051970] 2478 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 467.051975] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 471.293667] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 471.525081] 220 Obtaining resync_lock and disabling interrupts for
> wait_barrier
> [ 471.525081] In raid1_unplug debug read count: 5 write count: 0
> conf->nr_queued: 0
> [ 505.308962] 2216 WARNING, schedule_timeout timed out for raise_barrier
> [ 505.308076] 5118 WARNING, schedule_timeout timed out for wait_barrier
>
>
> ... so does that mean that there are are read requests going awol in the
> block layer?
>
> If so, then the circumstantial evidence from when the lockups occur make
> it look to me like this is probably an OpenVZ bug, but I'll try and do
> some more digging tomorrow...
>
> Does that make sense?

Yes. Superficially, it appears that there are still 5 outstanding read
requests that are not being completed. I cannot guess how OpenVZ would
cause that, but I don't really know much about OpenVZ.

NeilBrown

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

Re: Deadlock in md barrier code? / RAID1 / LVM CoW snapshot + ext3/ Debian 5.0 - lenny 2.6.26 kernel

On 11/21/10 23:05, Neil Brown wrote:
> Yes. Superficially, it appears that there are still 5 outstanding read
> requests that are not being completed. I cannot guess how OpenVZ would
> cause that, but I don't really know much about OpenVZ

Hi Neil,

I very much appreciate your help debugging this.

I opened a bug against the relevant Debian kernel. Now that this is
pretty well characterised, I think it's probably best to just workaround
it (e.g. by setting speed_limit_max to 0 during the backups which were
tripping over this), until such time as the kernel can be replaced with
a more recent one...

Cheers,

Tim.




--
South East Open Source Solutions Limited
Registered in England and Wales with company number 06134732.
Registered Office: 2 Powell Gardens, Redhill, Surrey, RH1 1TQ
VAT number: 900 6633 53 http://seoss.co.uk/ +44-(0)1273-808309

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