Bug 1095463 - lvmetad has over a million sockets open after long run of raid failure testing
Summary: lvmetad has over a million sockets open after long run of raid failure testing
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Red Hat Enterprise Linux 7
Classification: Red Hat
Component: lvm2
Version: 7.0
Hardware: x86_64
OS: Linux
urgent
high
Target Milestone: rc
: 7.1
Assignee: Petr Rockai
QA Contact: cluster-qe@redhat.com
Milan Navratil
URL:
Whiteboard:
Depends On:
Blocks: 1313485 1295577
TreeView+ depends on / blocked
 
Reported: 2014-05-07 18:53 UTC by Corey Marthaler
Modified: 2016-11-04 04:07 UTC (History)
9 users (show)

Fixed In Version: lvm2-2.02.152-1.el7
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2016-11-04 04:07:49 UTC
Target Upstream Version:


Attachments (Terms of Use)
-vvvv of the snap create (216.50 KB, text/plain)
2014-05-07 18:53 UTC, Corey Marthaler
no flags Details


Links
System ID Priority Status Summary Last Updated
Red Hat Product Errata RHBA-2016:1445 normal SHIPPED_LIVE lvm2 bug fix and enhancement update 2016-11-03 13:46:41 UTC

Description Corey Marthaler 2014-05-07 18:53:48 UTC
Created attachment 893454 [details]
-vvvv of the snap create

Description of problem:
I noticed these errors after a day and a half of running raid + pool failure testing. The test continued to run with out any actual failures so I'm not sure how big of a deal this is, if at all.


[root@host-003 ~]# lvcreate -s black_bird/synced_random_raid4_3legs_1 -L 100M
  black_bird-lvol0: event registration failed: 3225:7 libdevmapper-event-lvm2snapshot.so dlopen failed: libdevmapper-event-lvm2snapshot.so: cannot open shared object file: Too many open files
  black_bird/snapshot0: snapshot segment monitoring function failed.
  black_bird-lvol1: event registration failed: 3225:11 libdevmapper-event-lvm2snapshot.so dlopen failed: libdevmapper-event-lvm2snapshot.so: cannot open shared object file: Too many open files
  black_bird/snapshot1: snapshot segment monitoring function failed.
  black_bird-synced_random_raid4_3legs_1-real: event registration failed: 3225:15 libdevmapper-event-lvm2raid.so dlopen failed: libdevmapper-event-lvm2raid.so: cannot open shared object file: Too many open files
  black_bird/synced_random_raid4_3legs_1: raid4 segment monitoring function failed.
  Logical volume "lvol1" created
[root@host-003 ~]# echo $?
0
[root@host-003 ~]# lvs -a -o +devices
  LV                                     Attr       LSize   Origin                      Data%  Cpy%Sync Devices
  lvol0                                  swi-a-s--- 100.00m synced_random_raid4_3legs_1   0.00          /dev/sdf1(0)
  lvol1                                  swi-a-s--- 100.00m synced_random_raid4_3legs_1   0.00          /dev/sdf1(25)
  synced_random_raid4_3legs_1            owi-a-r--- 504.00m                                      100.00 synced_random_raid4_3legs_1_rimage_0(0),synced_random_raid4_3legs_1_rimage_1(0),synced_random_raid4_3legs_1_rimage_2(0),synced_random_raid4_3legs_1_rimage_3(0)
  [synced_random_raid4_3legs_1_rimage_0] iwi-aor--- 168.00m                                             /dev/sdc1(1)
  [synced_random_raid4_3legs_1_rimage_1] iwi-aor--- 168.00m                                             /dev/sdb1(1)
  [synced_random_raid4_3legs_1_rimage_2] iwi-aor--- 168.00m                                             /dev/sdh1(1)
  [synced_random_raid4_3legs_1_rimage_3] iwi-aor--- 168.00m                                             /dev/sde1(1)
  [synced_random_raid4_3legs_1_rmeta_0]  ewi-aor---   4.00m                                             /dev/sdc1(0)
  [synced_random_raid4_3legs_1_rmeta_1]  ewi-aor---   4.00m                                             /dev/sdb1(0)
  [synced_random_raid4_3legs_1_rmeta_2]  ewi-aor---   4.00m                                             /dev/sdh1(0)
  [synced_random_raid4_3legs_1_rmeta_3]  ewi-aor---   4.00m                                             /dev/sde1(0)

[root@host-003 ~]# lvcreate -s black_bird/synced_random_raid4_3legs_1 -vvvv -L 100M > /tmp/lvcreate 2>&1

[root@host-003 tmp]# lsof | grep lvmetad | wc -l
1060757
[root@host-003 tmp]# lsof | grep dmeventd | wc -l
1045


Version-Release number of selected component (if applicable):
3.10.0-122.el7.x86_64
lvm2-2.02.105-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014
lvm2-libs-2.02.105-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014
lvm2-cluster-2.02.105-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014
device-mapper-1.02.84-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014
device-mapper-libs-1.02.84-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014
device-mapper-event-1.02.84-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014
device-mapper-event-libs-1.02.84-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014
device-mapper-persistent-data-0.3.2-1.el7    BUILT: Thu Apr  3 09:58:51 CDT 2014
cmirror-2.02.105-14.el7    BUILT: Wed Mar 26 08:29:41 CDT 2014

