Bug 956387

This is reproducible.

This issue continues to appear during regression testing and blocks further progress.

All this requires to reproduce is two raid10 create attempts.

[root@qalvm-02 ~]# lvcreate --type raid10 -m 1 -L 4G -n lv1 test
  Logical volume "lv1" created
[root@qalvm-02 ~]# lvcreate --type raid10 -m 1 -L 4G -n lv2 test
[DEADLOCK]


May  1 14:27:27 qalvm-02 systemd-udevd[461]: worker [1324] /devices/virtual/block/dm-19 timeout; kill it
May  1 14:27:27 qalvm-02 systemd-udevd[461]: seq 1977 '/devices/virtual/block/dm-19' killed
May  1 14:27:33 qalvm-02 systemd-udevd[461]: worker [1324] terminated by signal 9 (Killed)

I've been able to create 25 RAID10 LV's using upstream kernel.

Is this reproducable on RHEL6?

I'll get RHEL7 installed and try it there.

This does not happen in official rhel6.4 build.

[root@taft-01 ~]# lvcreate --type raid10 -m 1 -L 4G -n lv1 taft
  Logical volume "lv1" created
[root@taft-01 ~]# lvcreate --type raid10 -m 1 -L 4G -n lv2 taft
  Logical volume "lv2" created

2.6.32-354.el6.x86_64
lvm2-2.02.98-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013
lvm2-libs-2.02.98-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013
lvm2-cluster-2.02.98-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013
udev-147-2.43.el6    BUILT: Thu Oct 11 05:59:38 CDT 2012
device-mapper-1.02.77-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013
device-mapper-libs-1.02.77-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013
device-mapper-event-1.02.77-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013
device-mapper-event-libs-1.02.77-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013
cmirror-2.02.98-9.el6    BUILT: Wed Jan 23 10:06:55 CST 2013

I can no longer reproduce this with the latest build from today (15-May-2013 15:29). The second create does still take quite awhile (in this case 2 minutes) apparently waiting for the first on to sync, but no longer hangs indefinitely. 

[root@qalvm-01 ~]# time lvcreate --type raid10 -m 1 -L 4G -n lv3 FOO
  Logical volume "lv3" created
real    0m2.107s
user    0m0.133s
sys     0m0.152s

[root@qalvm-01 ~]# time lvcreate --type raid10 -m 1 -L 4G -n lv4 FOO
  Logical volume "lv4" created
real    1m52.506s
user    0m0.162s
sys     0m0.157s


3.8.0-0.40.el7.x86_64
lvm2-2.02.99-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013
lvm2-libs-2.02.99-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013
lvm2-cluster-2.02.99-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013
device-mapper-1.02.78-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013
device-mapper-libs-1.02.78-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013
device-mapper-event-1.02.78-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013
device-mapper-event-libs-1.02.78-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013
cmirror-2.02.99-0.32.el7    BUILT: Wed May 15 08:28:08 CDT 2013

Let's keep this bug open for a bit.  The delay seems strange to me.

I'm having issues installing RHEL7, but I'll look at it when that's done.

Created attachment 753716 [details]
lvcreate verbose output of stuck RAID10 creation

Problem seems to be with udev/memlock.  Still needs more investigation to be sure.

The last upstream LVM package fixes the issue of an indefinite hang, but it still takes quite some time to create the logical volumes.  I get two LVs created quickly and then it seems to wait for sync before allowing new ones to be created.

I'd be willing to close this bug once the RPM is updated and the indefinite hang is cleared, but there are still a couple questions:
1) does this happen on RHEL6? (Either the hang or the long waits for creation.)
2) What upstream commit fixed the issue?
3) Is the problem due to unthrottled initialization or something else?

Nevermind.  Hit the same bug with the same output as the attachment.  Some of the questions in comment 9 are still valid though.  The same slowdown in creation is visible in RHEL6 (but not the hang) and it seems to be tied to waiting for initialization:

Below we can see that the first 3 RAID10 LVs were created quickly (all the LVs are still just beginning initialization).  The 4th create takes a long time and when finished shows the other 3 RAID10 LVs have completed their sync.

Iteration #3: 
real    0m0.661s
user    0m0.184s
sys     0m0.186s
  Configuration setting "activation/thin_check_executable" unknown.
  Configuration setting "activation/thin_check_options" unknown.
  LV   VG   Attr      LSize  Pool Origin Data%  Move Log Cpy%Sync Convert
  lv1  vg   rwi-a-r-- 10.00g                                 0.00        
  lv2  vg   rwi-a-r-- 10.00g                                 0.00        
  lv3  vg   rwi-a-r-- 10.00g                                 0.00        

Iteration #4: 
real    1m34.160s
user    0m0.227s
sys     0m0.273s
  Configuration setting "activation/thin_check_executable" unknown.
  Configuration setting "activation/thin_check_options" unknown.
  LV   VG   Attr      LSize  Pool Origin Data%  Move Log Cpy%Sync Convert
  lv1  vg   rwi-a-r-- 10.00g                               100.00        
  lv2  vg   rwi-a-r-- 10.00g                               100.00        
  lv3  vg   rwi-a-r-- 10.00g                               100.00        
  lv4  vg   rwi-a-r-- 10.00g                                 0.00

