|
Logs for the issue (xid 1427344285761632)
|
|
The original patch presumably introducing the issue: https://bugzilla.lustre.org/show_bug.cgi?id=16777
|
|
per xyratex internal discussion - change cfs_hash to insert lock in tail instead of head looks enough as short term fix, but if we have a too much resends we may double hash size and that will produce speed down for lookup operation - so.. we need look to better solution.
|
|
Under what conditions are you seeing a successful reply being lost for an intent lock request? How can the problem be recreated?
|
|
A reply can be lost because of a network error.
A simple reproducer for this issue, I believe, is:
[root@panda tests]# touch /mnt/lustre/file
[root@panda tests]# lctl set_param fail_loc=0x8000030c
fail_loc=0x8000030c
[root@panda tests]# setfattr -n user.attr -v value /mnt/lustre/file
|
|
The network should not loose things. Can you be more specific?
|
|
Keith,
you really think network should be don't loose something? 
PS. LNet don't have a guaranteed a delivering packet and delivering order. Network may have a flap or packet lost.. it's NORMAL.
|
|
Well, it is true that ideally network should not lose anything. In practice, though, packets do get lost sometimes, and we must deal with this unfortunate fact of life correctly.
The exact reason of why a reply might have been lost is not as important here (in case of hte reproducer it is lost deliberately as a test)
|
|
I think "lost" just means different things to different people I didn't mean to derail any discussion about mdt_intent_fixup_resent.
As step one on this issue I will work to add a test.
|
|
Panda, do you already have a patch for this bug? Could you please push it to Gerrit?
|
|
I don't seem to be able to trigger a deadlock and client eviction in my local test vms.
I tried adding more io but I was not able to trigger any form of a deadlock or eviction.
Would you mind writing a Lustre test for the deadlock and eviction that you see? It will help to address the issue.
|
|
What does dmesg show after running setfattr?
|
|
> Panda, do you already have a patch for this bug? Could you please push it to Gerrit?
No, I don't have a patch. I could trying coding if we agree how it can be fixed best. I can't agree with Alexey that changing hash to link new entries to tail instead of head is a good solution.
|
|
I don't have those logs at this point that VMs setup is pretty busy right now.
I don't recall seeing anything about setfattr in the dmesg.
I recall there was something about lost connection with the MDS (I slept for a while) and then a MDS Reconnection when file_loc when back to 0.
What do you see on your system? How do you trigger this issue?
|
|
Lucky day. I was cleaning up some old terminals and I found the output from one of my reproduction experiments.
I created a test replay-single test 91 . I think there was a 60 second sleep in this version before reverting the fail_loc status.
Can you provide your debug log or test for this issue? I should have some machines cycles tomorrow if you have further suggestions on how to reproduce the issue.
|
|
The defect clearly reproduces for me with WC repository commit 9fb5d1ff837880a7596d98f24ff6bb1bf0033f2b:
[root@panda tests]# bash llmount.sh
Stopping clients: panda /mnt/lustre (opts:)
Stopping clients: panda /mnt/lustre2 (opts:)
Loading modules from /mnt/nfs/xyratex/lustre-release/lustre/tests/..
detected 4 online CPUs by sysfs
Force libcfs to create 2 CPU partitions
../libcfs/libcfs/libcfs options: 'cpu_npartitions=2'
debug=vfstrace rpctrace dlmtrace neterror ha config ioctl super
subsystem_debug=all -lnet -lnd -pinger
gss/krb5 is not supported
quota/lquota options: 'hash_lqs_cur_bits=3'
Formatting mgs, mds, osts
Format mds1: /tmp/lustre-mdt1
Format ost1: /tmp/lustre-ost1
Format ost2: /tmp/lustre-ost2
Checking servers environments
Checking clients panda environments
Loading modules from /mnt/nfs/xyratex/lustre-release/lustre/tests/..
detected 4 online CPUs by sysfs
Force libcfs to create 2 CPU partitions
debug=vfstrace rpctrace dlmtrace neterror ha config ioctl super
subsystem_debug=all -lnet -lnd -pinger
gss/krb5 is not supported
Setup mgs, mdt, osts
Starting mds1: -o loop /tmp/lustre-mdt1 /mnt/mds1
Started lustre-MDT0000
Starting ost1: -o loop /tmp/lustre-ost1 /mnt/ost1
Started lustre-OST0000
Starting ost2: -o loop /tmp/lustre-ost2 /mnt/ost2
Started lustre-OST0001
Starting client: panda: -o user_xattr,flock panda@tcp:/lustre /mnt/lustre
Using TIMEOUT=20
enable jobstats, set job scheduler as procname_uid
Waiting 90 secs for update
Updated after 2s: wanted 'procname_uid' got 'procname_uid'
disable quota as required
[root@panda tests]# cd /mnt/lustre
[root@panda lustre]# touch /mnt/lustre/file
[root@panda lustre]# lctl set_param fail_loc=0x8000030c
fail_loc=0x8000030c
[root@panda lustre]# setfattr -n user.attr -v value /mnt/lustre/file
[root@panda lustre]# dmesg
Lustre: Mounted lustre-client
Lustre: DEBUG MARKER: Using TIMEOUT=20
Lustre: ctl-lustre-MDT0000: super-sequence allocation rc = 0 [0x0000000200000400-0x0000000240000400):0:mdt
Lustre: *** cfs_fail_loc=30c, val=2147483648***
LustreError: 30243:0:(ldlm_lib.c:2422:target_send_reply_msg()) @@@ dropping reply req@ffff88007d7d6850 x1429464107975760/t0(0) o101->ab287eba-76b5-0c4e-723e-377c1d2b0157@0@lo:0/0 lens 576/624 e 0 to 0 dl 1363243290 ref 1 fl Interpret:/0/0 rc 0/0
Lustre: 30711:0:(client.c:1866:ptlrpc_expire_one_request()) @@@ Request sent has timed out for slow reply: [sent 1363243284/real 1363243284] req@ffff88006b6db400 x1429464107975760/t0(0) o101->lustre-MDT0000-mdc-ffff88006b6db800@0@lo:12/10 lens 576/1048 e 0 to 1 dl 1363243291 ref 2 fl Rpc:X/0/ffffffff rc 0/-1
Lustre: lustre-MDT0000-mdc-ffff88006b6db800: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete
Lustre: lustre-MDT0000: Client ab287eba-76b5-0c4e-723e-377c1d2b0157 (at 0@lo) reconnecting
Lustre: lustre-MDT0000-mdc-ffff88006b6db800: Connection restored to lustre-MDT0000 (at 0@lo)
LNet: Service thread pid 30243 was inactive for 40.00s. The thread might be hung, or it might only be slow and will resume later. Dumping the stack trace for debugging purposes:
Pid: 30243, comm: mdt01_001
Call Trace:
[<ffffffff814ead32>] schedule_timeout+0x192/0x2e0
[<ffffffff8107cb50>] ? process_timeout+0x0/0x10
[<ffffffffa0fe46d1>] cfs_waitq_timedwait+0x11/0x20 [libcfs]
[<ffffffffa12bb22d>] ldlm_completion_ast+0x4ed/0x960 [ptlrpc]
[<ffffffffa12b6950>] ? ldlm_expired_completion_wait+0x0/0x390 [ptlrpc]
[<ffffffff8105fa40>] ? default_wake_function+0x0/0x20
[<ffffffffa12ba968>] ldlm_cli_enqueue_local+0x1f8/0x5d0 [ptlrpc]
[<ffffffffa12bad40>] ? ldlm_completion_ast+0x0/0x960 [ptlrpc]
[<ffffffffa0981c60>] ? mdt_blocking_ast+0x0/0x2a0 [mdt]
[<ffffffffa098492b>] mdt_object_lock0+0x33b/0xaf0 [mdt]
[<ffffffffa0981c60>] ? mdt_blocking_ast+0x0/0x2a0 [mdt]
[<ffffffffa12bad40>] ? ldlm_completion_ast+0x0/0x960 [ptlrpc]
[<ffffffffa09851a4>] mdt_object_lock+0x14/0x20 [mdt]
[<ffffffffa0985211>] mdt_object_find_lock+0x61/0x170 [mdt]
[<ffffffffa09a7671>] mdt_reint_setxattr+0x461/0x1850 [mdt]
[<ffffffffa1164c70>] ? lu_ucred+0x20/0x30 [obdclass]
[<ffffffffa09811e5>] ? mdt_ucred+0x15/0x20 [mdt]
[<ffffffffa099bf8c>] ? mdt_root_squash+0x2c/0x410 [mdt]
[<ffffffffa130fe96>] ? __req_capsule_get+0x166/0x700 [ptlrpc]
[<ffffffffa09a0781>] mdt_reint_rec+0x41/0xe0 [mdt]
[<ffffffffa0999de3>] mdt_reint_internal+0x4e3/0x7d0 [mdt]
[<ffffffffa099a114>] mdt_reint+0x44/0xe0 [mdt]
[<ffffffffa098b008>] mdt_handle_common+0x628/0x1620 [mdt]
[<ffffffffa09c27d5>] mds_regular_handle+0x15/0x20 [mdt]
[<ffffffffa12f402c>] ptlrpc_server_handle_request+0x41c/0xdf0 [ptlrpc]
[<ffffffffa0fe45de>] ? cfs_timer_arm+0xe/0x10 [libcfs]
[<ffffffffa12eb759>] ? ptlrpc_wait_event+0xa9/0x290 [ptlrpc]
[<ffffffff81052223>] ? __wake_up+0x53/0x70
[<ffffffffa12f5576>] ptlrpc_main+0xb76/0x1870 [ptlrpc]
[<ffffffffa12f4a00>] ? ptlrpc_main+0x0/0x1870 [ptlrpc]
[<ffffffff8100c0ca>] child_rip+0xa/0x20
[<ffffffffa12f4a00>] ? ptlrpc_main+0x0/0x1870 [ptlrpc]
[<ffffffffa12f4a00>] ? ptlrpc_main+0x0/0x1870 [ptlrpc]
[<ffffffff8100c0c0>] ? child_rip+0x0/0x20
LustreError: dumping log to /tmp/lustre-log.1363243331.30243
LustreError: 0:0:(ldlm_lockd.c:391:waiting_locks_callback()) ### lock callback timer expired after 157s: evicting client at 0@lo ns: mdt-ffff8800cd97e000 lock: ffff8800cdaa2600/0x3d633a3159cdb915 lrc: 3/0,0 mode: PR/PR res: 8589935616/1 bits 0x1b rrc: 3 type: IBT flags: 0x200000000020 nid: 0@lo remote: 0x3d633a3159cdb8f9 expref: 9 pid: 30243 timeout: 4297311737 lvb_type: 0
LNet: Service thread pid 30243 completed after 150.27s. This indicates the system was overloaded (too many service threads, or there were not enough hardware resources).
LustreError: 11-0: lustre-MDT0000-mdc-ffff88006b6db800: Communicating with 0@lo, operation obd_ping failed with -107.
Lustre: lustre-MDT0000-mdc-ffff88006b6db800: Connection to lustre-MDT0000 (at 0@lo) was lost; in progress operations using this service will wait for recovery to complete
LustreError: 167-0: lustre-MDT0000-mdc-ffff88006b6db800: This client was evicted by lustre-MDT0000; in progress operations using this service will fail.
Lustre: lustre-MDT0000-mdc-ffff88006b6db800: Connection restored to lustre-MDT0000 (at 0@lo)
|
|
I have waited way past 157s (well over 15 min) and there is no change to dmesg. This is the same behavior I saw before.
My version is Lustre: Build Version: 2.3.62--PRISTINE-2.6.32-279.19.1.el6_lustre.x86_64 . It is a Master build from last week it is post 9fb5d1ff837880a7596d98f24ff6bb1bf0033f2b by a good bit.
Any more ideas for reproduction? I am inclined to think this is not a generic Lustre Master issue.
|
|
Keith, I don't see the mark for the fail injection to hit in your logs?
The "Lustre: *** cfs_fail_loc=30c, val=2147483648***" message?
What is this mds node that you mount? The failloc needs to be injected on the mds node and you seems to be running on a client? (unless mds is just a fancy alias to client in your setup)
|
|
I've just checked out the latest version: 20baff1f7f77b02f629e5f7980807ad151423b3b.
The issue is still hit.
And I'm sorry if my explanation on fail_loc was not detailed enough.
Just as Oleg said, the fail loc needs to be set on the MDS. Actually, llmount without additional parameters sets up a single-node configuration, so I thought I did not have to mention that.
|
|
I learn something every day I do manage 3 small VMS. I haven't use fail_loc outside of the test framework context thanks for the info. My inital attemps to repro used the testframework so I think the fail_loc was set properly there.
Ok so a repeat of the test setting the fail_loc on the mds.
From the mds
from the client
The "setfattr -n user.attr -v value /mnt/lustre/file" hung for a small amount of time 10-20 seconds maybe.
|
|
All right I rebooted everything and did it again and this time I got it.
from the mds:
Would you mind making a Lustre test for this issue?
|
|
Keith, since you are able to reproduce it now, I think it's trivial for you to create the test.
In fact it would be great if you can just fix the existign test that tests for this problem (and is broken for ages as it appears because of teh change in locking we depended on to trigger it) and fix it.
|
|
Oleg which test tests for this presently? I can can take care of the test.
Is there a clear path forward to fix the issue?
|
|
Well a test not working at all or it just does not fail much.
This is with a 10 min wait from the MDS dmesg:
The fail_loc is set on the mds we don't seem to trigger the hang.
This is the test that is not working.
I tried it by hand a few times (including a fresh reboot) exactly the same way I triggered it before and did not encounter the error. I see the client reconnecting quickly and no eviction.
Andrew you seem to reproduce this quite easily. How many attempts does it take you to trigger it? What should the timeout be from the setfattr to the mount check? My inital thought was 180s but I escalated it thinking I was not waiting long enough?
I am going to run a 5 min wait loop overnight to see if I can catch the error again.
|
|
Hello Keith!
The issue has been reproducing very easily for me. Actually, I had to try a lot to make the test not work.
However, it seems, there is a race condition that can be hard to reproduce with your multi-node configuration.
This is how it works for me.
00010000:00010000:1.0:1363770071.095970:0:2835:0:(ldlm_lock.c:631:ldlm_add_bl_work_item()) ### lock incompatible; sending blocking AST. ns: mdt-ffff8801281dd000 lock: ffff8800c85
d8480/0x37eadca6bd308e8b lrc: 2/0,0 mode: PR/PR res: 8589935619/4 bits 0x3 rrc: 3 type: IBT flags: 0x4000000 nid: 0@lo remote: 0x37eadca6bd308e6f expref: 8 pid: 3330 timeout: 0
=============
00010000:00010000:1.0:1363770071.095987:0:2835:0:(ldlm_lock.c:631:ldlm_add_bl_work_item()) ### lock incompatible; sending blocking AST. ns: mdt-ffff8801281dd000 lock: ffff8800c85
d8a80/0x37eadca6bd308eae lrc: 2/0,0 mode: PR/PR res: 8589935619/4 bits 0x3 rrc: 3 type: IBT flags: 0x4000000 nid: 0@lo remote: 0x37eadca6bd308e6f expref: 8 pid: 2835 timeout: 0
00010000:00000001:1.0:1363770071.096007:0:2835:0:(ldlm_lock.c:666:ldlm_add_ast_work_item()) Process leaving
=============
00010000:00010000:1.0:1363770071.096129:0:2835:0:(ldlm_lockd.c:834:ldlm_server_blocking_ast()) ### server preparing blocking AST ns: mdt-ffff8801281dd000 lock: ffff8800c85d8a80/0x37eadca6bd308eae lrc: 3/0,0 mode: PR/PR res: 8589935619/4 bits 0x3 rrc: 3 type: IBT flags: 0x4000020 nid: 0@lo remote: 0x37eadca6bd308e6f expref: 8 pid: 2835 timeout: 0
00010000:00010000:1.0:1363770071.096144:0:2835:0:(ldlm_lockd.c:487:ldlm_add_waiting_lock()) ### adding to wait list(timeout: 150, AT: on) ns: mdt-ffff8801281dd000 lock: ffff8800c85d8a80/0x37eadca6bd308eae lrc: 4/0,0 mode: PR/PR res: 8589935619/4 bits 0x3 rrc: 3 type: IBT flags: 0x4000020 nid: 0@lo remote: 0x37eadca6bd308e6f expref: 8 pid: 2835 timeout: 4299631388
00010000:00010000:1.0:1363770071.096482:0:2835:0:(ldlm_lockd.c:834:ldlm_server_blocking_ast()) ### server preparing blocking AST ns: mdt-ffff8801281dd000 lock: ffff8800c85d8480/0x37eadca6bd308e8b lrc: 3/0,0 mode: PR/PR res: 8589935619/4 bits 0x3 rrc: 3 type: IBT flags: 0x4000020 nid: 0@lo remote: 0x37eadca6bd308e6f expref: 8 pid: 3330 timeout: 0
00010000:00010000:1.0:1363770071.096499:0:2835:0:(ldlm_lockd.c:487:ldlm_add_waiting_lock()) ### adding to wait list(timeout: 150, AT: on) ns: mdt-ffff8801281dd000 lock: ffff8800c85d8480/0x37eadca6bd308e8b lrc: 4/0,0 mode: PR/PR res: 8589935619/4 bits 0x3 rrc: 3 type: IBT flags: 0x4000020 nid: 0@lo remote: 0x37eadca6bd308e6f expref: 8 pid: 3330 timeout: 4299631389
==============
00010000:00010000:0.0:1363770071.097126:0:2972:0:(ldlm_lockd.c:1524:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: lustre-MDT0000-mdc-ffff8800cdb54c00 lock: ffff8800cd89abc0/0x37eadca6bd308e6f lrc: 2/0,0 mode: PR/PR res: 8589935619/4 bits 0x3 rrc: 1 type: IBT flags: 0x10000000 nid: local remote: 0x37eadca6bd308eae expref: -99 pid: 3430 timeout: 0
00010000:00010000:1.0:1363770071.097574:0:3217:0:(ldlm_lockd.c:1524:ldlm_handle_bl_callback()) ### client blocking AST callback handler ns: lustre-MDT0000-mdc-ffff8800cdb54c00 lock: ffff8800cd89abc0/0x37eadca6bd308e6f lrc: 3/0,0 mode: --/PR res: 8589935619/4 bits 0x3 rrc: 1 type: IBT flags: 0x30002090 nid: local remote: 0x37eadca6bd308eae expref: -99 pid: 3430 timeout: 0
00010000:00010000:1.0:1363770071.097614:0:3217:0:(ldlm_request.c:1251:ldlm_cli_cancel()) ### lock is already being destroyed <==================== no reply sent?
However, if two cancels are processed sequentially as compared to parallel execution ldlm_callback_handler() will return -EINVAL:
lock = ldlm_handle2lock_long(&dlm_req->lock_handle[0], 0);
if (!lock) {
CDEBUG(D_DLMTRACE, "callback on lock "LPX64" - lock "
"disappeared\n", dlm_req->lock_handle[0].cookie);
rc = ldlm_callback_reply(req, -EINVAL);
ldlm_callback_errmsg(req, "Operate with invalid parameter", rc,
&dlm_req->lock_handle[0]);
RETURN(0);
}
if ((lock->l_flags & LDLM_FL_FAIL_LOC) &&
lustre_msg_get_opc(req->rq_reqmsg) == LDLM_BL_CALLBACK)
OBD_RACE(OBD_FAIL_LDLM_CP_BL_RACE);
lock_res_and_lock(lock);
lock->l_flags |= ldlm_flags_from_wire(dlm_req->lock_flags &
LDLM_AST_FLAGS);
if (lustre_msg_get_opc(req->rq_reqmsg) == LDLM_BL_CALLBACK) {
/* If somebody cancels lock and cache is already dropped,
* or lock is failed before cp_ast received on client,
* we can tell the server we have no lock. Otherwise, we
* should send cancel after dropping the cache. */
if (((lock->l_flags & LDLM_FL_CANCELING) &&
(lock->l_flags & LDLM_FL_BL_DONE)) ||
(lock->l_flags & LDLM_FL_FAILED)) {
LDLM_DEBUG(lock, "callback on lock "
LPX64" - lock disappeared\n",
dlm_req->lock_handle[0].cookie);
unlock_res_and_lock(lock);
LDLM_LOCK_RELEASE(lock);
rc = ldlm_callback_reply(req, -EINVAL);
ldlm_callback_errmsg(req, "Operate on stale lock", rc,
&dlm_req->lock_handle[0]);
RETURN(0);
}
/* BL_AST locks are not needed in LRU.
* Let ldlm_cancel_lru() be fast. */
ldlm_lock_remove_from_lru(lock);
lock->l_flags |= LDLM_FL_BL_AST;
}
unlock_res_and_lock(lock);
Perhaps, adding an OBD_RACE barrier right before the ldlm_handle2lock_long() call might help the issue become more easily reproducible.
|
|
By the way, sleep 600 is not required by your test. And could you, please, make sure that sanity_mount_check() really checks if there was an eviction?
|
|
I have yet to repro the issue with the test. I will be sure sanity_mount_check or some other check is the right thing to catch eviction.
Perhaps I will work on this in a single VM environment as over night testing didn't get me anything. The one time I triggered it (documented up above) was right from a fresh reboot.
|
|
I put the beta test here http://review.whamcloud.com/5795
A timeout is need so that we can detect the error and take correct actions.
Likely when we detect the error we will need to recreate a working FS.
I tried to recreate the issue in a single VM for a while today but I didn't get the error.
Can you try the test to see if it fails for you? Perhaps you can help finish the test as you seem to be able to redly reproduce the issue and I don't for some reason.
|
|
Keith, the problem you have is your tet creates the double lock but does not really try to revoke it.
Now, if you do revocation (I have some comments in the patch), the problem is clearly seen, but in a somewhat unexpected way.
You might want to run it with debug logs and check in the debug log that the second lock got created on resend and then find out how can you cancel that lock - this will trigger lock timeout and client eviction.
Previous test for this was replay-single test 52 (I think, still cannot find original report I digged way back in the future), but now stat does not cancel the lock at all (not that it ever did too, I guess).
Potentially mds intent lock is ill suited for this test now, and instead we might want to do a test that drops lock reply on ost and then resend creates another one, and then we cause cancel (by e.g. unlinking a file or doing stat from another client - important to do it from another client to avoid ELC cancelling our copy of the lock beforehand)
|
|
replay single test 52 stemmed from https://projectlava.xyratex.com/show_bug.cgi?id=3764 (circa 2004)
I have started working on a two client test I hope to a have code to share tomorrow.
|
|
Well spent good cycles trying to created the issue with 2 clients and VMs for the MDT/MDS and OSS/OST. I tried all sort of operations. In general the first operations would block for a few seconds the things work like normal. The fail_loc setting only really seems change the behavior on initial operations. I did not encounter the issue today at all.
I spent some time trying to sort how to drop locks on the OST but I find any examples of this. Any hints?
|
|
To for a lock drop, do some conflicting operation.
Example:
touch /mnt/lustre/file # creates file
ls -l /mnt/lustre/file # obtains read locks on ost objects of the file
echo aaa >/mnt/lustre/file # attempts to write - cancels read lock in process (unlink would do too), but due to ELC client does it all by itself
# now, assuming /mnt/lustre2 is same lustre fs on different mountpoint
echo aaa >>/mnt/lustre2/file # this actually forces ost to cancel the lock given out from a previous operation.
|
|
Actually, looking at the title of this ticket (duh), this is mdt_intent_fixup() bug, so it's mds only, as such, its best to concentrate on mds operations after all, like setxattr.
So example from above would probably be: touch somefile ; ls -l somefile ; rm -rf othermountpoint/somefile
with the reply drop around ls -l
|
|
Alexey, Vitaly and I have discussed a possible solution. I'm coding it at the moment.
|
|
Panda,
I have reproduced this in single node cluster but not in multiple nodes. Have you ever tried to reproduce this in multiple nodes cluster? If not, could you try that?
|
|
Minh, I haven't tried to reproduce with multi-node configurations. But, as I wrote in https://jira.hpdd.intel.com/browse/LU-2827?focusedCommentId=54450&page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel#comment-54450, it seems clear that without special fault injection code it might be hard to reproduce the issue on a multi-node setup.
I've posted a prototype patch for discussion/review: http://review.whamcloud.com/5978 (it does not include a test case).
|
|
Xyratex-bug-id: MRP-975
|
|
A test case: http://review.whamcloud.com/#change,6000
|
|
Lowering priority. This patch is not ready and this limitation has been present in earlier version of Lustre
|
|
There's no new patch at the moment. We will be discussing a different solution than was coded in the gerrit patches.
If Whamcloud are going to code their own patch, please let us know.
|
|
Since both tickets (and their patches!) are highly related, I tried running the reproducer of LU-4584 against latest build #23312 from this ticket/Gerrit-change LU-2827/#5978-8. But the MDS just hit the LASSERT(lock->l_granted_mode != lock->l_req_mode) that the change introduced in ldlm_process_inodebits_lock().
The platform I used was made of one MDS, 2 OSSs with a total of 154 OSTs, and a full default striping...
|
|
I also see this patch does NOT apply well to the b2_5 branch.
|
|
I just had a look into the MDS crash-dump I got when running the reproducer of LU-4584 against latest build #23312 from this ticket/Gerrit-change LU-2827/#5978-8, and due to the LBUG/LASSERT(lock->l_granted_mode != lock->l_req_mode) that the change introduced in ldlm_process_inodebits_lock(). It looks like it does not handle the scenario of a layout-lock reply that is truncated due to the size of layout exceeding the reply buffer on Client side, causing the Client to resend the request. Because in this particular case, the ldlm_lock is already granted, so I wonder why this LASSERT has been introduced starting with patch-set #6 of Change #5978 ??
|
|
I just tried this patch with the LASSERT removed. For my simul run I see the following:
22441.866214] INFO: task mdt03_000:14714 blocked for more than 120 seconds.
[22441.866546] Tainted: P --------------- 2.6.32-431.11.2.el6.wc.x86_64 #1
[22441.867007] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[22441.867482] mdt03_000 D 000000000000001e 0 14714 2 0x00000000
[22441.867840] ffff8807d77a58c8 0000000000000046 0000000000000000 ffffffffa0f52503
[22441.868319] ffff8807b7b8f190 ffff8807b7b8f138 ffff881071a8b538 ffffffffa0f52503
[22441.868786] ffff8807d77a3af8 ffff8807d77a5fd8 000000000000fbc8 ffff8807d77a3af8
[22441.869267] Call Trace:
[22441.869440] [<ffffffff8152aa15>] rwsem_down_failed_common+0x95/0x1d0
[22441.869773] [<ffffffffa0d9c32b>] ? ldiskfs_xattr_trusted_get+0x2b/0x30 [ldiskfs]
[22441.870218] [<ffffffff811ae457>] ? generic_getxattr+0x87/0x90
[22441.870516] [<ffffffff8152aba6>] rwsem_down_read_failed+0x26/0x30
[22441.870838] [<ffffffffa0fdf073>] ? lod_xattr_get+0x153/0x420 [lod]
[22441.871168] [<ffffffff8128eef4>] call_rwsem_down_read_failed+0x14/0x30
[22441.871495] [<ffffffff8152a0a4>] ? down_read+0x24/0x30
[22441.871786] [<ffffffffa0f1c4bd>] mdt_object_open_lock+0x1ed/0x9d0 [mdt]
[22441.872141] [<ffffffffa0efe7ac>] ? mdt_attr_get_complex+0x4ec/0x770 [mdt]
[22441.872486] [<ffffffffa0f24ae7>] mdt_reint_open+0x15b7/0x2150 [mdt]
[22441.872818] [<ffffffffa05bdf86>] ? upcall_cache_get_entry+0x296/0x880 [libcfs]
[22441.873292] [<ffffffffa074f780>] ? lu_ucred+0x20/0x30 [obdclass]
[22441.873608] [<ffffffffa0f0d461>] mdt_reint_rec+0x41/0xe0 [mdt]
[22441.859651] [<ffffffffa0ef2e63>] mdt_reint_internal+0x4c3/0x780 [mdt]
[22441.859989] [<ffffffffa0ef330e>] mdt_intent_reint+0x1ee/0x520 [mdt]
[22441.860347] [<ffffffffa0ef0bce>] mdt_intent_policy+0x3ae/0x770 [mdt]
[22441.860694] [<ffffffffa086a511>] ldlm_lock_enqueue+0x361/0x8c0 [ptlrpc]
[22441.861059] [<ffffffffa0893b1f>] ldlm_handle_enqueue0+0x51f/0x10f0 [ptlrpc]
[22441.861443] [<ffffffffa0ef1096>] mdt_enqueue+0x46/0xe0 [mdt]
[22441.861791] [<ffffffffa0ef5c5a>] mdt_handle_common+0x52a/0x1470 [mdt]
[22441.862134] [<ffffffffa0f32785>] mds_regular_handle+0x15/0x20 [mdt]
[22441.862476] [<ffffffffa08c3b85>] ptlrpc_server_handle_request+0x385/0xc00 [ptlrpc]
[22441.862977] [<ffffffffa05a24ce>] ? cfs_timer_arm+0xe/0x10 [libcfs]
[22441.863330] [<ffffffffa05b33df>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
[22441.863687] [<ffffffffa08bb1d9>] ? ptlrpc_wait_event+0xa9/0x2d0 [ptlrpc]
[22441.864077] [<ffffffff81054839>] ? __wake_up_common+0x59/0x90
[22441.864417] [<ffffffffa08c4eed>] ptlrpc_main+0xaed/0x1920 [ptlrpc]
[22441.864778] [<ffffffffa08c4400>] ? ptlrpc_main+0x0/0x1920 [ptlrpc]
[22441.865127] [<ffffffff8109aee6>] kthread+0x96/0xa0
[22441.865390] [<ffffffff8100c20a>] child_rip+0xa/0x20
[22441.865655] [<ffffffff8109ae50>] ? kthread+0x0/0xa0
[22441.865925] [<ffffffff8100c200>] ? child_rip+0x0/0x20
[22609.397953] Lustre: 14705:0:(service.c:1341:ptlrpc_at_send_early_reply()) @@@ Couldn't add any time (5/5), not sending early reply
[22609.397955] req@ffff8807ca512800 x1467386901306824/t0(0) o101->daaf34f5-eb04-8d8f-f1f6-350b15d96039@2@gni1:0/0 lens 656/3512 e 12 to 0 dl 1399410998 ref 2 fl Interpret:/0/0 rc 0/0
[22609.619944] Lustre: 15089:0:(service.c:1341:ptlrpc_at_send_early_reply()) @@@ Couldn't add any time (5/5), not sending early reply
[22609.619946] req@ffff8807d548d800 x1467386902355424/t0(0) o101->a076348e-1b45-8004-2751-8404ca9d2c3f@28@gni1:0/0 lens 656/3512 e 12 to 0 dl 1399410998 ref 2 fl Interpret:/0/0 rc 0/0
[23019.472325] Lustre: sultan-MDT0000: Client a076348e-1b45-8004-2751-8404ca9d2c3f (at 28@gni1) reconnecting
[23019.476010] Lustre: sultan-MDT0000: Client 8ba0393c-b95b-703f-68d0-65583606e0ff (at 3@gni1) reconnecting
|
|
Bruno: The assert was introduced specifically to catch this case.
Basically what we are tryign to catch is this: Server has processed a request and returned it back to client, but client cannot accept it due to too small buffer, so it resends.
Now server finds this is a resend and finds the old, already granted lock. The assertion is placed in to ensure that this lock is NOT attempted to be granted again (it's already granted). And so if it hits for you, it appears some sort of a path is left uncovered to just reuse the old found lock and not retry to grant it.
So if you can outline how this happens so that Vitaly can update the patch, that would be great. Thanks
|
|
Oleg,
I thought I made it clear already that LU-4584 contains already all information/reproducer/... that fully detail its specific scenario of a layout-lock reply from Server being truncated, due to reply buffer too short on Client vs layout/striping size, then causing Client to resend layout-lock request where current bug leads to a duplicated lock on Server and later Client eviction during 1st lock blocking callback process.
BTW, it reproduces solid on homogeneous b2_4/b2_5/master Servers/Client platforms and again triggers the LBUG/LASSERT(lock->l_granted_mode != lock->l_req_mode) that the change introduced in ldlm_process_inodebits_lock() when running with this ticket/Gerrit-change LU-2827/#5978-8.
|
|
I spent some time to reproduce the MDS LBUG//LASSERT(lock->l_granted_mode != lock->l_req_mode) I had when running the simple reproducer from LU-4584 on a Lustre build with this ticket/Gerrit-change LU-2827/#5978-[8,9] and here is what seems to happen :
_ in fact even a simple dd to create a file with a default and significant striping (I am using 154 OSTs), right after file-system start/mount triggers the problem ...
_ what I see in the Client/MDS full debug logs then is that, as expected after LU-4584 scenario analysis, the Client resend occurs during a layout lock (MDS_INODELOCK_LAYOUT) reply from the server that is truncated due to the striping/layout size exceeding reply buffer size :
Client 1st/original request
Server handle+reply
Reply truncated at Client side, request is resent
Server detects resend, but since not expected for layout-lock, handles again, hence the LBUG
I have an add-on for current Gerrit-change LU-2827/#5978-[8,9] that handles this truncate/resend during layout-lock issue.
And I just submitted it, at http://review.whamcloud.com/10378, as a new patch/change that relates on latest LU-2827/#5978-9 patch-set.
|
|
Here is the b2_5 version of the patch I'm testing with:
http://review.whamcloud.com/#/c/10492
|
|
Tested it first on my smallest size test bed and the two patches that I combined and back port to b2_5 did pretty well. So I moved the test to a larger system and when I went to run my simul reproducer I now get this:
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.308755] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.317414] mdt02_247 D 0000000000000008 0 17580 2 0x00000000
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.324711] ffff88104d7b98c8 0000000000000046 0000000000000000 ffffffffa0e0f4ab
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.333113] ffff8810719e5310 ffff8810719e52b8 ffff88104d7a5538 ffffffffa0e0f4ab
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.341442] ffff88104d7b7af8 ffff88104d7b9fd8 000000000000fbc8 ffff88104d7b7af8
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.349651] Call Trace:
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.352455] [<ffffffff8152a6d5>] rwsem_down_failed_common+0x95/0x1d0
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.359226] [<ffffffffa0c0c32b>] ? ldiskfs_xattr_trusted_get+0x2b/0x30 [ldiskfs]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.367490] [<ffffffff811ae017>] ? generic_getxattr+0x87/0x90
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.373729] [<ffffffff8152a866>] rwsem_down_read_failed+0x26/0x30
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.380272] [<ffffffffa08b7083>] ? lod_xattr_get+0x153/0x420 [lod]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.386972] [<ffffffff8128eab4>] call_rwsem_down_read_failed+0x14/0x30
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.393901] [<ffffffff81529d64>] ? down_read+0x24/0x30
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.399595] [<ffffffffa0dd949d>] mdt_object_open_lock+0x1ed/0x9d0 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.406680] [<ffffffffa0dbb7ac>] ? mdt_attr_get_complex+0x4ec/0x770 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.413960] [<ffffffffa0de1ac7>] mdt_reint_open+0x15b7/0x2150 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.420672] [<ffffffffa0453f76>] ? upcall_cache_get_entry+0x296/0x880 [libcfs]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.428803] [<ffffffffa05f3700>] ? lu_ucred+0x20/0x30 [obdclass]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.435224] [<ffffffffa0dca441>] mdt_reint_rec+0x41/0xe0 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.441611] [<ffffffffa0dafe63>] mdt_reint_internal+0x4c3/0x780 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.448515] [<ffffffffa0db03ee>] mdt_intent_reint+0x1ee/0x520 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.455274] [<ffffffffa0dadbce>] mdt_intent_policy+0x3ae/0x770 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.462212] [<ffffffffa070e511>] ldlm_lock_enqueue+0x361/0x8c0 [ptlrpc]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.469289] [<ffffffffa0737b9f>] ldlm_handle_enqueue0+0x51f/0x10f0 [ptlrpc]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.476684] [<ffffffffa0dae096>] mdt_enqueue+0x46/0xe0 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.482790] [<ffffffffa0db2c5a>] mdt_handle_common+0x52a/0x1470 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.489687] [<ffffffffa0def765>] mds_regular_handle+0x15/0x20 [mdt]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.496399] [<ffffffffa0767c25>] ptlrpc_server_handle_request+0x385/0xc00 [ptlrpc]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.504762] [<ffffffffa04384ce>] ? cfs_timer_arm+0xe/0x10 [libcfs]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.511492] [<ffffffffa04493cf>] ? lc_watchdog_touch+0x6f/0x170 [libcfs]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.518772] [<ffffffffa075f2a9>] ? ptlrpc_wait_event+0xa9/0x2d0 [ptlrpc]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.525902] [<ffffffff810546b9>] ? __wake_up_common+0x59/0x90
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.532184] [<ffffffffa0768f8d>] ptlrpc_main+0xaed/0x1920 [ptlrpc]
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.545438] [<ffffffff8109ab56>] kthread+0x96/0xa0
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.550656] [<ffffffff8100c20a>] child_rip+0xa/0x20
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.556068] [<ffffffff8109aac0>] ? kthread+0x0/0xa0
May 29 18:27:03 atlas-tds-mds1 kernel: [10809.561451] [<ffffffff8100c200>] ? child_rip+0x0/0x20
Its better in that the MDS doesn't assert any more.I also canceled the job and the system recovered which is a good sign.
|
|
IOR single shared file run is producing the below messages. Also I have a log dumps that I uploaded to
ftp.whamcloud.com/uploads/LU-2827/lustre-log-LU-2827-29-05-2014
May 29 18:47:39 atlas-tds-mds1 kernel: [12046.175064] Lustre: 17065:0:(service.c:1349:ptlrpc_at_send_early_reply()) Skipped 8 previous similar messages
May 29 18:47:45 atlas-tds-mds1 kernel: [12052.188755] Lustre: atlastds-MDT0000: Client 23d4a774-8c3b-4edc-3b98-24d112966233 (at 14@gni2) reconnecting
May 29 18:47:45 atlas-tds-mds1 kernel: [12052.199379] Lustre: Skipped 1 previous similar message
May 29 19:00:15 atlas-tds-mds1 kernel: [12801.706037] Lustre: 17829:0:(service.c:1349:ptlrpc_at_send_early_reply()) @@@ Couldn't add any time (5/-150), not sending early reply
May 29 19:00:15 atlas-tds-mds1 kernel: [12801.706039] req@ffff8807e74adc00 x1468567563329976/t0(0) o101->73ecb9e8-d229-752a-3cfc-2036f509fb5b@50@gni2:0/0 lens 512/3512 e 0 to 0 dl 1401404420 ref 2 fl Interpret:/0/0 rc 0/0
May 29 19:00:15 atlas-tds-mds1 kernel: [12802.233175] Lustre: 17062:0:(service.c:1349:ptlrpc_at_send_early_reply()) @@@ Couldn't add any time (5/-150), not sending early reply
May 29 19:00:15 atlas-tds-mds1 kernel: [12802.233176] req@ffff8807e76d6400 x1468567565457596/t0(0) o101->e8d3ca06-b910-df85-78e9-5653469b4bb8@81@gni2:0/0 lens 512/3512 e 0 to 0 dl 1401404420 ref 2 fl Interpret:/0/0 rc 0/0
May 29 19:00:15 atlas-tds-mds1 kernel: [12802.263339] Lustre: 17062:0:(service.c:1349:ptlrpc_at_send_early_reply()) Skipped 4 previous similar messages
May 29 19:00:21 atlas-tds-mds1 kernel: [12808.519392] Lustre: atlastds-MDT0000: Client 568959a5-c11b-5ded-e1c9-1c90892a82ca (at 49@gni2) reconnecting
|
|
I am afraid I am not able to conclude about what is going wrong, using this only MDS Lustre debug-log. Are there still similar stacks being dumped in dmesg/syslog ?
Also, I did not find any eviction trace in this log.
|
|
With the patches the evictions are gone which is good. Now its just locking up.
|
|
I tested master with the patches as well and got the same results.
|
|
http://review.whamcloud.com/#/c/5978/
http://review.whamcloud.com/#/c/10378/
|
|
Landed for 2.6
|
|
Merged b2_4 backport of both #5978 and #10378 master changes for this ticket, is at http://review.whamcloud.com/10902.
|
|
We would really, really prefer that you guys not merge together multiple patches when backporting. That makes sanity checking and rebasing quite a bit more complicated for us.
|
|
The merge was done to avoid the same miss with original patch where mdt_intent_layout() had been forgotten because not present in Xyratex source-tree at this time.
BTW, my b2_4 patch/back-port has some problem and needs some re-work, because MDS bombs with "(ldlm_lock.c:851:ldlm_lock_decref_internal_nolock()) ASSERTION( lock->l_readers > 0 ) failed" when running LLNL reproducer from LU-4584 or recovery-small/test_53 in auto-tests.
More to come, crash-dump is under investigations ...
|
|
I should have commented this before, sorry.
In fact there are regression issues with my b2_4 back-port (http://review.whamcloud.com/#/c/10902/) of LU-2827 changes. And I checked that the b2_5 version (http://review.whamcloud.com/#/c/10492/) is ok and that it should land soon now.
|
|
need to included fix from LU-5530 with fix from LU-2827
|
|
Antoine,
You are right this must be made clear here also, so to be complete, the full list of post LU-2827 related tickets/patches has been well documented and in detail by Oleg in its LU-4584 2x comments dated 11/Sep/14 for LU-4584.
|
|
Jian Yu (jian.yu@intel.com) uploaded a new patch: http://review.whamcloud.com/14056
Subject: LU-2827 tests: add version check to recovery-small test 113
Project: fs/lustre-release
Branch: master
Current Patch Set: 1
Commit: 43d451f52f487780c9c83340574a125c3b6506fe
|
Generated at Sat Feb 10 01:28:32 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
hash-bug.log