|
I have assigned it to me since I have started to work on this with JB on-site.
|
|
I could reproduce the problem yesterday on site with Lustre 2.9 (containing the suggested LU-5560 patch).
I am preparing a custom build with more debug information on locks in some ldlm functions.
I will test it tomorrow on site, and with debug done with Bruno last week in crash, I should have a precise idea of what it is going on by tomorrow evening.
|
|
During joint on-site analysis with JB (where we have crashed all Clients/Servers nodes of our test VM-made cluster at the same time trying to get a frozen picture of the blocked situation), we have found that due to SE-Linux, each inode/dentry look'ed-up on a path discovery/namei needs to get+control the security/selinux XATTR, and this seems to strongly interfer when concurrent access occur from same and different nodes, like with CEA's identified reproducer (A mix of concurrent stat/create/setattr from >100 nodes, as far as I can understand from reproducer's text indicated in ticket's description).
We have still not finished the analysis, but seems that for a particular MDT object, for which there are a lot of mdt threads waiting to grant Clients read/write locks, and where some (there are multiple granted) of the currently granted read-lock owner's are now stuck on client side trying to getxattr of security.selinux xattr, and this since hundreds of seconds. When on MDT side we have discovered that these getxattr requests have been received/queued but are not handled.
This is where we are at the moment, but there is more to come. And JB, feel free to add/correct me.
|
|
JB, could you attach the dmesg and the output of 'foreach bt' from the MDS crash image?
|
|
Here are more detailed infos with the help of datas that we have been allowed to extract and use in this ticket.
We have continued the analysis of the pseudo-hang on-site, and we have found that the getxattr() request for the security.selinux EA could not be handled by MDS/MDT because all the 149 of the 150 threads serving the "mdt" service are stuck with either of the following 2 stacks :
when the last/150th seems busy handling obd_ping traffic, as found in the debug trace extracted from the crash-dump.
BTW and as expected, during a new run+pseudo-hang of the reproducer, raising the max number of “mdt” service threads to 1024, has allowed the MDS to quickly recover from its pseudo-hung situation and finally handle all requests leading to reproducer's completion in a very short time !!…
The contended resource appears to be the main directory where the reproducer’s files are located “/lustre/testfs/testuser/testdir/“.
The Clients threads, currently having the lock on the directory resource granted, and then waiting for their getxattr() request to be serviced have the following stack :
Others reproducer's threads on the same Clients have the following stacks, depending if they support a touch (3 per reproducer step) or stat (4 per reproducer step) cmd in the reproducer :
But I need to also detail the state of the reproducer's processes on the others Clients/nodes, likely to be responsible of the requests being handled by the hung threads on MDS side just described before.
I will also try to better understand if the 1st touch/file creation (requiring a write lock on directory to add entry) is mandatory or not to get the pseudo-hung situation or not.
Based on all of this, and after a finer on-site crash-dump analysis of the current locking requests state from all Clients, I will also try to summarize our understanding of the exact sequence of requests/events leading to the pseudo-hung situation when running the reproducer in my next post.
But I have already the feeling that we may face a problem due to a timing window where some Client(s) can get a lock on directory granted and then try to access the security.selinux xattr, but in the mean time others Clients have submitted their requests/locks on the directory resource and have monopolized all the available "mdt" service threads.
|
|
What are the kernel and lustre versions running on the MDS and on the clients?
|
|
Clients and MDS are running both:
- 3.10.0-514.el7_lustre.x86_64
- lustre: 2.9.0 (lustre-2.9.0-1)
|
|
MDS max started threads: 149
Blocked thread blocked on the MDS: 147
Remaining non-blocked threads are high prio threads for OBD_PING, MDS_CONNECT and OST_CONNECT operations.
Locks waiting:
[riauxj@test174 ]$ cat locks_waiting | wc -l
147
Blocked threads in mdt_intent_getattr:
[riauxj@test174 tmp]$ grep mdt_intent_getattr /tmp/bt_all_mdt_service_threads.out |wc -l
126
locks are LCK_PR
[riauxj@test174 ]$ grep LCK_PR locks_waiting.out | wc -l
126
[riauxj@test174 ]$ cat locks_waiting.out | grep "l_req_mode = LCK_PR" -A 28 | grep -i "bits = " | grep -v l_inodebits | uniq
bits = 19 # 13 en hexa
[riauxj@test174 ]$ cat locks_waiting.out | grep "l_req_mode = LCK_PR" -A 28 | grep -i "bits = " | grep -v l_inodebits | wc -l
126
Blocked threads in mdt_reint_open:
[riauxj@test174 tmp]$ grep mdt_reint_open /tmp/bt_all_mdt_service_threads.out |wc -l
21
Locks are LCK_CW, ibits 2.
[riauxj@test174 ]$ grep LCK_CW locks_waiting.out | wc -l
21
[riauxj@test174 ]$ cat locks_waiting.out | grep "l_req_mode = LCK_CW" -A 28 | grep -i "bits = " | grep -v l_inodebits | uniq
bits = 2
[riauxj@test174 ]$ cat locks_waiting.out | grep "l_req_mode = LCK_CW" -A 28 | grep -i "bits = " | grep -v l_inodebits | wc -l
21
126+21 = 147 which math blocked threads number.
Looking compat matrix:
* <PRE>
* NL CR CW PR PW EX
* NL 1 1 1 1 1 1
* CR 1 1 1 1 1 0
* CW 1 1 1 0 0 0
* PR 1 1 0 1 0 0
* PW 1 1 0 0 0 0
* EX 1 0 0 0 0 0
* </PRE>
PR and CW are not compatible.
So we have processes (stat and touch) doing Concurent Write ibits 2 :
MDS_INODELOCK_UPDATE
and Protected Read ibits 0x13:
MDS_INODELOCK_LOOKUP
MDS_INODELOCK_UPDATE
MDS_INODELOCK_PERM
-------------------
GRANTED locks:
We identified why granted locks are not released.
Granted locks are LCK_PR ibits 0x13
[riauxj@test174 ]$ cat locks_granted.out | grep "l_req_mode = LCK_PR" -A 28 | grep -i "bits = " | grep -v l_inodebits | uniq
bits = 19
[riauxj@test174 ]$ cat locks_granted.out | grep "l_req_mode = LCK_PR" -A 28 | grep -i "bits = " | grep -v l_inodebits | wc -l
33
Following the locks lead again to following stacks (touch and stat)
commande touch:
PID: 8825 TASK: ffff88072dee6dd0 CPU: 5 COMMAND: "touch"
#0 [ffff88017d4ef5a0] __schedule at ffffffff8168b175
#1 [ffff88017d4ef608] schedule at ffffffff8168b7c9
#2 [ffff88017d4ef618] schedule_timeout at ffffffff81689155
#3 [ffff88017d4ef6c8] ptlrpc_set_wait at ffffffffa09c8cd0 [ptlrpc]
#4 [ffff88017d4ef770] ptlrpc_queue_wait at ffffffffa09c918d [ptlrpc]
#5 [ffff88017d4ef790] mdc_xattr_common at ffffffffa0bd93aa [mdc]
#6 [ffff88017d4ef810] mdc_getxattr at ffffffffa0bd962f [mdc]
Here the client tries to create a new lock (MDS_INODELOCK_XATTR) but MDS cannot accept it as all its threads are busy
#7 [ffff88017d4ef850] lmv_getxattr at ffffffffa0c1660e [lmv]
#8 [ffff88017d4ef8c8] ll_getxattr_common at ffffffffa0c942c4 [lustre]
#9 [ffff88017d4ef948] ll_getxattr at ffffffffa0c94763 [lustre]
#10 [ffff88017d4ef980] inode_doinit_with_dentry at ffffffff812b281f
#11 [ffff88017d4ef9d8] selinux_d_instantiate at ffffffff812b38ec
#12 [ffff88017d4ef9e8] security_d_instantiate at ffffffff812a819b
#13 [ffff88017d4ef9f8] d_instantiate at ffffffff812162b0
#14 [ffff88017d4efa20] ll_splice_alias at ffffffffa0c8939a [lustre]
#15 [ffff88017d4efa60] ll_lookup_it_finish at ffffffffa0c89633 [lustre]
Here the client created a lock on the test directory (common on all clients) which is the granted lock we find on the MDS. But client cannot release the lock as it tries to create a lock MDS_INODELOCK_XATTR upper in the stack (which cannot be handled by MDS because all threads are busy). So we are stuck
#16 [ffff88017d4efb28] ll_lookup_it at ffffffffa0c8ae6e [lustre]
#17 [ffff88017d4efbe0] ll_lookup_nd at ffffffffa0c8c6dd [lustre]
#18 [ffff88017d4efc78] lookup_real at ffffffff812083dd
#19 [ffff88017d4efc98] __lookup_hash at ffffffff81208d52
#20 [ffff88017d4efcc8] lookup_slow at ffffffff816833fb
#21 [ffff88017d4efd00] link_path_walk at ffffffff8120b96f
#22 [ffff88017d4efdb0] path_openat at ffffffff8120dc53
#23 [ffff88017d4efe48] do_filp_open at ffffffff8120fdeb
#24 [ffff88017d4eff18] do_sys_open at ffffffff811fd2f3
#25 [ffff88017d4eff70] sys_open at ffffffff811fd40e
#26 [ffff88017d4eff80] system_call_fastpath at ffffffff81696709
PID: 8826 TASK: ffff88072b7d0000 CPU: 6 COMMAND: "stat"
#0 [ffff880729abbbc0] __schedule at ffffffff8168b175
#1 [ffff880729abbc28] schedule_preempt_disabled at ffffffff8168c8b9
#2 [ffff880729abbc38] __mutex_lock_slowpath at ffffffff8168a515
#3 [ffff880729abbc98] mutex_lock at ffffffff8168997f
#4 [ffff880729abbcb0] lookup_slow at ffffffff816833ec
#5 [ffff880729abbce8] path_lookupat at ffffffff8120c273
#6 [ffff880729abbd80] filename_lookup at ffffffff8120c2cb
#7 [ffff880729abbdb8] user_path_at_empty at ffffffff8120fce7
#8 [ffff880729abbe88] user_path_at at ffffffff8120fd51
#9 [ffff880729abbe98] vfs_fstatat at ffffffff812031c3
#10 [ffff880729abbee8] SYSC_newlstat at ffffffff81203791
#11 [ffff880729abbf70] sys_newlstat at ffffffff81203a1e
#12 [ffff880729abbf80] system_call_fastpath at ffffffff81696709
We see also that invocating d_instantiate (selinux_d_instantiate) add an entry in the dentry.
So sometimes with luck, some processes finished (before we kill the job) and when we rerun the test it works because the cache was populated (at least a bit).
|
|
John,
After I had an indeep look into the related source code and the patches for LU-5560, I wonder if the solution to this problem could not be to simply restore the xattr cache usage (that is presently removed in merged patch version of "LU-5560 llite: basic support of SELinux in CLIO", i.e. master commit 8a11cb6282cfbdc8617b809344e6a11223e86a38) also for security.selinux ??
What do you think?
J-B, would it be possible to test this on-site with your reproducer+test-platform??
Patch should look as this :
|
|
Talking with S.Buisson about this, he also pointed to his patch (https://review.whamcloud.com/24426) for LU-8956 which should also avoid extraneous getxattr() request to fetch security related EAs.
J-B will give a try to both possible solutions and expose them to the known reproducer and let us know asap about his results.
|
|
Tested both patches yesterday, the problem remains. However with Bruno's patch, the stack is now different than before and Sebastien's patch did improve a bit the test speed. The test did evict 2 or 3 clients at each run but every run ended after 5mns(lustre unmounted and cache dropped between runs), so it's a bit better. Before this patch we could wait 2h, lustre was not recovering properly. If I don't drop caches, the test ends in less than 3 seconds after a first run.
Also for the 2 or 3 clients that failed I see this output:
I did merge both patches today. New stacks on clients looks like this:
On the MDS, no surprises (all stacks are the same):
|
|
We should be able to test a possible solution (embed security context/xattr in lookup reply to avoid extra getxattr() from security hooks, and thus fix dead-lock) on-site next week.
|
|
Hi Bruno, JB,
Any news from the test mentioned in your last comment ?
|
|
Hello Seb,
Tests of my patch by JB are still on-going (I had a few issues to fix in-between), and I should hopefully be able to push it soon now.
|
|
Faccini Bruno (bruno.faccini@intel.com) uploaded a new patch: https://review.whamcloud.com/26831
Subject: LU-9193 security: return security context for lookup
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 7dde7a39a58fbdf580238970608b6a74e976659f
|
|
Ticket status:
- gerrit patchset-8 tested: the selinux attr returned by MDC (for the new atomic op) had a wrong size so the client had to do a getxattr so bug can be reproduced.
- gerrit patchset-9 tested: fix of attr size, could reproduce again but need to do another run to get full logs and investigate.
|
|
New logs.
Size problem on attribute security.selinux remains:
00000100:00020000:5.0:1499254632.192081:0:8826:0:(pack_generic.c:425:lustre_msg_buf_v2()) msg ffff8806812ca0c0 buffer[6] size 37 too small (required 128, opc=101)
00000100:00020000:5.0:1499254632.193816:0:8826:0:(layout.c:2087:__req_capsule_get()) @@@ Wrong buffer for field `file_secctx' (6 of 7) in format `LDLM_INTENT_GETATTR': 37 vs. 128 (server)
req@ffff8806746f8000 x1572082208998624/t0(0) o101->testfs1-MDT0000-mdc-ffff88066da70800@10.252.0.1@tcp:12/10 lens 728/584 e 0 to 0 dl 1499254639 ref 1 fl Complete:R/0/0 rc 0/0
00000080:08000000:5.0:1499254632.196775:0:8826:0:(namei.c:513:ll_lookup_it_finish()) Server returned 'security.selinux' security context/xattr for [0x200000401:0x1:0x0] (37 bytes long): (null)
00000080:00000400:5.0:1499254632.196777:0:8826:0:(namei.c:521:ll_lookup_it_finish()) Error when trying to set security context for [0x200000401:0x1:0x0] rc = -13
removed unnecessary OSS logs from the archive (file size too big) logs_050717.tar.gz
|
|
New test today with use of flag RMF_F_NO_SIZE_CHECK in call file_secctx:
Errors messages as in previous comment are gone but MDS threads are all consumed and load is at 0 (as before).
New set of logs attached (one mistake: backtrace of MDS, vm0.bt.log file, is in lustre directory instead of crash directory).
lustre-LU9193-240817.tar.gz
|
|
Patchset-11 tested. Problem remains (MDS load at 0 and all threads used) and this time I got eviction (see vm19 logs).
Logs attached. logs-9193-patchset11-tests.tar.gz
|
|
Hum, having a look to the all the hung Client tasks stacks, it does not look like anymore that we are still facing a dead-lock scenario due to unexpected getxattr() of security xattr/context. On the other hand, since the MDS full thread stacks log is missing in the tarball I can't analyze further. Will need to go on-site and analyze in live with J-B, but looks like the original dead-lock issue is over and that we face a new issue.
|
|
Well, as expected after my previous comment, this new pseudo-hang/dead-lock situation can be reproduced by running latest Lustre master on RHEL7.2 and with SELinux disabled...
A lot of reproducer/clients stat+touch threads are stuck waiting for lock on directory to be granted with stacks like following:
when all MDT service threads become busy/blocked with the similar stacks than following :
So my current feeling is that the original problem/dead-lock for this ticket should be fixed now by my current patch, but we may now face some regression in Lustre latest master.
We will try to better qualify this new suspected problem, with more on-site debugging using reproducer's new runs without SELinux now. Will also try to expose same platform to others CEA regression tests on meta-datas.
|
|
By the way, it seems to me that this last pseudo-hang/dead-lock scenario looks very similar to LU-10235 !!
|
|
It is close, yes. It looks like mdt_reint_open() also takes a MDS_INODELOCK_UPDATE lock on the parent object before doing a lookup and create if lookup fails.
In LU-10235 I was only looking at mdt_create() but a similar solution of doing a first lookup with MDS_INODELOCK_LOOKUP followed by dropping/getting lock for update and another lookup would likely help in this precise case (since you're hammering a file that already exists), but if all the files are different e.g. hundreds of clients creating thousands different files in a single directory then it wouldn't help at all. I'm not sure what we could do for this scenario, it's practically a denial of service at this point...
|
|
The last dead-lock situation encountered in this ticket, has nothing related with original issue that this ticket has been created for, but seems to be more generic and being addressed in both LU-10235/LU-10262 tickets now.
|
|
Bruno, unless you think your current patch is fundamentally moving in the wrong direction (I haven looked at it yet) then I think it makes sense to land the current patch that solves the first problem, then make a second patch to address this next problem.
At least we are moving in the right direction to fix the first problem, which is what the application was originally hitting, and possibly the second problem you are able to produce is not actually being seen by applications, so we have more time to work on a solution.
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/26831/
Subject: LU-9193 security: return security context for metadata ops
Project: fs/lustre-release
Branch: master
Current Patch Set:
Commit: fca35f74f9ec5c5ed77e774f3e3209d9df057a01
|
|
Landed for 2.13
|
|
Sebastien Piechurski (sebastien.piechurski@atos.net) uploaded a new patch: https://review.whamcloud.com/34573
Subject: LU-9193 security: return security context for metadata ops
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 24b11428909ea77c7f4a101b4e2b7f8b2c490f06
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/34573/
Subject: LU-9193 security: return security context for metadata ops
Project: fs/lustre-release
Branch: b2_12
Current Patch Set:
Commit: 7aa5ae2673f70ef851fb903b280a0fc9a47c476b
|
|
this patch causes often client reconnects somehow:
Apr 21 03:09:50 nodez kernel: Lustre: 4239:0:(client.c:2134:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1555830583/real 1555830583] req@ffff8800ad5fc740 x1631406542374112/t0(0) o101->lustre-MDT0000-mdc-ffff8800af2fb800@0@lo:12/10 lens 616/4752 e 0 to 1 dl 1555830590 ref 2 fl Rpc:X/2/ffffffff rc 0/-1
Apr 21 03:09:50 nodez kernel: Lustre: lustre-MDT0000-mdc-ffff8800af2fb800: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete
Apr 21 03:09:50 nodez kernel: Lustre: lustre-MDT0000: Client 2f22eecb-5055-b4d6-16b5-a958700fcbda (at 0@lo) reconnecting
Apr 21 03:09:50 nodez kernel: Lustre: lustre-MDT0000: Connection restored to 4e8c3a45-3b8a-cd6a-047f-22363e8171e6 (at 0@lo)
Apr 21 03:09:50 nodez kernel: Lustre: Skipped 1 previous similar message
I am seeing many such messages during dbench run and git bisect shows this patch is source of problems.
|
|
Created LU-12212 for reconnect issue
|
|
Mike Pershin (mpershin@whamcloud.com) uploaded a new patch: https://review.whamcloud.com/41387
Subject: LU-9193 security: return security context for metadata ops
Project: fs/lustre-release
Branch: b2_12
Current Patch Set: 1
Commit: 68554f5ebf1479748b9bc9f6f86d4eb4c5dc9873
|
|
Oleg Drokin (green@whamcloud.com) merged in patch https://review.whamcloud.com/41387/
Subject: LU-9193 security: return security context for metadata ops
Project: fs/lustre-release
Branch: b2_12
Current Patch Set:
Commit: cd17e1a2e6367a7c3f07753e71fa569c28000c81
|
Generated at Sat Feb 10 02:24:02 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
LU-9193-patchset8.tar.gz