|
What I observed in the log
line 140698, ldlm_cli_cancel()
line 140704, ldlm_cli_cancel_local() ldlm lock ffff880793e54180/0xf128b59d838c9d81 res: [0x9edf8f:0x0:0x0].0 flags: 0x284'0000'0000 (LVB_READY|CANCELING|CBPENDING)
line 140756, the ldlm lock is destroyed ldlm_lock_destroy_internal(), which set the destroy flag for the ldlm lock (0x0004000000000000ULL)
line 140771, prepare to issue ldlm lock cancel request
line 140781, ldlm_cancel_pack() lock: ffff880793e54180/0xf128b59d838c9d81 flags: 0x8694'0000'0000 (BL_DONE|KMS_IGNORE|LVB_READY|CANCELING|CANCEL|CBPENDING) the destroy flag disappeared
Cliff, what's the latest git commit is this code? Since I've seen cl_lock_discard_pages() while current master branch does not have this function in it, I need to know the exact code base you were using when you hit this problem.
|
|
We saw exactly same problem on multiple clients during mdtest is running. The client was running with the latest master branch.
we have crashdump as well. Please let me know it helps for debugging.
|
|
Hi Ihara-San,
Do you have debug log of it?
|
|
Hi Bobijam,
vmware-dmesg.txt attached. Please let me know if you need vmware itself. I can upload it as well.
|
|
besides dmesg, do you have debug log? (lctl dk)
|
|
The test was run Nov 18th, build information was not in the version: build: 2.5.51--PRISTINE-2.6.32-358.23.2.el6_lustre.x86_64 - so it was likely the 2.5.51 tag.
|
|
Sysrq -t from hung client.
|
|
Attempting to attach file again
|
|
From the feedback from Ihara, it looks like there exists race condition to access the flags of dlm lock.
Let's create a debug patch to add a line into ldlm_lock_destroy_internal() to print out what's exact state of the lock
|
|
debug patch at http://review.whamcloud.com/8759, please unset panic_on_lbug (echo 0 > /proc/sys/lnet/panic_on_lbug) and run this debug patched version so that we can collect the debug log when this assertion is hit.
|
|
I've post a patch for this. However, it is not sure whether it fixes this problem, since we don't have a reliable way to reproduce this problem yet.
http://review.whamcloud.com/#/c/8772/
|
|
Thank you LiXi, but the iwc48.lctl.log.txt shows in line 140770
which shows that when we canceled the problematic lock, ldlm_prepare_lru_list() didn't find other lru locks, so I'd think your patch would possibly not affect this issue.
|
|
Ah, thank you for pointing that out, Zhenyu. I was just wondering why we can call ldlm_lock_remove_from_lru_nolock() without calling lock_res_and_lock() first. Is there anything I missed?
|
|
ldlm_prepare_lru_list() is to collect unused lock from namespace::ns_unused_list, where only unused locks are linked into it (please refer to ldlm_lock_decref_internal()->ldlm_lock_add_to_lru()), so in ldlm_prepare_lru_list() we can call ldlm_lock_remove_from_lru_nolock() w/o locking the res and lock since the lock has no readers nor writers referring to it.
|
|
Ah, thank you for the explaination! Now I understand. 
|
|
how often do you guys see this problem? If it's quite often, please apply Bobijam's patch and get some logs; otherwise, I'd like to drop the priority of this ticket.
Jinshan
|
|
Jinshan, Bobijam,
Yes, we applied Bobijam's debug patch at the customer site, but didn't reproduce problem yet. I will post logs once we can hit same issue.
|
|
We got crash again with debug patch. Attached is diagnostic information of crach.
|
|
do you collect any lctl log from it?
|
|
no, unfortunately.. client got panic even we have panic_on_lbug=0 setting.. I don't know why we got panic after LBUG..
|
|
We reproduced this running master + a client lock debug patch on SLES11SP3 while reproducing a client lock bug. I believe we hit this with a special debug flag for cl_lock_trace turned on (So all calls to cl_lock_trace are being logged, but little or nothing else.)
I should be able to make the dump and logs available if you think it would be helpful. I'm not sure about reproducing it, with different debug or at all - We run the test I'm using as a reproducer a lot and this is the first we've seen this particular bug. (The test in question is mmstress from the Linux Test Project.)
|
|
yes please upload logs Patrick, thank you.
|
|
Console log & Lustre log.
System is master from January 23rd on SLES11SP3, with a special debug patch that enables all calls to cl_lock_trace.
|
|
Logs attached as noted. I've also uploaded the dump (with logs, vmlinuz, ko files, etc) to ftp.whamcloud.com at uploads/LU-4269/LU-4269-140123.tar.gz
System is master from January 23rd on SLES11SP3, with a special debug patch that enables all calls to cl_lock_trace.
Also, we reproduced this by running mmstress from the Linux test project. We ran multiple copies on multiple nodes. (This also hits several cl_lock related bugs, so that may make this harder to find. Those problems are more common than this one when running mmstress.)
|
|
Hi Jinshan,
When a top lock enqueue failed, top lock will go to cl_lock_hold_release() and then unhold a lovsub lock, which will go to osc_lock_cancel(), if at this time the osc lock is used by another IO, then the ldlm lock is not canceled.
do_cancel = (dlmlock->l_readers == 0 &&
dlmlock->l_writers == 0);
ldlm_set_cbpending(dlmlock);
unlock_res_and_lock(dlmlock);
if (do_cancel)
result = ldlm_cli_cancel(&olck->ols_handle, LCF_ASYNC);
}
and the osc lock is detached from the lobsub lock in cl_lock_hold_release()
if (lock->cll_holds == 0) {
CL_LOCK_ASSERT(lock->cll_state != CLS_HELD, env, lock);
if (lock->cll_descr.cld_mode == CLM_PHANTOM ||
lock->cll_descr.cld_mode == CLM_GROUP ||
lock->cll_state != CLS_CACHED)
/*
* If lock is still phantom or grouplock when user is
* done with it---destroy the lock.
*/
lock->cll_flags |= CLF_CANCELPEND|CLF_DOOMED;
if (lock->cll_flags & CLF_CANCELPEND) {
lock->cll_flags &= ~CLF_CANCELPEND;
cl_lock_cancel0(env, lock);
}
if (lock->cll_flags & CLF_DOOMED) {
lock->cll_flags &= ~CLF_DOOMED;
cl_lock_delete0(env, lock);
}
}
Is it possible that the ldlm lock somehow missed the cancel process somewhere so that its last dereference is still missing the destroy flag?
|
|
I happen to be able to reproduce this issue steadily while I was working another one.
After I applied the following patch:
diff --git a/lustre/ldlm/ldlm_lock.c b/lustre/ldlm/ldlm_lock.c
index 214ee8c..2e69ad0 100644
--- a/lustre/ldlm/ldlm_lock.c
+++ b/lustre/ldlm/ldlm_lock.c
@@ -372,12 +372,14 @@ int ldlm_lock_destroy_internal(struct ldlm_lock *lock)
LBUG();
}
+ LDLM_DEBUG(lock, "destroy");
if (ldlm_is_destroyed(lock)) {
LASSERT(cfs_list_empty(&lock->l_lru));
EXIT;
return 0;
}
ldlm_set_destroyed(lock);
+ LDLM_DEBUG(lock, "destroy");
if (lock->l_export && lock->l_export->exp_lock_hash) {
/* NB: it's safe to call cfs_hash_del() even lock isn't
@@ -2169,6 +2171,7 @@ void ldlm_lock_cancel(struct ldlm_lock *lock)
ldlm_resource_unlink_lock(lock);
ldlm_lock_destroy_nolock(lock);
+ LDLM_DEBUG(lock, "destroyed");
if (lock->l_granted_mode == lock->l_req_mode)
ldlm_pool_del(&ns->ns_pool, lock);
diff --git a/lustre/ldlm/ldlm_request.c b/lustre/ldlm/ldlm_request.c
index e140e0f..def3ee5 100644
--- a/lustre/ldlm/ldlm_request.c
+++ b/lustre/ldlm/ldlm_request.c
@@ -1141,6 +1141,7 @@ static __u64 ldlm_cli_cancel_local(struct ldlm_lock *lock)
rc = LDLM_FL_LOCAL_ONLY;
}
ldlm_lock_cancel(lock);
+ LDLM_DEBUG(lock, "client-side cancel completed, rc = %lld", rc);
} else {
if (ns_is_client(ldlm_lock_to_ns(lock))) {
LDLM_ERROR(lock, "Trying to cancel local lock");
diff --git a/lustre/llite/llite_internal.h b/lustre/llite/llite_internal.h
index 92b278e..e9e7053 100644
--- a/lustre/llite/llite_internal.h
+++ b/lustre/llite/llite_internal.h
@@ -1469,7 +1469,7 @@ static inline void cl_isize_unlock(struct inode *inode)
static inline void cl_isize_write_nolock(struct inode *inode, loff_t kms)
{
- LASSERT(down_trylock(&ll_i2info(inode)->lli_size_sem) != 0);
+ i_size_write(inode, kms);
}
diff --git a/lustre/llite/llite_lib.c b/lustre/llite/llite_lib.c
index df421d6..ae53f3d 100644
--- a/lustre/llite/llite_lib.c
+++ b/lustre/llite/llite_lib.c
@@ -1700,25 +1700,29 @@ int ll_statfs(struct dentry *de, struct kstatfs *sfs)
void ll_inode_size_lock(struct inode *inode)
{
+#if 0
struct ll_inode_info *lli;
LASSERT(!S_ISDIR(inode->i_mode));
lli = ll_i2info(inode);
LASSERT(lli->lli_size_sem_owner != current);
- down(&lli->lli_size_sem);
+ LASSERT(lli->lli_size_sem_owner == NULL);
lli->lli_size_sem_owner = current;
+#endif
}
void ll_inode_size_unlock(struct inode *inode)
{
+#if 0
struct ll_inode_info *lli;
lli = ll_i2info(inode);
LASSERT(lli->lli_size_sem_owner == current);
lli->lli_size_sem_owner = NULL;
- up(&lli->lli_size_sem);
+ +#endif
}
void ll_update_inode(struct inode *inode, struct lustre_md *md)
diff --git a/lustre/obdclass/cl_lock.c b/lustre/obdclass/cl_lock.c
index d440da9..b8c2e04 100644
--- a/lustre/obdclass/cl_lock.c
+++ b/lustre/obdclass/cl_lock.c
@@ -493,6 +493,7 @@ static struct cl_lock *cl_lock_lookup(const struct lu_env *env,
const struct cl_io *io,
const struct cl_lock_descr *need)
{
+#if 0
struct cl_lock *lock;
struct cl_object_header *head;
@@ -518,6 +519,7 @@ static struct cl_lock *cl_lock_lookup(const struct lu_env *env,
RETURN(lock);
}
}
+#endif
RETURN(NULL);
}
@@ -1964,6 +1966,8 @@ static struct cl_lock *cl_lock_hold_mutex(const struct lu_env *env,
cl_lock_hold_mod(env, lock, +1);
lu_ref_add(&lock->cll_holders, scope, source);
lu_ref_add(&lock->cll_reference, scope, source);
+
+ cl_lock_cancel(env, lock);
break;
}
cl_lock_mutex_put(env, lock);
And uses 32 processes to read the same file on the same time. The reading process hit the LBUG at the same place:
However, from the log, I can see this:
Both line 375 and 382 in were printed. and the source is as follows:
361 int ldlm_lock_destroy_internal(struct ldlm_lock *lock)
362 {
363 ENTRY;
364
365 if (lock->l_readers || lock->l_writers) {
366 LDLM_ERROR(lock, "lock still has references");
367 LBUG();
368 }
369
370 if (!cfs_list_empty(&lock->l_res_link)) {
371 LDLM_ERROR(lock, "lock still on resource");
372 LBUG();
373 }
374
375 LDLM_DEBUG(lock, "destroy");
376 if (ldlm_is_destroyed(lock)) {
377 LASSERT(cfs_list_empty(&lock->l_lru));
378 EXIT;
379 return 0;
380 }
381 ldlm_set_destroyed(lock);
382 LDLM_DEBUG(lock, "destroy");
However, the destroyed flag was failed to set. This is beyond of my understanding, and we should escalate this issue.
|
|
Full log is here
|
|
I think the prime suspect owuld be some place that updates lock flags without taking lock spinlock. There are several such places.
|
|
I confirmed that changing the dlm flag operation to bitops fixed the problem.
Check the attachment for the concept patch. The real patch should be worked out by modifying lustre/contrib/bit-masks/lustre_dlm_flags.tpl.
diff --git a/lustre/include/lustre_dlm.h b/lustre/include/lustre_dlm.h
index 98e03c9..bf4fb65 100644
--- a/lustre/include/lustre_dlm.h
+++ b/lustre/include/lustre_dlm.h
@@ -772,7 +772,7 @@ struct ldlm_lock {
* Lock state flags. Protected by lr_lock.
* \see lustre_dlm_flags.h where the bits are defined.
*/
- __u64 l_flags;
+ volatile __u64 l_flags;
/**
* Lock r/w usage counters.
diff --git a/lustre/include/lustre_dlm_flags.h b/lustre/include/lustre_dlm_flags.h
index 283546d..4be532f 100644
--- a/lustre/include/lustre_dlm_flags.h
+++ b/lustre/include/lustre_dlm_flags.h
@@ -57,91 +57,91 @@
#define LDLM_FL_LOCK_CHANGED 0x0000000000000001ULL -#define ldlm_is_lock_changed(_l) LDLM_TEST_FLAG(( _l), 1ULL << 0)
-#define ldlm_set_lock_changed(_l) LDLM_SET_FLAG(( _l), 1ULL << 0)
-#define ldlm_clear_lock_changed(_l) LDLM_CLEAR_FLAG((_l), 1ULL << 0)
+#define ldlm_is_lock_changed(_l) LDLM_TEST_FLAG(( _l), 0)
+#define ldlm_set_lock_changed(_l) LDLM_SET_FLAG(( _l), 0)
+#define ldlm_clear_lock_changed(_l) LDLM_CLEAR_FLAG((_l), 0)
......
......
-#define LDLM_TEST_FLAG(_l, _b) (((_l)->l_flags & (_b)) != 0)
+#define LDLM_TEST_FLAG(_l, _b) test_bit(_b, (volatile unsigned long *)&(_l)->l_flags)
#define LDLM_HAVE_MASK(_l, _m) (((_l)->l_flags & LDLM_FL_##_m##_MASK) != 0)
-#define LDLM_SET_FLAG(_l, _b) ((_l)->l_flags |= (_b))
+#define LDLM_SET_FLAG(_l, _b) set_bit(_b, (volatile unsigned long *)&(_l)->l_flags)
-#define LDLM_CLEAR_FLAG(_l, _b) ((_l)->l_flags &= ~(_b))
+#define LDLM_CLEAR_FLAG(_l, _b) clear_bit(_b, (volatile unsigned long *)&(_l)->l_flags)
|
|
Jinshan, according to the comment, the flags should be protected by lr_flags. Are there flag changes not protected by this lock?
Also, I have some concern that using set_bit() will not set the same bits as the Lustre network protocol on all architectures. Do you know if there is a specific bit ordering used in all cases?
|
|
The flags should be protected by ldlm_lock::l_lock. When I saw this issue, my first reaction was to check if there are unprotected writing to l_flags and the only place is:
/**
* Removes LDLM lock \a lock from LRU. Assumes LRU is already locked.
*/
int ldlm_lock_remove_from_lru_nolock(struct ldlm_lock *lock)
{
int rc = 0;
if (!cfs_list_empty(&lock->l_lru)) {
struct ldlm_namespace *ns = ldlm_lock_to_ns(lock);
LASSERT(lock->l_resource->lr_type != LDLM_FLOCK);
cfs_list_del_init(&lock->l_lru);
ldlm_clear_skipped(lock);
LASSERT(ns->ns_nr_unused > 0);
ns->ns_nr_unused--;
rc = 1;
}
return rc;
}
However, it was protected by ns_lock and if the lock is being destroyed, it must have been taken out of LRU list.
|
|
Hi Jinshan,
According to your test results, this problem really looks like a race problem. Would you please try following patch to check that the lock is always held when clearing/setting the flag?
http://review.whamcloud.com/#/c/8772/
|
|
Hi Li Xi,
That looks true. Somehow I looked at the code wrong. The dlm lock was set destroyed flag before taking out of LRU, so ldlm_clear_skipped() in ldlm_lock_remove_from_lru_nolock() is indeed the root cause of this problem.
Your patch will cause deadlock because we should take res lock first and then ns_lock. My idea to fix this problem is to move ldlm_clear_skipped() out of ldlm_lock_remove_from_lru_nolock() into ldlm_lock_add_to_lru_nolock(). I think this will fix the problem as well.
|
|
Ah, yeah, the right lock order is lock->l_lock, res->lr_lock, ns->ns_lock. Thanks for poiting that error out.
We are able to reproduce the problem steadily too. If you could push a patch, we can check whether it helps. I feel that there are more than one place where lock->l_flags is changed without the protection of lock->l_lock.
|
|
Li, Jinshan - Are either of you able to share how you're reproducing this?
|
|
The root cause of this issue is pretty clear.
Bobijam, can you please create a patch for this?
|
|
updated patch http://review.whamcloud.com/#/c/8772/
|
|
Patch landed to Master. Please reopen ticket if more work is needed.
|
|
backport to b2_5:
http://review.whamcloud.com/9346
|
Generated at Sat Feb 10 01:41:12 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
LU-4268-140123-log.tar.gz
analysis.txt