Comment 1 Zdenek Kabelac 2014-06-19 11:26:33 UTC
Passing to prockai to give some more thoughts, but with current upstream it might be already fixed since I do not observe this.

Anyway - it would be probably better to attach  list of running processes for such case (ps -aux) and even at least portion of opened sockets.

Number of opened file descriptors by  dmeventd  looks quite high as well so likely there could be some other weird actions going on behind.

Comment 2 Petr Rockai 2014-06-30 14:47:10 UTC
This is super-weird. It is dmeventd failing to open files, not lvmetad. A dump of running processes and their /proc/<pid>/fd/ would be definitely helpful. lsof | grep lvmetad will not only count the number of FDs held by lvmetad, if the socket has (as is the default) lvmetad in its name -- any processes talking to (or trying to talk to) lvmetad will be included as well. Also, is there an FD ulimit imposed on dmeventd in this scenario? Running out of FDs at ~1000 would be otherwise quite odd.

Comment 3 Petr Rockai 2014-10-01 09:07:22 UTC
Any updates on this? Does it still happen, and if yes, any chance of getting a more detailed listing of open files?

Comment 4 Corey Marthaler 2014-10-23 17:10:03 UTC
This does still happen with the latest 7.1 rpms when doing extended failure testing (if you don't hit bug 1153796 first).

lvcreate --virtualsize 200M --thinpool black_bird/non_synced_random_raid1_3legs_3 -n virt_non_synced_random_raid1_3legs_3
  black_bird-non_synced_random_raid1_3legs_3-tpool: event registration failed: 3964:5 libdevmapper-event-lvm2thin.so dlopen failed: libdevmapper-event-lvm2thin.so: cannot open shared object file: Too many open files
  black_bird/non_synced_random_raid1_3legs_3: thin-pool segment monitoring function failed.
  black_bird-non_synced_random_raid1_3legs_3-tpool: event registration failed: 3964:11 libdevmapper-event-lvm2thin.so dlopen failed: libdevmapper-event-lvm2thin.so: cannot open shared object file: Too many open files
  black_bird/non_synced_random_raid1_3legs_3: thin-pool segment monitoring function failed.

[root@host-114 ~]# lsof | grep lvmetad | wc -l
1058697
[root@host-114 ~]# lsof | grep dmeventd | wc -l
4194

3.10.0-184.el7.x86_64

lvm2-2.02.111-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014
lvm2-libs-2.02.111-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014
lvm2-cluster-2.02.111-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014
device-mapper-1.02.90-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014
device-mapper-libs-1.02.90-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014
device-mapper-event-1.02.90-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014
device-mapper-event-libs-1.02.90-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014
device-mapper-persistent-data-0.3.2-1.el7    BUILT: Thu Apr  3 09:58:51 CDT 2014
cmirror-2.02.111-1.el7    BUILT: Mon Sep 29 09:18:07 CDT 2014

Comment 5 Alasdair Kergon 2014-11-28 21:46:02 UTC
The patch for bug 1164234 might provide part of the answer.

But as requested in comment 3, we do need to see the *actual* listings, not just the 'wc' summaries.  Could you grab the complete 'lsof' output into a file for us so we can get a better idea of where the leak(s) are?

Comment 6 Alasdair Kergon 2014-11-28 23:24:44 UTC
(You don't have to wait for the failure to get the lsof data as it accumulates over time, grabbing it much earlier in the test should be enough to show exactly which resources are not getting released when they should be.)

Comment 8 Zdenek Kabelac 2015-11-05 13:17:53 UTC
New code in lvm2 2.02.133 tracks resources differently - and hopefully more correctly - in already version thanks to various races it's been possible to leak file descriptors for control device.

Once this version is out for testing - this bug should be rechecked.

Comment 12 Mike McCune 2016-03-28 23:23:30 UTC
This bug was accidentally moved from POST to MODIFIED via an error in automation, please see mmccune@redhat.com with any questions

Comment 15 Corey Marthaler 2016-09-07 21:23:35 UTC
Marking this verified in lvm2-2.02.164-4. 

Raid failure testing now appears to run for days with lvm2-lvmetad running. 


[...]
================================================================================
Iteration 32.37 started at Wed Sep  7 09:51:48 CDT 2016
================================================================================
Scenario kill_multiple_synced_raid6_4legs: Kill multiple legs of synced 4 leg raid6 volume(s)
********* RAID hash info for this scenario *********
* names:              synced_multiple_raid6_4legs_1
* sync:               1
* type:               raid6
* -m |-i value:       4
* leg devices:        /dev/sdc1 /dev/sdb1 /dev/sda1 /dev/sdf1 /dev/sdg1 /dev/sde1
* spanned legs:       0
* manual repair:      0
* failpv(s):          /dev/sdf1 /dev/sdg1
* failnode(s):        host-124
* lvmetad:            1
* cache stack:        1
* raid fault policy:  warn
******************************************************

Comment 18 errata-xmlrpc 2016-11-04 04:07:49 UTC
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory, and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://rhn.redhat.com/errata/RHBA-2016-1445.html


Note You need to log in before you can comment on or make changes to this bug.