Lustre discuss - Nov 2008 - MDS: lock timed out -- not entering recovery in server code, just going back to sleep

Hi all,

after some nasty problems with network switches we see repeated hangs of 
our Lustre system. On a client, "lfs check mds" will say
 > error: check ''lustre-MDT0000-mdc-ffff810419da5800'':
Resource
temporarily unavailable (11)
All our OSS are doing o.k. The MDS itself seems to be o.k, too - no 
error messages in the logs directly related to this situation, but also 
nothing that would indicate that the MDT had taken notice of a client 
trying to reconnect, not even when trying to mount the  FS on a new 
client. The MDT had just become unresponsive.
Since nothing goes in such a situation anyhow, we rebooted the MDS. 
After recovery, the clients reconnect, the FS seems to be fine again.
However, the MDT is dumping log like crazy - a few times per minute, and 
most dumps are empty.
In addition, in the logs I find a lot of

 > Nov 27 17:57:41 lustre kernel: LustreError: 
3974:0:(ldlm_request.c:64:ldlm_expired_completion_wait()) ### lock timed 
out (enqueued
 > at 1227804060, 1001s ago); not entering recovery in server code, just 
going back to sleep ns: mds-lustre-MDT0000_UUID lock:
 > e4f54680/0x2ccbde901a8157f2 lrc: 3/1,0 mode: --/CR res: 
74908813/3524601089 bits 0x2 rrc: 173 type: IBT flags: 4004030 remote:
 > 0x0 expref: -99 pid 3974

My question is now whether you would interpret this as a result of 
ongoing trouble with the network  - or is it a sign of MDT-illness?


There are more disturbing log messages, many of the following type:

 > Nov 27 18:17:42 lustre kernel: LustreError: 
28521:0:(mds_open.c:1474:mds_close()) @@@ no handle for file close ino 
81208923:
 >  cookie 0x2ccbde8fcca85aa7  req at f3e75800 x1686877/t0
 > o35->e0c12120-24ea-68c2-0394-712e75354f55 at
NET_0x200008cb5726e_UUID:-1
lens 296/3472 ref 0 fl Interpret:/0/0 rc 0/0


What to make of that?

Hm, the MDS is running Lustre v 1.6.3, the OSS 1.6.4.2, the clients 
1.6.5 - may not be the most healthy mix, either?

Thanks,
Thomas

On Thu, 2008-11-27 at 19:18 +0100, Thomas Roth wrote:
> 
>  > Nov 27 17:57:41 lustre kernel: LustreError: 
> 3974:0:(ldlm_request.c:64:ldlm_expired_completion_wait()) ### lock timed 
> out (enqueued
>  > at 1227804060, 1001s ago); not entering recovery in server code, just
> going back to sleep ns: mds-lustre-MDT0000_UUID lock:
>  > e4f54680/0x2ccbde901a8157f2 lrc: 3/1,0 mode: --/CR res: 
> 74908813/3524601089 bits 0x2 rrc: 173 type: IBT flags: 4004030 remote:
>  > 0x0 expref: -99 pid 3974
> 
> My question is now whether you would interpret this as a result of 
> ongoing trouble with the network
Yes, network problems are a common cause of this.
> There are more disturbing log messages, many of the following type:
> 
>  > Nov 27 18:17:42 lustre kernel: LustreError: 
> 28521:0:(mds_open.c:1474:mds_close()) @@@ no handle for file close ino 
> 81208923:
>  >  cookie 0x2ccbde8fcca85aa7  req at f3e75800 x1686877/t0
>  > o35->e0c12120-24ea-68c2-0394-712e75354f55 at
NET_0x200008cb5726e_UUID:-1
> lens 296/3472 ref 0 fl Interpret:/0/0 rc 0/0
There was a description of that here or in bugzilla not that long ago.
IIRC it''s the result of a recovery operations where the MDS performs a
close on a file on behalf of a disconnected client and then the client
comes along and tries to explicitly close the file but the MDS has
already done it for it.

b.

-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 197 bytes
Desc: This is a digitally signed message part
Url :
http://lists.lustre.org/pipermail/lustre-discuss/attachments/20081127/4593ef5d/attachment.bin