On RHEL6, if the max_recovery_rate is throttled, the creates happen almost instantly.  So it seems that (at least on RHEL6) that the unbounded sync processes are crowding out the I/O needed to update the VG metadata - causing the creation process to appear slow.

Throttling eliminates the problem on RHEL7 too.  However, LVM operations should not hang indefinitely if throttling is not used.  So, this still needs to get fixed even if throttling is introduced.

Removing --enable-udev_sync option from 'configure' solves the problem.  The issue is most certainly with udev.  Again, you can see this also in the attachment (attachment 753716 [details]).

To reproduce this issue, simply:
for i in $(seq 25) ; do
  echo
  echo -n "Iteration #$i: "
  time lvcreate --type raid10 -i 2 -m 1 -L 10G -n lv$i vg -vvvv >& output-$i.txt
  lvs vg
done

If '--enable-udev_sync' has been used, the third or forth lvcreate will hang forever.  (It is easier to reproduce if the LVs are at least 10G in size.)

Re-assigning to prajnoha for udev inspection.

*** Bug 951721 has been marked as a duplicate of this bug. ***

Well, I've tried this on my VM and it happens right after the second lvcreate call! I put udevd into debug mode and all the scanning bits (blkid etc) just wait too long while trying to read the disk - seems the raid sync is an overkill here.

As a consequence, after the default 30 sec udev timeout (which was 3 min before they changed this!), the blkid call gets killed and the whole udev RUN queue with that (hence we miss the completion notification from udev which is at the end of this RUN queue and hence we end up with a hang). We already filed a bug to provide some mechanism in udev to handle such situations more peacefully, at least to have a possibility to do some cleanup or provide some useful error messages to users if the udev timeout happens (see also bug #918511).

The IO queues are just huge. This helps a bit (at least in my case):

  sysctl -w vm.dirty_background_ratio=1
  sysctl -w  vm.dirty_ratio=1

Simply, the disk read is blocked too much by that md raid sync... What we would probably need here is to ban any scanning on the raid LV until it is synced and ready. But I'm not sure if that is possible to do it this way. We'd need an event generated at the end of the sync only, not before it (or at least we need to skip any scanning unless it's completely in sync and then run the scans in udev after syncing). OR the md raid needs to be throttled better by default so that other reads are allowed and there's no starving.

Jon, any idea?

I'm not very keen on throttling just to keep udev from barfing.  Besides, what value should we set it to?

While it does slow down the process of creating many LVs in RHEL6, it still functions without throttling.  This is how things should work in RHEL7.  Do you know what has changed in udev in RHEL7 vs RHEL6 that is causing such a bad problem?

(In reply to Jonathan Earl Brassow from comment #17)
> While it does slow down the process of creating many LVs in RHEL6, it still
> functions without throttling.  This is how things should work in RHEL7.  Do
> you know what has changed in udev in RHEL7 vs RHEL6 that is causing such a
> bad problem?

Unfortunately, I don't know exactly, it would need more inspection and comparison. However, we already hit an issue where the udev processing was slow enough (or starved enough) that udev killed the run queue on timeout and it also appeared later, for example in case of bug #885978, this was 6.3 iirc and we haven't found the exact change that caused this (though one of the main factors was in udev parallelism). I guess it must be a set of system-wide changes that make up for the whole timing to change and the actual timeout to appear as a consequence... In this case it's very hard to track down the exact source :-/

Well, I've reinstated the original 3min timeout for LVM devices:

  https://git.fedorahosted.org/cgit/lvm2.git/commit/?id=72a9d4f879751d58e531efbffaef1f7d325092c7

Recent udev uses 30s which is not enough when the system is under a load while the raid/mirror synchronization takes place. This is just a workaround until we can optimize this so that the 30s timeout is usable... Corey, could you please test the latest RHEL7 nighly build (Sep 11) to see whether the udev timeout/hang is gone? (or I can do a scratch build if needed).

If RHEL6 works, then this workaround should do it as then the udev timeout is exactly the same as in RHEL6...

I'm setting this one to POST for now - the other solution is to simply throttle the RAID processing. I believe the reason it did not show up in RHEL6 is the change in udev timeout only.

I need to put this back and add a fix - the timeout was not set correctly with the original patch. The fix:

https://git.fedorahosted.org/cgit/lvm2.git/commit/?id=e4c7236c07056ddc9af3ba6ad2314d649d6814f9

Sorry.

FYI, I am still running into the issue in 6.5 VMs (latest 6.5 compose with upstream LVM including 3 minute time out.) There are more VMs running on the host which are rather I/O intensive. This may not be a realistic scenario, but udev timing out may still happen under high load.

After changing elevator to deadline on both host and VMs this is no longer reproducible.

Ran 25 iterations of the loop, and even though it is slow, I did not get it stuck..
Ran on real HW not virtuals. 

Marking verified with lvm2-2.02.103-4.el7

This request was resolved in Red Hat Enterprise Linux 7.0.

Contact your manager or support representative in case you have further questions about the request.