import
note
[LU-6991] LBUG in ptlrpc_connection_put(): ASSERTION( atomic_read(&conn->c_refcount) > 1 ) Created: 12/Aug/15 Updated: 11/Feb/16 Resolved: 11/Feb/16 |
|
| Status: | Resolved |
| Project: | Lustre |
| Component/s: | None |
| Affects Version/s: | Lustre 2.5.4 |
| Fix Version/s: | None |
| Type: | Bug | Priority: | Major |
| Reporter: | Bruno Travouillon (Inactive) | Assignee: | Alex Zhuravlev |
| Resolution: | Cannot Reproduce | Votes: | 0 |
| Labels: | None | ||
| Environment: |
RHEL6.6 + Lustre 2.5.3.90 w/ bull patches |
||
| Attachments: |
import
note
|
| Severity: | 3 |
| Rank (Obsolete): | 9223372036854775807 |
| Description |
|
We hit the following LBUG on one of our MDS. <3>LustreError: 12255:0:(sec.c:379:import_sec_validate_get()) import ffff880903ac1000 (FULL) with no sec
<0>LustreError: 19842:0:(connection.c:104:ptlrpc_connection_put()) ASSERTION( atomic_read(&conn->c_refcount) > 1 ) failed:
<0>LustreError: 19842:0:(connection.c:104:ptlrpc_connection_put()) LBUG
<4>Pid: 19842, comm: obd_zombid
<4>
<4>Call Trace:
<4> [<ffffffffa04f2895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
<4> [<ffffffffa04f2e97>] lbug_with_loc+0x47/0xb0 [libcfs]
<4> [<ffffffffa082938b>] ptlrpc_connection_put+0x1db/0x1e0 [ptlrpc]
<4> [<ffffffffa066c70d>] class_import_destroy+0x5d/0x420 [obdclass]
<4> [<ffffffffa067067b>] obd_zombie_impexp_cull+0xcb/0x5d0 [obdclass]
<4> [<ffffffffa0670be5>] obd_zombie_impexp_thread+0x65/0x190 [obdclass]
<4> [<ffffffff81064bc0>] ? default_wake_function+0x0/0x20
<4> [<ffffffffa0670b80>] ? obd_zombie_impexp_thread+0x0/0x190 [obdclass]
<4> [<ffffffff8109e71e>] kthread+0x9e/0xc0
<4> [<ffffffff8100c20a>] child_rip+0xa/0x20
<4> [<ffffffff8109e680>] ? kthread+0x0/0xc0
<4> [<ffffffff8100c200>] ? child_rip+0x0/0x20
<4>
<0>Kernel panic - not syncing: LBUG
<4>Pid: 19842, comm: obd_zombid Not tainted 2.6.32-504.16.2.el6.Bull.74.x86_64 #1
<4>Call Trace:
<4> [<ffffffff8152a2bd>] ? panic+0xa7/0x16f
<4> [<ffffffffa04f2eeb>] ? lbug_with_loc+0x9b/0xb0 [libcfs]
<4> [<ffffffffa082938b>] ? ptlrpc_connection_put+0x1db/0x1e0 [ptlrpc]
<4> [<ffffffffa066c70d>] ? class_import_destroy+0x5d/0x420 [obdclass]
<4> [<ffffffffa067067b>] ? obd_zombie_impexp_cull+0xcb/0x5d0 [obdclass]
<4> [<ffffffffa0670be5>] ? obd_zombie_impexp_thread+0x65/0x190 [obdclass]
<4> [<ffffffff81064bc0>] ? default_wake_function+0x0/0x20
<4> [<ffffffffa0670b80>] ? obd_zombie_impexp_thread+0x0/0x190 [obdclass]
<4> [<ffffffff8109e71e>] ? kthread+0x9e/0xc0
<4> [<ffffffff8100c20a>] ? child_rip+0xa/0x20
<4> [<ffffffff8109e680>] ? kthread+0x0/0xc0
<4> [<ffffffff8100c200>] ? child_rip+0x0/0x20
It appears that the MDS was overloaded at that time. crash> sys
KERNEL: /usr/lib/debug/lib/modules/2.6.32-504.16.2.el6.Bull.74.x86_64/vmlinux
DUMPFILE: vmcore [PARTIAL DUMP]
CPUS: 32
DATE: Sun Jun 7 06:41:03 2015
UPTIME: 4 days, 19:14:07
LOAD AVERAGE: 646.72, 556.57, 328.17
TASKS: 2556
NODENAME: mds111
RELEASE: 2.6.32-504.16.2.el6.Bull.74.x86_64
VERSION: #1 SMP Tue Apr 28 01:43:42 CEST 2015
MACHINE: x86_64 (2266 Mhz)
MEMORY: 64 GB
PANIC: "Kernel panic - not syncing: LBUG"
You will find attached some traces of my analysis of the vmcore. The customer is a blacksite, I can't provide the vmcore. It appears that the import involved in the LBUG is ffff880903ac1000. In the console, right before the LBUG, we can observe a LustreError involving the same import. It is also reported in the debug log: 02000000:00020000:28.0F:1433652063.227347:0:12255:0:(sec.c:379:import_sec_validate_get()) import ffff880903ac1000 (FULL) with no sec
00000100:00040000:28.0:1433652063.248671:0:19842:0:(connection.c:104:ptlrpc_connection_put()) ASSERTION( atomic_read(&conn->c_refcount) > 1 ) failed:
00000100:00040000:28.0:1433652063.259452:0:19842:0:(connection.c:104:ptlrpc_connection_put()) LBUG
This import is Lustre client compute2823. Here is the console output of the compute node: 00000001:02000400:11.0:1433651401.837787:0:30301:0:(debug.c:339:libcfs_debug_mark_buffer()) DEBUG MARKER: Sun Jun 7 06:30:01 2015 00000001:02000400:11.0:1433651701.267541:0:31155:0:(debug.c:339:libcfs_debug_mark_buffer()) DEBUG MARKER: Sun Jun 7 06:35:01 2015 00000001:02000400:10.0:1433652001.829909:0:31973:0:(debug.c:339:libcfs_debug_mark_buffer()) DEBUG MARKER: Sun Jun 7 06:40:01 2015 00000800:00020000:31.0:1433652118.496756:0:15908:0:(o2iblnd_cb.c:3018:kiblnd_check_txs_locked()) Timed out tx: tx_queue, 4 seconds 00000800:00020000:31.0:1433652118.505625:0:15908:0:(o2iblnd_cb.c:3081:kiblnd_check_conns()) Timed out RDMA with X.Y.Z.42@o2ib11 (54): c: 0, oc: 0, rc: 8 00000100:00000400:19.0:1433652118.517268:0:15965:0:(client.c:1942:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1433652063/real 1433652118] req@ffff880c0cdf1400 x1502885054441032/t0(0) o103->ptmp2-MDT0000-mdc-ffff88047c753800@X.Y.Z.42@o2ib11:17/18 lens 328/224 e 0 to 1 dl 1433652672 ref 1 fl Rpc:X/2/ffffffff rc -11/-1 00000100:00000400:7.0:1433652118.518199:0:15961:0:(client.c:1942:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1433652063/real 1433652118] req@ffff880a81a1b800 x1502885054432068/t0(0) o103->ptmp2-MDT0000-mdc-ffff88047c753800@X.Y.Z.42@o2ib11:17/18 lens 328/224 e 0 to 1 dl 1433652672 ref 1 fl Rpc:X/2/ffffffff rc -11/-1 00000100:00000400:3.0:1433652118.518222:0:15945:0:(client.c:1942:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1433652063/real 1433652118] req@ffff8805270aa800 x1502885054436340/t0(0) o103->ptmp2-MDT0000-mdc-ffff88047c753800@X.Y.Z.42@o2ib11:17/18 lens 328/224 e 0 to 1 dl 1433652672 ref 1 fl Rpc:X/2/ffffffff rc -11/-1 00000100:00000400:10.0:1433652118.518231:0:15960:0:(client.c:1942:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1433652063/real 1433652118] req@ffff880c02ee5c00 x1502885054439124/t0(0) o103->ptmp2-MDT0000-mdc-ffff88047c753800@X.Y.Z.42@o2ib11:17/18 lens 328/224 e 0 to 1 dl 1433652672 ref 1 fl Rpc:X/2/ffffffff rc -11/-1 00000100:00000400:27.0:1433652118.518233:0:15949:0:(client.c:1942:ptlrpc_expire_one_request()) @@@ Request sent has failed due to network error: [sent 1433652063/real 1433652118] req@ffff880a85e69800 x1502885054432296/t0(0) o103->ptmp2-MDT0000-mdc-ffff88047c753800@X.Y.Z.42@o2ib11:17/18 lens 328/224 e 0 to 1 dl 1433652672 ref 1 fl Rpc:X/2/ffffffff rc -11/-1 [...] 00000100:02020000:14.0:1433653897.305027:0:15941:0:(import.c:1359:ptlrpc_import_recovery_state_machine()) 167-0: ptmp2-MDT0000-mdc-ffff88047c753800: This client was evicted by ptmp2-MDT0000; in progress operations using this service will fail. This client has been evicted by the failover MDS. This is the only client we found evicted. We also have a vmcore for this node. 06/08/2015 06:46 AM compute2823: /proc/fs/lustre/mdc/ptmp2-MDT0000-mdc-ffff88047c753800/state:current_state: EVICTED I have not been able to understand the root cause of the LBUG. Please let me know if you need further details. |
| Comments |
| Comment by Peter Jones [ 12/Aug/15 ] |
|
Hongchao Could you please help with this issue? Thanks Peter |
| Comment by Hongchao Zhang [ 13/Aug/15 ] |
|
Thanks for your detailed analysis! I looked at the related codes, this obd_import could be the "obd_export->exp_imp_reverse", and it was used by "ldlm_server_blocking_ast" int target_handle_connect(struct ptlrpc_request *req)
{
...
spin_lock(&export->exp_lock);
if (export->exp_imp_reverse != NULL)
/* destroyed import can be still referenced in ctxt */
tmp_imp = export->exp_imp_reverse;
export->exp_imp_reverse = revimp;
spin_unlock(&export->exp_lock);
...
if (tmp_imp != NULL)
client_destroy_import(tmp_imp);
...
}
the "imp_sec" was cleaned up in "client_destroy_import", then "import ffff880903ac1000 (FULL) with no sec" error is shown. but it is still unknown why this LASSERT is triggered and the "c_refcount" in the vmcore is NOT zero (it's 3)! crash> struct ptlrpc_connection 0xffff880b157a7540
struct ptlrpc_connection {
c_hash = {
next = 0xffff880496d62b40,
pprev = 0xffff8803242fdd00
},
c_self = 1407422302593066,
c_peer = {
nid = 1407422302596706,
pid = 12345
},
c_remote_uuid = {
uuid = "NET_0x5000OBFUSCATE_UUID\000\000\000\000\000\000\000\000\000\000\000\000\000\000\000"
},
c_refcount = {
counter = 3
}
}
|
| Comment by Hongchao Zhang [ 20/Aug/15 ] |
|
Is the address of MDS is different from that of the evicted client? when did the LBUG occurs? in normal operations or during failing over to another MDS? |
| Comment by Bruno Travouillon (Inactive) [ 21/Aug/15 ] |
|
LBUG occurs during normal operation. However, we can notice the increasing LOAD AVERAGE: 646.72, 556.57, 328.17 in the crash. I will try to get the debug log from the crash if it can help. Once mds111 panic, the MDT has been failover to mds110. compute2823 has been evicted by mds110 (failover). 00000100:02020000:14.0:1433653897.305027:0:15941:0:(import.c:1359:ptlrpc_import_recovery_state_machine()) 167-0: ptmp2-MDT0000-mdc-ffff88047c753800: This client was evicted by ptmp2-MDT0000; in progress operations using this service will fail. The nid of mds111 is X.Y.Z.42@o2ib11, as seen in the compute2823 console: 00000800:00020000:31.0:1433652118.505625:0:15908:0:(o2iblnd_cb.c:3081:kiblnd_check_conns()) Timed out RDMA with X.Y.Z.42@o2ib11 (54): c: 0, oc: 0, rc: 8 The nid of the evicted client is X.Y.46.98@o2ib11. |
| Comment by Peter Jones [ 26/Aug/15 ] |
|
Alex Could you please assist with this issue? Thanks Peter |
| Comment by Bruno Travouillon (Inactive) [ 02/Sep/15 ] |
|
Alex, Do you need more info on this one ? |
| Comment by Alex Zhuravlev [ 10/Sep/15 ] |
|
is it possible to run with a debugging patch? |
| Comment by Bruno Travouillon (Inactive) [ 10/Sep/15 ] |
|
This is a production cluster, I will need to discuss this. Moreover, we hit this LBUG once for the moment. Can we consider using a SystemTap script for debugging? |
| Comment by Alex Zhuravlev [ 11/Sep/15 ] |
|
not ready to answer about SystemTap.. will try to find an existing state in the code signaling on the condition. |
| Comment by Bruno Travouillon (Inactive) [ 11/Sep/15 ] |
|
SystemTap is a short term solution for the production system. Is your debug patch available in gerrit? I can ask my engineering to consider its inclusion into our build. Thanks. |
| Comment by Alex Zhuravlev [ 11/Sep/15 ] |
|
it's been in testing.. especially given your system is production. |
| Comment by Alex Zhuravlev [ 30/Sep/15 ] |
|
please, tell what additional patches are used. |
| Comment by Bruno Travouillon (Inactive) [ 01/Oct/15 ] |
|
Here is the list of additional patches on top of 2.5.3.90:
|
| Comment by Alex Zhuravlev [ 14/Oct/15 ] |
|
sorry, I still have no a good theory on what happened. do you still have that vmcore? would it be possible to dump the content of the import. |
| Comment by Bruno Travouillon (Inactive) [ 04/Nov/15 ] |
|
Hi Alex, Here is the requested import. Sorry for the delay. crash> struct obd_import ffff880903ac1000
struct obd_import {
imp_handle = {
h_link = {
next = 0xffff880ba8b11980,
prev = 0xffffc90018637e28
},
h_cookie = 4546027237220243948,
h_owner = 0x0,
h_ops = 0xffffffffa06fef10,
h_rcu = {
next = 0x0,
func = 0
},
h_lock = {
raw_lock = {
slock = 0
}
},
h_size = 0,
h_in = 1
},
imp_refcount = {
counter = 1
},
imp_dlm_handle = {
cookie = 0
},
imp_connection = 0xffff880b157a7540,
imp_client = 0xffff8808d060e270,
imp_pinger_chain = {
next = 0xffff880903ac1060,
prev = 0xffff880903ac1060
},
imp_zombie_chain = {
next = 0xffff880903ac1070,
prev = 0xffff880903ac1070
},
imp_replay_list = {
next = 0xffff880903ac1080,
prev = 0xffff880903ac1080
},
imp_sending_list = {
next = 0xffff880903ac1090,
prev = 0xffff880903ac1090
},
imp_delayed_list = {
next = 0xffff880903ac10a0,
prev = 0xffff880903ac10a0
},
imp_committed_list = {
next = 0xffff880903ac10b0,
prev = 0xffff880903ac10b0
},
imp_replay_cursor = 0xffff880903ac10b0,
imp_obd = 0xffff8808d060e138,
imp_sec = 0xffffffffa09138c0,
imp_sec_mutex = {
count = {
counter = 1
},
wait_lock = {
raw_lock = {
slock = 0
}
},
wait_list = 0xffff880903ac10e0,
spin_mlock = 0x0,
owner = 0x0
},
imp_sec_expire = 0,
imp_recovery_waitq = {
lock = {
raw_lock = {
slock = 0
}
},
task_list = {
next = 0xffff880903ac1108,
prev = 0xffff880903ac1108
}
},
imp_inflight = {
counter = 0
},
imp_unregistering = {
counter = 0
},
imp_replay_inflight = {
counter = 0
},
imp_inval_count = {
counter = 0
},
imp_timeouts = {
counter = 0
},
imp_state = LUSTRE_IMP_FULL,
imp_replay_state = 0,
imp_state_hist = {{
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}, {
ish_state = 0,
ish_time = 0
}},
imp_state_hist_idx = 0,
imp_generation = 0,
imp_conn_cnt = 0,
imp_last_generation_checked = 0,
imp_last_replay_transno = 0,
imp_peer_committed_transno = 0,
imp_last_transno_checked = 0,
imp_remote_handle = {
cookie = 12735384055159921237
},
imp_next_ping = 0,
imp_last_success_conn = 0,
imp_conn_list = {
next = 0xffff880903ac1278,
prev = 0xffff880903ac1278
},
imp_conn_current = 0x0,
imp_lock = {
raw_lock = {
slock = 131074
}
},
imp_no_timeout = 0,
imp_invalid = 0,
imp_deactive = 0,
imp_replayable = 0,
imp_dlm_fake = 1,
imp_server_timeout = 0,
imp_delayed_recovery = 0,
imp_no_lock_replay = 0,
imp_vbr_failed = 0,
imp_force_verify = 0,
imp_force_next_verify = 0,
imp_pingable = 0,
imp_resend_replay = 0,
imp_no_pinger_recover = 0,
imp_need_mne_swab = 0,
imp_force_reconnect = 0,
imp_connect_tried = 0,
imp_connect_op = 0,
imp_connect_data = {
ocd_connect_flags = 0,
ocd_version = 0,
ocd_grant = 0,
ocd_index = 0,
ocd_brw_size = 0,
ocd_ibits_known = 0,
ocd_blocksize = 0 '\000',
ocd_inodespace = 0 '\000',
ocd_grant_extent = 0,
ocd_unused = 0,
ocd_transno = 0,
ocd_group = 0,
ocd_cksum_types = 0,
ocd_max_easize = 0,
ocd_instance = 0,
ocd_maxbytes = 0,
padding1 = 0,
padding2 = 0,
padding3 = 0,
padding4 = 0,
padding5 = 0,
padding6 = 0,
padding7 = 0,
padding8 = 0,
padding9 = 0,
paddingA = 0,
paddingB = 0,
paddingC = 0,
paddingD = 0,
paddingE = 0,
paddingF = 0
},
imp_connect_flags_orig = 0,
imp_connect_error = 0,
imp_msg_magic = 198183891,
imp_msghdr_flags = 3,
imp_rq_pool = 0x0,
imp_at = {
iat_portal = {0, 0, 0, 0, 0, 0, 0, 0},
iat_net_latency = {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 0,
at_current = 0,
at_worst_ever = 0,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
},
iat_service_estimate = {{
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}, {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}, {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}, {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}, {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}, {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}, {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}, {
at_binstart = 0,
at_hist = {0, 0, 0, 0},
at_flags = 1,
at_current = 5,
at_worst_ever = 5,
at_worst_time = 1433652063,
at_lock = {
raw_lock = {
slock = 65537
}
}
}}
},
imp_last_reply_time = 0
}
|
| Comment by Sebastien Piechurski [ 17/Dec/15 ] |
|
Hi Alex, Do you have any news or progress on this ticket ? |
| Comment by Sebastien Piechurski [ 28/Jan/16 ] |
|
Alex, we don't have any news for almost 3 months. |
| Comment by Alex Zhuravlev [ 28/Jan/16 ] |
|
I'm sorry Sebastien, I'm not able to reproduce this and all my hypothesis failed.. |
| Comment by Sebastien Piechurski [ 11/Feb/16 ] |
|
Hi Alex. |
| Comment by Peter Jones [ 11/Feb/16 ] |
|
Sebastien This does seem reasonable under the circumstances Peter |