Brian J. Murrell wrote:
> On Thu, 2008-11-27 at 19:18 +0100, Thomas Roth wrote:
>>  > Nov 27 17:57:41 lustre kernel: LustreError: 
>> 3974:0:(ldlm_request.c:64:ldlm_expired_completion_wait()) ### lock
timed
>> out (enqueued
>>  > at 1227804060, 1001s ago); not entering recovery in server code,
just
>> going back to sleep ns: mds-lustre-MDT0000_UUID lock:
>>  > e4f54680/0x2ccbde901a8157f2 lrc: 3/1,0 mode: --/CR res: 
>> 74908813/3524601089 bits 0x2 rrc: 173 type: IBT flags: 4004030 remote:
>>  > 0x0 expref: -99 pid 3974
>>
>> My question is now whether you would interpret this as a result of 
>> ongoing trouble with the network
> 
> Yes, network problems are a common cause of this.
> 
>> There are more disturbing log messages, many of the following type:
>>
>>  > Nov 27 18:17:42 lustre kernel: LustreError: 
>> 28521:0:(mds_open.c:1474:mds_close()) @@@ no handle for file close ino 
>> 81208923:
>>  >  cookie 0x2ccbde8fcca85aa7  req at f3e75800 x1686877/t0
>>  > o35->e0c12120-24ea-68c2-0394-712e75354f55 at
NET_0x200008cb5726e_UUID:-1
>> lens 296/3472 ref 0 fl Interpret:/0/0 rc 0/0
> 
> There was a description of that here or in bugzilla not that long ago.
> IIRC it''s the result of a recovery operations where the MDS
performs a
> close on a file on behalf of a disconnected client and then the client
> comes along and tries to explicitly close the file but the MDS has
> already done it for it.
> 
> b.
> 
Thanks Brian - for a while we could blame network for our problems with 
the MDS.

However in the meantime, things got worse. We now see this kind of hang 
on the MDS every day - the rest of our servers/network doing fine all 
the time.
Twice we hit an LBUG:

Dec  1 22:14:17 lustre2 kernel: LustreError: 
14714:0:(mds_reint.c:1512:mds_orphan_add_link()) 
ASSERTION(inode->i_nlink == 1) failed:dir nlink == 0
Dec  1 22:14:17 lustre2 kernel: LustreError: 
14714:0:(mds_reint.c:1512:mds_orphan_add_link()) LBUG
Dec  1 22:14:17 lustre2 kernel: Lustre: 
14714:0:(linux-debug.c:168:libcfs_debug_dumpstack()) showing stack for 
process 14714
Dec  1 22:14:17 lustre2 kernel: ll_mdt_69     R running     0 14714 
  1         14715 14713 (L-TLB)
