|
Actually, there is a pretty common low level of activity from ldlm_poold, and ptlrpcds appear now and then in top.
|
|
Attaching log files. The following files:
seqio652_lustre.log
seqio542_lustre.log
Were just an "lctl dk" on the nodes that were hung in mount.
This file:
seqio652_lustre2.log
Is "lctl dk" after enabling full debugging and waiting a few seconds.
This file:
seqio542_console_sysrq.log
I did both "l" and "t" sysrq and captured the console output.
|
|
At first glance, this looks like a duplicate of LU-2263.
|
|
Perhaps related, but in this instance there is no significant lock contention when I log in. CPU usage is very low. My understanding from LU-2263 is that the node has very high load due to lock contention.
|
|
But there definitely was significant lock contention at some point, 68 seconds worth according to the message. Perhaps you caught it and logged in just as it cleared up? Or I may have mis-characterized the "locking up" part in the description of LU-2263.
Either way, it appears to be contending on an (the same?) import lock as in LU-2263:
lustre/ptlrpc/pinger.c:
|
|
If this is deemed a different issue that LU-2263, I probably incorrectly resolved LU-2141.
|
|
Alex will triage this one
|
|
I'm looking at the seqio542_console_sysrq.log file..
The mount.lustre task is sleeping:
The dump of the active CPUs shows two threads stuck on the import lock I detailed above. The "important" one (I think) is below:
So it looks like, one thread is stuck in ptlrpc_pinger_process_import spinning on the imp->imp_lock while still holding the pinger_mutex, as a result mount.lustre gets stuck in ptlrpc_pinger_add_import waiting to obtain the pinger_mutex which is held by the other thread spinning on the import lock.
The question that remains to be answered is, why in the active thread spinning on imp->imp_lock in the first place?
|
|
I do not see any processes spinning when I run "top", so I don't think we have anyone stuck waiting on a spin lock. I may have just caught it when it happened to be grabbing the lock. Or the stack may not be entirely reliable.
|
|
But.. But.. The console messages.. The kernel was just mistaken about the thread being stuck for so long?
top and the console seem to be at odds.. Personally I'd trust the kernel messages, but I can't back up that claim.
|
|
soft lockups are often not a permanent situation. I don't suspect that ll_ping is permanently stuck. I saw it appear in top occasionally, as you normally would on an otherwise idle system. But I'm pretty sure it is not stuck permanently on a single spin lock.
|
|
Liang, can you please look this one over?
|
|
I think this is different with LU-2263. There are only two threads are spinning on imp_lock, one is ptlrpc_main, the other is ptlrpcd()->ptlrpc_check_set(). imp_lock is a heavy contention lock, but I can't explain why both threads are spinning on it but no thread actually hold it.
I will update you if I found something later.
|
|
Christopher, Prakash, could you translace ptlrpc_check_set+0x4f4 to the source line, please?
|
|
I'm taking this from the description in LU-2263:
|
|
I think this is just another symptom of LU-2263 - the pinger got stuck awaiting for imp_lock and holding pinger_mutex. then mount got stuck awaiting for pinger_mutex.
though one thing in the log doesn't quite fit the theory:
2012-11-14 14:08:38.748069
{DefaultControlEventListener} [mmcs]{549}.8.1: BUG: soft lockup - CPU#33 stuck for 68s! [ll_ping:3244]
...
2012-11-14 14:32:16.108436 {DefaultControlEventListener}
[mmcs]
{549}
.0.1: SysRq : Show backtrace of all active CPUs
so, we had no "soft lockup" messages for ~24min while they are supposed to repeat every ~67s if the thread is making no progress.
also I'd say there should be tiny or zero contention at this point: we're in the middle of mount, the only possible activity is connect and/or ping.
it'd be interesting to have a dump and see details of import/lock.
|
|
We don't have kdump enabled on these systems, but I can try to collect a lustre debug log if that is helpful. Will that contain the information we need (i.e. who is holding the lock)?
Also, will the "soft lockup" message repeat for the same thread? I had thought it would only print once for each thread, I could be wrong though.
|
|
yes, I verified that the message will be printed few times with a simple while(1); in the module.
BUG: soft lockup - CPU#0 stuck for 67s! [osp-syn-0:3547]
...
BUG: soft lockup - CPU#0 stuck for 67s! [osp-syn-0:3547]
...
BUG: soft lockup - CPU#0 stuck for 67s! [osp-syn-0:3547]
btw, was the kernel compiled with CONFIG_DEBUG_SPINLOCK ? this would let us to exclude some basic problems at least (like recursive locks).
|
|
Unfortunately, it does not have CONFIG_DEBUG_SPINLOCK enabled. When trying to enable various kernel config options, I run into boot issues. So far, I've only been able to successfully enable CONFIG_DEBUG_SPINLOCK_SLEEP. I'll look into getting CONFIG_DEBUG_SPINLOCK enabled again, next time we get time on Sequoia.
|
|
please consider CONFIG_LOCK_STAT to collect stats on the locking.
|
|
http://review.whamcloud.com/#change,4808 - the purpose of this debug patch is to make sure this is not ptlrpc_check_set() itself taking too long due to lots of requests.
|
|
Alex, I'll pull that in.
|
|
Ok, I believe that we're stuck in spin locks now. It turns out that "top" isn't reporting our spinning threads on the ppc64 nodes for some reason. But when I make my terminal tall enough to fit the 68 processors, I see 4 of the 68 processors at 100% usage. Two of the 4 match up with IBM processes that always spin by design (polling their network) on cpus 66 and 67. The other two match up with the cpus that sysrq-l lists as stuck in Lustre code:
and
The former process is ptlrpcd_rcv and the latter is ll_ping.
These are, not at all coincidentally, the two processes for which there were soft lockup reports on the console:
Alex, we have the 4808 patch applied, but I do not see the message from that on the console.
|
|
ok, thanks for the update. could you verify with gdb this is exactly the same place again?
|
|
Yes, ll_ping is stuck in the first spin_lock() at the beginning of ptlrpc_pinger_process_import, and ptlrpc_rcv is stuck in the spin_lock() in ptlrpc_check_set() right before the "/* Request already may be not".
The same places that Prakash noted in earlier comments.
|
|
got it, thanks. it would be ideal to try with a debug-enabled kernel.. in the meantime I'll try to cook a local debug patch. sorry, but I still have no any good idea what's happening here.
|
|
We have about as much kernel debugging enabled as we can. Crash doesn't work on these ppc64 nodes, and the kernel won't boot when many of the kernel debugging options are enabled. We'll add anything else that we can get to work, but I wouldn't plan on getting more.
|
|
this patch fixed a deadlock for ptlrpc: http://review.whamcloud.com/#change,4880 , hope it can be helpful for this too.
|
|
this patch should dump request/import information if the lock can't be acquired in 5s: http://review.whamcloud.com/4881
it would be great to give it a spin along with Liang's patch, if possible.
|
|
Liang, Alex, I pulled in those two patches (with a small tweak to 4881). It will probably be a week or two until we get time on the machine again to test them out.
|
|
Testing lustre 2.3.58-4chaos, we hit the mount hang.
The console shows:
See the attached lustre log file "lustre-log.1357681275.3261.txt".
|
|
00000100:00020000:2.0:1357681275.788314:1632:3261:0:(client.c:1797:ptlrpc_check_set()) import c0000003ce3c7000, obd c0000003ce29fc80, imp_lock = 2147483654
(gdb) p/x 2147483654
$1 = 0x80000006
#ifdef CONFIG_PPC64
/* use 0x800000yy when locked, where yy == CPU number */
#define LOCK_TOKEN (*(u32 *)(&get_paca()->lock_token))
so, imp_lock was held by cpu #6, which later was reported with:
2013-01-08 13:42:23.488699
{DefaultControlEventListener}
[mmcs]
{592}
.1.2: BUG: soft lockup - CPU#6 stuck for 68s! [ll_ping:3278]
this mean either CPU#6 is trying to acquire imp_lock recursively (unlikely, the code is easy to follow) or CPU#6 has scheduled out a thread holding imp_lock and is running the pinger.
|
|
I have enabled CONFIG_DEBUG_SPINLOCK on these kernels, but was unable to turn on CONFIG_LOCK_STAT.
Chris, the next time we hit this, can you log into the node and check the console. If we schedule while holding a spin lock, it should print this message:
This should also make it to the logs, but I don't trust the way we filter some messages out.
|
|
oh, great news. thanks, Prakash!
|
|
I've landed http://review.whamcloud.com/#change,4880 to master.
|
|
Andreas, it seems 4880 didn't help in this case, see comment from Dec 28
|
|
So, during testing yesterday I looped through many mount/unmounts of the file system on each of the Sequoia IONs running 2.3.58-5chaos and didn't run into a single hang. This is confusing because Chris noted that we hit the hang on 2.358-4chaos, and not much has changed between the two tags:
Also, I looked into the kernel sources some more, and contrary to my comment above, I don't think anything will be printed to the console if we schedule while holding a spinlock. The lines I quoted above only print if might_sleep is called, and the message printed from within schedule_debug is only printed if CONFIG_PREEMPT is enabled (which is not on the IONs).
|
|
Lowered priority on this one. We haven't seen the problem in a couple of weeks. Not entirely sure why/where it could have been fixed, but this is not going to get our attention if we don't see it again.
|
|
Had some evidence that this problem is still hitting. Of course, the debugging patch itself is fatal (calls LBUG()), so I'm not 100% sure that the problem wasn't just the debug patch itself. I modified the debug patch to print the debug message and drop a backtrace, but not LBUG.
But sadly, I don't think this bug fixed itself. 
|
|
I've bumped the priority of this back to "Blocker" status as we've hit this a number of times today, running 2.3.58-12chaos.
We've modified the debug patch a bit, but it's basically shows the same information. A few example messages from the logs:
It's interesting to note the raw_lock.slock value is slightly different in these two messages. It's hex value is: 2147483652 = 0x80000004 != 2147483655 = 0x80000007.
|
|
Christopher, do you think the system get back to "normal" after you removed LBUG() ? or those threads keep spinning on the locks forever?
Prakash, the values different because locks belong to different imports, so they different as different their current owner (CPU#4 and CPU#7).
|
|
It hit again after removing the LBUG(), so now I can definitively say that the two threads get stuck spinning on a spin lock indefinitely.
|
|
OK, then there should be a list of the backtraces ?
|
|
Please see the attached files seqio162_console.txt (contains sysrq-l and sysrq-t backtraces) and seqio162_lustre_log.txt.
|
|
ok, thanks... are you still running on the kernel with CONFIG_DEBUG_SPINLOCK ? if so, let's drop that lustre patch and try to see an owner?
|
|
Unfortunately, CONFIG_DEBUG_SPINLOCK was dropped when we upgraded the kernel a couple weeks ago. I need to talk to the admins about why they dropped it, and if it can get enabled again. I'm also interested in finding out who the owner is.
|
|
Yes, when we went to the RHEL6.3 kernel on Sequoia last Thursday, we lost CONFIG_DEBUG_SPINLOCK. Apparently the kernel would no longer operate with that enabled, as we've seen with other debug settings.
|
|
any chance to get it back ?
|
|
I'm not sure yet, I need to get a test machine to play around with the kernel and determine what the underlying issue is with that option set. Pending work to be done. Is that the best option available to us? I'd imagine knowing what the "owner" field is would tell us a lot.
|
|
well, I've read through the code few times yet. Liang did as well. still no idea how do we get into this.. sorry. I hoped to get a hint from the kernel.
|
|
Alex, we've re-enabled CONFIG_DEBUG_SPINLOCK on the ION kernels. I've added a patch to print out the void *owner, int magic, and int owner_cpu fields of the spinlock_t when the "spinning" message is printed. Is there any other information I should print when this hits? Or any other debugging info that would be useful?
|
|
I've tried reproducing the hang with CONFIG_DEBUG_SPINLOCK enabled, but haven't been able to trigger it.
|
|
Have you been able to reproduce this issue? Or should we close this ticket and reopen if it occurs again?
|
|
We seem to have the problem that enabling kernel spin lock debugging makes the problem go away. I think that explains why we had a period of time before that the problem went away as well.
So I would say that the ticket should remain open, because there seems to be a lustre race here somewhere. But the priority can be dropped in favor of other things that are more pressing.
|
|
This is still a problem. Unfortunately, we never seem to hit the problem while CONFIG_DEBUG_SPINLOCK is enabled, but it hits fairly frequently with it disabled.
In the latest occurance that I investigated yesterday, I see the following stacks:
CPU1:
It appears to be stuck spinning on the "while (spin_trylock (&imp->imp_lock)" line.
CPU5:
It is spinning on "spin_lock(&imp->imp_lock)" in ptlrpc_pinger_process_import(), which holding the pinger mutex.
Not spinning, but stuck sleeping on the pinger mutex is the mount.lustre process:
But mount.lustre waiting on the mutex is understood since the other thread is holding it. We still need to understand who is holding the import spin lock.
Looking our debugging statement ("spinning too long"), I see that the value of the spin lock is 2147483652. In hex, that is:
Looking at the Linux kernel PowerPC spin lock code, I see that when lock is set, the least significant byte is set to the CPU number. So the lock value looks correct, and apparently the lock was taken on a CPU that is not currently in use by any processes.
So that is just seems to further support the assumption that Lustre is failing to unlock the imp_lock somewhere.
|
Generated at Sat Feb 10 01:24:16 UTC 2024 using Jira 9.4.14#940014-sha1:734e6822bbf0d45eff9af51f82432957f73aa32c.
lustre-log.1357681275.3261.txt
seqio542_console_sysrq.log