11:16 a.m.
We see the below crash in the mdcache_lru_unref path with a long running test using a
Windows NFS client.
We’re running ganesha v2.7.1 with 2 additional commits from -next that seemed possibly
relevant:
https://github.com/nfs-ganesha/nfs-ganesha/commit/654dd706d22663c6ae6029e...
https://github.com/nfs-ganesha/nfs-ganesha/commit/5dc6a70ed42275a4f6772b9...
Client:
Windows 2012 NFSv3 [UID=-2, GID=-2, rsize=1048576, wsize=1048576, mount=hard, timeout=1.6,
retry=1, locking=no, fileaccess=755, lang=ANSI, casesensitive=no, sec=sys]
Note use hard mount and nolock which are not default for Windows.
Workload:
Concurrent access from multiple threads. 1 thread continuously (in a loop) running python
os.walk (i.e., readdir) of the entire filesystem, roughly ~5M files total. 5 more threads
are writing a few thousand files each. When the writes complete, a single thread verifies
written content, then deletes it. Then the writes repeat again.
Test requires 24-48 hours until failure but failure is repeatable if you are sufficiently
patient.
We do not see this issue with a Linux NFS client (v3 or v4) with a similar workload.
We seem to have re-entered _mdcache_lru_unref with the same entry.
Apologies if my email client destroys the formatting below.
(gdb) bt
#0 0x00007f1520efe277 in raise () from /lib64/libc.so.6
#1 0x00007f1520eff968 in abort () from /lib64/libc.so.6
#2 0x0000000000536388 in cih_remove_checked (entry=0x22a9d1a0) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_hash.h:394
#3 0x0000000000537248 in mdc_clean_entry (entry=0x22a9d1a0) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:264
#4 0x000000000052480d in mdcache_lru_clean (entry=0x22a9d1a0) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:591
#5 0x000000000052963c in _mdcache_lru_unref (entry=0x22a9d1a0, flags=0, func=0x596b90
<__func__.23067> "cih_remove_checked", line=406)
at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:1989
#6 0x000000000053642d in cih_remove_checked (entry=0x22a9d1a0) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_hash.h:406
#7 0x0000000000537248 in mdc_clean_entry (entry=0x22a9d1a0) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:264
#8 0x000000000052480d in mdcache_lru_clean (entry=0x22a9d1a0) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:591
#9 0x000000000052963c in _mdcache_lru_unref (entry=0x22a9d1a0, flags=0, func=0x5941df
<__func__.22972> "mdcache_put", line=196)
at /src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.c:1989
#10 0x000000000052cb54 in mdcache_put (entry=0x22a9d1a0) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_lru.h:196
#11 0x0000000000530bca in mdcache_put_ref (obj_hdl=0x22a9d1d8) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:1280
#12 0x00000000004327e5 in populate_dirent (name=0x43f30278 "random.267",
obj=0x22a9d1d8, attrs=0x22a9d268, dir_state=0x7f15176e9af0, cookie=3786442)
at /src/src/FSAL/fsal_helper.c:1064
#13 0x0000000000541a25 in mdcache_readdir_chunked (directory=0xcf7c7c0, whence=3786313,
dir_state=0x7f15176e9af0, cb=0x43217c <populate_dirent>,
attrmask=0, eod_met=0x7f15176e9feb) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_helpers.c:3146
#14 0x000000000052e8c3 in mdcache_readdir (dir_hdl=0xcf7c7f8, whence=0x7f15176e9ad0,
dir_state=0x7f15176e9af0, cb=0x43217c <populate_dirent>, attrmask=0,
eod_met=0x7f15176e9feb) at
/src/src/FSAL/Stackable_FSALs/FSAL_MDCACHE/mdcache_handle.c:559
#15 0x0000000000432a76 in fsal_readdir (directory=0xcf7c7f8, cookie=3786313,
nbfound=0x7f15176e9fec, eod_met=0x7f15176e9feb, attrmask=0,
cb=0x4912a2 <nfs3_readdir_callback>, opaque=0x7f15176e9fa0) at
/src/src/FSAL/fsal_helper.c:1158
#16 0x000000000049108a in nfs3_readdir (arg=0x996f788, req=0x996f080, res=0x3f3c6a30) at
/src/src/Protocols/NFS/nfs3_readdir.c:289
#17 0x00000000004574d1 in nfs_rpc_process_request (reqdata=0x996f080) at
/src/src/MainNFSD/nfs_worker_thread.c:1329
#18 0x0000000000457c90 in nfs_rpc_valid_NFS (req=0x996f080) at
/src/src/MainNFSD/nfs_worker_thread.c:1549
#19 0x00007f15226b1e75 in svc_vc_decode (req=0x996f080) at
/src/src/libntirpc/src/svc_vc.c:825
#20 0x000000000044a688 in nfs_rpc_decode_request (xprt=0x4f4e77f0, xdrs=0xd57ef60) at
/src/src/MainNFSD/nfs_rpc_dispatcher_thread.c:1341
#21 0x00007f15226b1d86 in svc_vc_recv (xprt=0x4f4e77f0) at
/src/src/libntirpc/src/svc_vc.c:798
#22 0x00007f15226ae4d3 in svc_rqst_xprt_task (wpe=0x4f4e7a08) at
/src/src/libntirpc/src/svc_rqst.c:767
#23 0x00007f15226ae94d in svc_rqst_epoll_events (sr_rec=0x101b440, n_events=1) at
/src/src/libntirpc/src/svc_rqst.c:939
#24 0x00007f15226aebe2 in svc_rqst_epoll_loop (sr_rec=0x101b440) at
/src/src/libntirpc/src/svc_rqst.c:1012
#25 0x00007f15226aec95 in svc_rqst_run_task (wpe=0x101b440) at
/src/src/libntirpc/src/svc_rqst.c:1048
(gdb) print *entry
$2 = {attr_lock = {__data = {__lock = 0, __nr_readers = 0, __readers_wakeup = 0,
__writer_wakeup = 0, __nr_readers_queued = 0, __nr_writers_queued = 0,
__writer = 0, __shared = 0, __pad1 = 0, __pad2 = 0, __flags = 0}, __size =
'\000' <repeats 55 times>, __align = 0}, obj_handle = {handles = {
next = 0x12a5ac78, prev = 0x12de5418}, fs = 0x0, fsal = 0x7d3340 <MDCACHE>,
obj_ops = 0x7d3490 <MDCACHE+336>, obj_lock = {__data = {__lock = 0,
__nr_readers = 0, __readers_wakeup = 0, __writer_wakeup = 0, __nr_readers_queued =
0, __nr_writers_queued = 0, __writer = 0, __shared = 0,
__pad1 = 0, __pad2 = 0, __flags = 0}, __size = '\000' <repeats 55
times>, __align = 0}, type = REGULAR_FILE, fsid = {major = 0, minor = 0},
fileid = 2454576, state_hdl = 0x22a9d428}, sub_handle = 0x0, attrs = {request_mask =
1433550, valid_mask = 1433550, supported = 1433582,
type = REGULAR_FILE, filesize = 1024, fsid = {major = 0, minor = 0}, acl = 0x0, fileid
= 2454576, mode = 438, numlinks = 1, owner = 65534,
group = 65534, rawdev = {major = 0, minor = 0}, atime = {tv_sec = 1547875446, tv_nsec
= 112000000}, creation = {tv_sec = 0, tv_nsec = 0}, ctime = {
tv_sec = 1547875446, tv_nsec = 112000000}, mtime = {tv_sec = 1547875446, tv_nsec =
112000000}, chgtime = {tv_sec = 1547875446, tv_nsec = 112000000},
spaceused = 1024, change = 1547875446112, generation = 0, expire_time_attr = 60,
fs_locations = 0x0}, fh_hk = {node_k = {left = 0x0, right = 0x0,
parent = 267421682}, key = {hk = 10676371249170983334, fsal = 0x7f15186d45e0
<FOO>, kv = {addr = 0x4761f300, len = 10}}, inavl = false},
mde_flags = 1, attr_time = 1547998073, acl_time = 0, fs_locations_time = 0, lru = {q =
{next = 0x0, prev = 0x0}, qid = LRU_ENTRY_L1, refcnt = 0,
flags = 0, lane = 10, cf = 0}, export_list = {next = 0x22a9d3d8, prev = 0x22a9d3d8},
first_export_id = -1, content_lock = {__data = {__lock = 0,
__nr_readers = 0, __readers_wakeup = 0, __writer_wakeup = 0, __nr_readers_queued =
0, __nr_writers_queued = 0, __writer = 0, __shared = 0,
__pad1 = 0, __pad2 = 0, __flags = 0}, __size = '\000' <repeats 55
times>, __align = 0}, fsobj = {hdl = {state_lock = {__data = {__lock = 0,
__nr_readers = 0, __readers_wakeup = 0, __writer_wakeup = 0, __nr_readers_queued
= 0, __nr_writers_queued = 0, __writer = 0, __shared = 0,
__pad1 = 0, __pad2 = 0, __flags = 0}, __size = '\000' <repeats 55
times>, __align = 0}, no_cleanup = false, {file = {obj = 0x22a9d1d8,
list_of_states = {next = 0x22a9d470, prev = 0x22a9d470}, layoutrecall_list =
{next = 0x22a9d480, prev = 0x22a9d480}, lock_list = {
next = 0x22a9d490, prev = 0x22a9d490}, nlm_share_list = {next = 0x22a9d4a0,
prev = 0x22a9d4a0}, write_delegated = false, fdeleg_stats = {
fds_curr_delegations = 0, fds_deleg_type = OPEN_DELEGATE_NONE,
fds_delegation_count = 0, fds_recall_count = 0, fds_avg_hold = 0,
fds_last_delegation = 0, fds_last_recall = 0, fds_num_opens = 0,
fds_first_open = 0}, anon_ops = 0}, dir = {junction_export = 0x22a9d1d8,
export_roots = {next = 0x22a9d470, prev = 0x22a9d470}, exp_root_refcount =
581555328}}}, fsdir = {chunks = {next = 0x0, prev = 0x0}, detached = {
next = 0x0, prev = 0x0}, spin = 0, detached_count = 0, dhdl = {state_lock =
{__data = {__lock = 0, __nr_readers = 0, __readers_wakeup = 0,
__writer_wakeup = 0, __nr_readers_queued = 0, __nr_writers_queued = 0,
__writer = 581554648, __shared = 0, __pad1 = 581555312,
__pad2 = 581555312, __flags = 581555328},
__size = '\000' <repeats 24 times>,
"\330ѩ\"\000\000\000\000p\324\251\"\000\000\000\000p\324\251\"\000\000\000\000\200\324\251\"\000\000\000",
__align = 0}, no_cleanup = 128, {file = {obj = 0x22a9d490, list_of_states =
{next = 0x22a9d490, prev = 0x22a9d4a0}, layoutrecall_list = {
next = 0x22a9d4a0, prev = 0x0}, lock_list = {next = 0x0, prev = 0x0},
nlm_share_list = {next = 0x0, prev = 0x0}, write_delegated = false,
fdeleg_stats = {fds_curr_delegations = 0, fds_deleg_type = OPEN_DELEGATE_NONE,
fds_delegation_count = 0, fds_recall_count = 0,
fds_avg_hold = 0, fds_last_delegation = 0, fds_last_recall = 0,
fds_num_opens = 0, fds_first_open = 0}, anon_ops = 0}, dir = {
junction_export = 0x22a9d490, export_roots = {next = 0x22a9d490, prev =
0x22a9d4a0}, exp_root_refcount = 581555360}}}, parent = {addr = 0x0,
len = 0}, first_ck = 0, avl = {t = {root = 0x0, cmp_fn = 0x0, height = 0, first =
0x0, last = 0x0, size = 0}, ck = {root = 0x0, cmp_fn = 0x0,
height = 0, first = 0x0, last = 0x0, size = 0}, sorted = {root = 0x0, cmp_fn =
0x0, height = 0, first = 0x0, last = 0x0, size = 0},
collisions = 0}}}}