Dec  1 22:14:17 lustre2 kernel: 00000019 00000018 c3635000 c0204fb4 
00000001 00000001 00000000 c3635000
Dec  1 22:14:17 lustre2 kernel: c3635000 00000018 00000000 c020502e 
00000001 00000000 c020872a c0364a82
Dec  1 22:14:17 lustre2 kernel: 0a01ffff 00000000 c02dac00 c020851e 
00047c05 00047c62 c011d553 00047c62
Dec  1 22:14:17 lustre2 kernel: Call Trace:
Dec  1 22:14:17 lustre2 kernel: [<c0204fb4>] scrup+0x58/0xba
Dec  1 22:14:17 lustre2 kernel: [<c011de22>] printk+0x14/0x18
Dec  1 22:14:17 lustre2 kernel: [<c0136851>] __print_symbol+0x9f/0xa8
Dec  1 22:14:17 lustre2 kernel: [<c01cbbe8>] vgacon_scroll+0x17a/0x195
Dec  1 22:14:17 lustre2 kernel: [<c01ba234>] vsnprintf+0x419/0x457
Dec  1 22:14:17 lustre2 kernel: [<c01ba234>] vsnprintf+0x419/0x457
Dec  1 22:14:17 lustre2 kernel: [<c011672a>] __wake_up_locked+0x11/0x15
Dec  1 22:14:17 lustre2 kernel: [<c01b932b>] __down_trylock+0x3b/0x44
Dec  1 22:14:17 lustre2 kernel: [<c01b932b>] __down_trylock+0x3b/0x44
Dec  1 22:14:17 lustre2 kernel: [<c027f977>] __down_failed_trylock+0x7/0xc
Dec  1 22:14:17 lustre2 kernel: [<c011d822>]
release_console_sem+0x182/0x1bc
Dec  1 22:14:17 lustre2 kernel: [<c011d822>]
release_console_sem+0x182/0x1bc
Dec  1 22:14:17 lustre2 kernel: [<c012c6d8>]
__kernel_text_address+0x18/0x23
Dec  1 22:14:17 lustre2 kernel: [<c0103b62>] show_trace_log_lvl+0x47/0x6a
Dec  1 22:14:17 lustre2 kernel: [<c0103c13>] show_stack_log_lvl+0x8e/0x96
Dec  1 22:14:17 lustre2 kernel: [<c0104107>] show_stack+0x20/0x25
Dec  1 22:14:17 lustre2 kernel: [<fa1b7f79>] lbug_with_loc+0x69/0xc0 
[libcfs]
Dec  1 22:14:17 lustre2 kernel: [<fa682448>] 
mds_orphan_add_link+0xcb8/0xd20 [mds]
Dec  1 22:14:17 lustre2 kernel: [<fa69587a>] 
mds_reint_unlink+0x292a/0x3fd0 [mds]
Dec  1 22:14:17 lustre2 kernel: [<fa3a5990>] 
lustre_swab_ldlm_request+0x0/0x20 [ptlrpc]
Dec  1 22:14:17 lustre2 kernel: [<fa681495>] mds_reint_rec+0xf5/0x3f0
[mds]
Dec  1 22:14:17 lustre2 kernel: [<fa664feb>] mds_reint+0xcb/0x8a0 [mds]
Dec  1 22:14:17 lustre2 kernel: [<c01171b2>]
find_busiest_group+0x177/0x46a
Dec  1 22:14:17 lustre2 kernel: [<fa678998>] mds_handle+0x3048/0xb9df
[mds]
Dec  1 22:14:17 lustre2 kernel: [<c0124d83>] do_gettimeofday+0x31/0xce
Dec  1 22:14:17 lustre2 kernel: [<fa2d506b>] 
class_handle2object+0xbb/0x2a0 [obdclass]
Dec  1 22:14:17 lustre2 kernel: [<fa3a5a00>] 
lustre_swab_ptlrpc_body+0x0/0xc0 [ptlrpc]
Dec  1 22:14:17 lustre2 kernel: [<fa3a2b5a>] lustre_swab_buf+0xfa/0x180 
[ptlrpc]
Dec  1 22:14:17 lustre2 kernel: [<c0125aac>] lock_timer_base+0x15/0x2f
Dec  1 22:14:17 lustre2 kernel: [<c0125bbd>] __mod_timer+0x99/0xa3
Dec  1 22:14:17 lustre2 kernel: [<fa39fefe>] 
lustre_msg_get_conn_cnt+0xce/0x220 [ptlrpc]
Dec  1 22:14:17 lustre2 kernel: [<fa3b1e56>] ptlrpc_main+0x2016/0x2f40 
[ptlrpc]
Dec  1 22:14:17 lustre2 kernel: [<c0117c1f>] default_wake_function+0x0/0xc
Dec  1 22:14:17 lustre2 kernel: [<fa3afe40>] ptlrpc_main+0x0/0x2f40
[ptlrpc]
Dec  1 22:14:17 lustre2 kernel: [<c0101005>] kernel_thread_helper+0x5/0xb



After booting the machine, Lustre complains:
Dec  2 09:19:44 lustre2 kernel: Lustre: 
3880:0:(class_hash.c:159:lustre_hash_additem_unique()) Already found the 
key in hash [UU
ID_HASH]
Dec  2 09:19:44 lustre2 kernel: Lustre: 
3880:0:(genops.c:686:class_new_export()) alilust-MDT0000: denying 
duplicate export for a
e7199dc-a53f-c901-f07c-87b4285fb7af


This is about the only unusual error message in the log - in addition to 
the ''operation X on unconnected MDS'' messages and the high
frequency of
(empty) log dumping.

Any ideas what''s going on here?

Thanks,
Thomas