[LU-4192] NFS server crash while fsx runs on clients

• Type: Bug
• Resolution: Duplicate
• Priority: Minor
• Affects Version/s: Lustre 2.5.0
• Environment: Lustre 2.5.0-RC1 build #2, RHEL 6, OpenSFS cluster with one MDS/MGS, one OST with two OSSs, one NFS server, four clients.
• Severity: 3
• Assignee: WC Triage
• Reporter: James Nunez (Inactive)

Description

Running 2.5.0-RC1, with one NFS server exporting the Lustre file system with 4 clients running "./fsx", "./fsx", "./fsx -c 3 -l 8000000 -r 75 -w 4096 /misc/export/nfs_x_4" and "./fsx -c 5 -l 500000 -o 2048". The export options are rw,async,insecure. After a few hours of running fsx, the NFS server crashed.

From the console of the NFS server (c06):

Message from syslogd@c06 at Oct 30 14:52:40 ...
 kernel:LustreError: 6653:0:(rw.c:695:ll_read_ahead_pages()) ASSERTION( page_idx > ria->ria_stoff ) failed: Invalid page_idx 1025rs 1025 re 1534 ro 1279 rl 256 rp 1

Message from syslogd@c06 at Oct 30 14:52:40 ...
 kernel:LustreError: 6653:0:(rw.c:695:ll_read_ahead_pages()) LBUG

From vmcore-dmesg.txt on the NFS server (c06):

<0>LustreError: 6653:0:(rw.c:695:ll_read_ahead_pages()) ASSERTION( page_idx > ri
a->ria_stoff ) failed: Invalid page_idx 1025rs 1025 re 1534 ro 1279 rl 256 rp 1
<0>LustreError: 6653:0:(rw.c:695:ll_read_ahead_pages()) LBUG
<4>Pid: 6653, comm: nfsd
<4>
<4>Call Trace:
<4> [<ffffffffa044f895>] libcfs_debug_dumpstack+0x55/0x80 [libcfs]
<4> [<ffffffffa044fe97>] lbug_with_loc+0x47/0xb0 [libcfs]
<4> [<ffffffffa0a607d6>] ll_readahead+0x10c6/0x10f0 [lustre]
<4> [<ffffffff8127d847>] ? radix_tree_insert+0x1c7/0x220
<4> [<ffffffffa0a8cd75>] vvp_io_read_page+0x305/0x340 [lustre]
<4> [<ffffffffa05d5c7d>] cl_io_read_page+0x8d/0x170 [obdclass]
<4> [<ffffffffa05c9a77>] ? cl_page_assume+0xf7/0x220 [obdclass]
<4> [<ffffffffa0a5f176>] ll_readpage+0x96/0x1a0 [lustre]
<4> [<ffffffff811b0cf8>] __generic_file_splice_read+0x3a8/0x560
<4> [<ffffffff81168712>] ? kmem_cache_alloc+0x182/0x190
<4> [<ffffffffa0464e47>] ? cfs_hash_bd_lookup_intent+0x37/0x130 [libcfs]
<4> [<ffffffffa0464e47>] ? cfs_hash_bd_lookup_intent+0x37/0x130 [libcfs]
<4> [<ffffffffa05cd6db>] ? cl_lock_fits_into+0x6b/0x190 [obdclass]
<4> [<ffffffffa09b38d9>] ? lov_lock_fits_into+0x409/0x560 [lov]
<4> [<ffffffff811aeb90>] ? spd_release_page+0x0/0x20
<4> [<ffffffff811b0efa>] generic_file_splice_read+0x4a/0x90
<4> [<ffffffffa0a8e905>] vvp_io_read_start+0x3c5/0x470 [lustre]
<4> [<ffffffffa05d37ea>] cl_io_start+0x6a/0x140 [obdclass]
<4> [<ffffffffa05d7ef4>] cl_io_loop+0xb4/0x1b0 [obdclass]
<4> [<ffffffffa0a30f9f>] ll_file_io_generic+0x33f/0x610 [lustre]
<4> [<ffffffffa0a319c0>] ll_file_splice_read+0xb0/0x1d0 [lustre]
<4> [<ffffffff811af15b>] do_splice_to+0x6b/0xa0
<4> [<ffffffff811af45f>] splice_direct_to_actor+0xaf/0x1c0
<4> [<ffffffffa03aa3b0>] ? nfsd_direct_splice_actor+0x0/0x20 [nfsd]
<4> [<ffffffffa03aae70>] nfsd_vfs_read+0x1a0/0x1c0 [nfsd]
<4> [<ffffffffa03ac4a0>] nfsd_read_file+0x90/0xb0 [nfsd]
<4> [<ffffffffa03c00ef>] nfsd4_encode_read+0x13f/0x240 [nfsd]
<4> [<ffffffffa03c5dd4>] ? nfs4_preprocess_stateid_op+0x284/0x310 [nfsd]
<4> [<ffffffffa03b9d35>] nfsd4_encode_operation+0x75/0x180 [nfsd]
<4> [<ffffffffa03b7d35>] nfsd4_proc_compound+0x195/0x490 [nfsd]
<4> [<ffffffffa03a543e>] nfsd_dispatch+0xfe/0x240 [nfsd]
<4> [<ffffffffa02d0614>] svc_process_common+0x344/0x640 [sunrpc]
<4> [<ffffffff81063410>] ? default_wake_function+0x0/0x20
<4> [<ffffffffa02d0c50>] svc_process+0x110/0x160 [sunrpc]
<4> [<ffffffffa03a5b62>] nfsd+0xc2/0x160 [nfsd]
<4> [<ffffffffa03a5aa0>] ? nfsd+0x0/0x160 [nfsd]
<4> [<ffffffff81096a36>] kthread+0x96/0xa0
<4> [<ffffffff8100c0ca>] child_rip+0xa/0x20
<4> [<ffffffff810969a0>] ? kthread+0x0/0xa0
<4> [<ffffffff8100c0c0>] ? child_rip+0x0/0x20
<4>
<0>Kernel panic - not syncing: LBUG
<4>Pid: 6653, comm: nfsd Not tainted 2.6.32-358.18.1.el6.x86_64 #1
<4>Call Trace:
<4> [<ffffffff8150da18>] ? panic+0xa7/0x16f
<4> [<ffffffffa044feeb>] ? lbug_with_loc+0x9b/0xb0 [libcfs]
<4> [<ffffffffa0a607d6>] ? ll_readahead+0x10c6/0x10f0 [lustre]
<4> [<ffffffff8127d847>] ? radix_tree_insert+0x1c7/0x220
<4> [<ffffffffa0a8cd75>] ? vvp_io_read_page+0x305/0x340 [lustre]
<4> [<ffffffffa05d5c7d>] ? cl_io_read_page+0x8d/0x170 [obdclass]
<4> [<ffffffffa05c9a77>] ? cl_page_assume+0xf7/0x220 [obdclass]
<4> [<ffffffffa0a5f176>] ? ll_readpage+0x96/0x1a0 [lustre]
<4> [<ffffffff811b0cf8>] ? __generic_file_splice_read+0x3a8/0x560
<4> [<ffffffff81168712>] ? kmem_cache_alloc+0x182/0x190
<4> [<ffffffffa0464e47>] ? cfs_hash_bd_lookup_intent+0x37/0x130 [libcfs]
<4> [<ffffffffa0464e47>] ? cfs_hash_bd_lookup_intent+0x37/0x130 [libcfs]
<4> [<ffffffffa05cd6db>] ? cl_lock_fits_into+0x6b/0x190 [obdclass]
<4> [<ffffffffa09b38d9>] ? lov_lock_fits_into+0x409/0x560 [lov]
<4> [<ffffffff811aeb90>] ? spd_release_page+0x0/0x20
<4> [<ffffffff811b0efa>] ? generic_file_splice_read+0x4a/0x90
<4> [<ffffffffa0a8e905>] ? vvp_io_read_start+0x3c5/0x470 [lustre]
<4> [<ffffffffa05d37ea>] ? cl_io_start+0x6a/0x140 [obdclass]
<4> [<ffffffffa05d7ef4>] ? cl_io_loop+0xb4/0x1b0 [obdclass]
<4> [<ffffffffa0a30f9f>] ? ll_file_io_generic+0x33f/0x610 [lustre]
<4> [<ffffffffa0a319c0>] ? ll_file_splice_read+0xb0/0x1d0 [lustre]
<4> [<ffffffff811af15b>] ? do_splice_to+0x6b/0xa0
<4> [<ffffffff811af45f>] ? splice_direct_to_actor+0xaf/0x1c0
<4> [<ffffffffa03aa3b0>] ? nfsd_direct_splice_actor+0x0/0x20 [nfsd]
<4> [<ffffffffa03aae70>] ? nfsd_vfs_read+0x1a0/0x1c0 [nfsd]
<4> [<ffffffffa03ac4a0>] ? nfsd_read_file+0x90/0xb0 [nfsd]
<4> [<ffffffffa03c00ef>] ? nfsd4_encode_read+0x13f/0x240 [nfsd]
<4> [<ffffffffa03c5dd4>] ? nfs4_preprocess_stateid_op+0x284/0x310 [nfsd]
<4> [<ffffffffa03b9d35>] ? nfsd4_encode_operation+0x75/0x180 [nfsd]
<4> [<ffffffffa03b7d35>] ? nfsd4_proc_compound+0x195/0x490 [nfsd]
<4> [<ffffffffa03a543e>] ? nfsd_dispatch+0xfe/0x240 [nfsd]
<4> [<ffffffffa02d0614>] ? svc_process_common+0x344/0x640 [sunrpc]
<4> [<ffffffff81063410>] ? default_wake_function+0x0/0x20
<4> [<ffffffffa02d0c50>] ? svc_process+0x110/0x160 [sunrpc]
<4> [<ffffffffa03a5b62>] ? nfsd+0xc2/0x160 [nfsd]
<4> [<ffffffffa03a5aa0>] ? nfsd+0x0/0x160 [nfsd]
<4> [<ffffffff81096a36>] ? kthread+0x96/0xa0
<4> [<ffffffff8100c0ca>] ? child_rip+0xa/0x20
<4> [<ffffffff810969a0>] ? kthread+0x0/0xa0
<4> [<ffffffff8100c0c0>] ? child_rip+0x0/0x20

From dmesg on the MDS/MGS (c04):

Lustre: MGS: haven't heard from client 69d18973-27a2-0441-1720-b772711670c2 (at 192.168.2.106@o2ib) in 236 seconds. I think it's dead, and I am evicting it. exp ffff880664582400, cur 1383170178 expire 1383170028 last 1383169942
Lustre: scratch-MDT0000: haven't heard from client 63f330f5-0403-f077-ec5e-2a25cace70a6 (at 192.168.2.106@o2ib) in 239 seconds. I think it's dead, and I am evicting it. exp ffff88082e2c9c00, cur 1383170203 expire 1383170053 last 138316996

dmesg on one of the clients(c03) running fsx:

nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
nfs: server c06-ib.lab.opensfs.org not responding, still trying
nfs: server c06-ib.lab.opensfs.org OK

dmesg on another client(c11) running fsx:

nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
ip_tables: (C) 2000-2006 Netfilter Core Team
nf_conntrack version 0.5.0 (16384 buckets, 65536 max)
INFO: task fsx:7077 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
fsx           D 0000000000000002     0  7077   6831 0x00000080
 ffff880822b21c28 0000000000000082 ffff880822b21ba8 ffffffffa02cbcd0
 ffff880823ec7c00 ffff880822b21bd8 ffff880823ec7cb0 ffff880823161408
 ffff88082482a638 ffff880822b21fd8 000000000000fb88 ffff88082482a638
Call Trace:
 [<ffffffffa02cbcd0>] ? rpc_execute+0x50/0xa0 [sunrpc]
 [<ffffffff810a2431>] ? ktime_get_ts+0xb1/0xf0
 [<ffffffff81119e10>] ? sync_page+0x0/0x50
 [<ffffffff8150e8c3>] io_schedule+0x73/0xc0
 [<ffffffff81119e4d>] sync_page+0x3d/0x50
 [<ffffffff8150f27f>] __wait_on_bit+0x5f/0x90
 [<ffffffff8111a083>] wait_on_page_bit+0x73/0x80
 [<ffffffff81096de0>] ? wake_bit_function+0x0/0x50
 [<ffffffff8112f0e5>] ? pagevec_lookup_tag+0x25/0x40
 [<ffffffff8111a4ab>] wait_on_page_writeback_range+0xfb/0x190
 [<ffffffff8111a56f>] filemap_fdatawait+0x2f/0x40
 [<ffffffff8111ab94>] filemap_write_and_wait+0x44/0x60
 [<ffffffffa032ddfd>] nfs_getattr+0x10d/0x120 [nfs]
 [<ffffffff81186d21>] vfs_getattr+0x51/0x80
 [<ffffffff81186fdf>] vfs_fstat+0x3f/0x60
 [<ffffffff81187024>] sys_newfstat+0x24/0x40
 [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
 [<ffffffff810dc685>] ? __audit_syscall_exit+0x265/0x290
 [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
nfs: server c06-ib.lab.opensfs.org not responding, still trying
INFO: task fsx:7077 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
fsx           D 0000000000000002     0  7077   6831 0x00000080
 ffff880822b21c28 0000000000000082 ffff880822b21ba8 ffffffffa02cbcd0
 ffff880823ec7c00 ffff880822b21bd8 ffff880823ec7cb0 ffff880823161408
 ffff88082482a638 ffff880822b21fd8 000000000000fb88 ffff88082482a638
Call Trace:
 [<ffffffffa02cbcd0>] ? rpc_execute+0x50/0xa0 [sunrpc]
 [<ffffffff810a2431>] ? ktime_get_ts+0xb1/0xf0
 [<ffffffff81119e10>] ? sync_page+0x0/0x50
 [<ffffffff8150e8c3>] io_schedule+0x73/0xc0
 [<ffffffff81119e4d>] sync_page+0x3d/0x50
 [<ffffffff8150f27f>] __wait_on_bit+0x5f/0x90
 [<ffffffff8111a083>] wait_on_page_bit+0x73/0x80
 [<ffffffff81096de0>] ? wake_bit_function+0x0/0x50
 [<ffffffff8112f0e5>] ? pagevec_lookup_tag+0x25/0x40
 [<ffffffff8111a4ab>] wait_on_page_writeback_range+0xfb/0x190
 [<ffffffff8111a56f>] filemap_fdatawait+0x2f/0x40
 [<ffffffff8111ab94>] filemap_write_and_wait+0x44/0x60
 [<ffffffffa032ddfd>] nfs_getattr+0x10d/0x120 [nfs]
 [<ffffffff81186d21>] vfs_getattr+0x51/0x80
 [<ffffffff81186fdf>] vfs_fstat+0x3f/0x60
 [<ffffffff81187024>] sys_newfstat+0x24/0x40
 [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
 [<ffffffff810dc685>] ? __audit_syscall_exit+0x265/0x290
 [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
INFO: task fsx:7077 blocked for more than 120 seconds.
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
fsx           D 0000000000000002     0  7077   6831 0x00000080
 ffff880822b21c28 0000000000000082 ffff880822b21ba8 ffffffffa02cbcd0
 ffff880823ec7c00 ffff880822b21bd8 ffff880823ec7cb0 ffff880823161408
 ffff88082482a638 ffff880822b21fd8 000000000000fb88 ffff88082482a638
Call Trace:
 [<ffffffffa02cbcd0>] ? rpc_execute+0x50/0xa0 [sunrpc]
 [<ffffffff810a2431>] ? ktime_get_ts+0xb1/0xf0
 [<ffffffff81119e10>] ? sync_page+0x0/0x50
 [<ffffffff8150e8c3>] io_schedule+0x73/0xc0
 [<ffffffff81119e4d>] sync_page+0x3d/0x50
 [<ffffffff8150f27f>] __wait_on_bit+0x5f/0x90
 [<ffffffff8111a083>] wait_on_page_bit+0x73/0x80
 [<ffffffff81096de0>] ? wake_bit_function+0x0/0x50
 [<ffffffff8112f0e5>] ? pagevec_lookup_tag+0x25/0x40
 [<ffffffff8111a4ab>] wait_on_page_writeback_range+0xfb/0x190
 [<ffffffff8111a56f>] filemap_fdatawait+0x2f/0x40
 [<ffffffff8111ab94>] filemap_write_and_wait+0x44/0x60
 [<ffffffffa032ddfd>] nfs_getattr+0x10d/0x120 [nfs]
 [<ffffffff81186d21>] vfs_getattr+0x51/0x80
 [<ffffffff81186fdf>] vfs_fstat+0x3f/0x60
 [<ffffffff81187024>] sys_newfstat+0x24/0x40
 [<ffffffff810dc937>] ? audit_syscall_entry+0x1d7/0x200
 [<ffffffff810dc685>] ? __audit_syscall_exit+0x265/0x290
 [<ffffffff8100b072>] system_call_fastpath+0x16/0x1b
nfs: server c06-ib.lab.opensfs.org OK

On the above two clients running fsx, there is some information from fsx on the console.

From c11:

21166179: 1383169965.726634 TRUNCATE DOWN       from 0x3f79b to 0x1faa0
21166180: 1383169965.727509 WRITE    0xf5 thru 0xe785 (0xe691 bytes)
21166181: 1383169965.728551 READ     0xcc40 thru 0x1048d (0x384e bytes)
21166182: 1383169965.728579 TRUNCATE UP from 0x1faa0 to 0x3d30f
21166183: 1383169965.729270 WRITE    0x1efa1 thru 0x1ff22 (0xf82 bytes)
21166184: 1383169965.729569 MAPWRITE 0x24b11 thru 0x3137f (0xc86f bytes)
21166185: 1383169965.732139 WRITE    0x3d715 thru 0x3ffff (0x28eb bytes) HOLE
21166186: 1383169965.732569 READ     0x36ae3 thru 0x3bebc (0x53da bytes)
21166187: 1383169965.732607 WRITE    0x2bde3 thru 0x2edce (0x2fec bytes)
21166188: 1383169965.733019 TRUNCATE DOWN       from 0x40000 to 0x22c5a
21166189: 1383169965.733905 READ     0x5aa2 thru 0x111fd (0xb75c bytes)
21166190: 1383169965.733984 MAPREAD  0x8954 thru 0xf80c (0x6eb9 bytes)
21166191: 1383169965.734046 TRUNCATE UP from 0x22c5a to 0x2d1ff
21166192: 1383169965.734796 TRUNCATE DOWN       from 0x2d1ff to 0x14b1c
21166193: 1383169965.735632 READ     0x13752 thru 0x14b1b (0x13ca bytes)
21166194: 1383169965.735643 READ     0xec90 thru 0x14b1b (0x5e8c bytes)
21166195: 1383169965.735682 MAPWRITE 0x16fcc thru 0x22e5b (0xbe90 bytes)
21166196: 1383169965.738445 TRUNCATE DOWN       from 0x22e5c to 0x946a
21166197: 1383169965.739279 MAPWRITE 0x1f64b thru 0x23e6a (0x4820 bytes)
21166198: 1383169965.742263 MAPREAD  0x14df4 thru 0x1855c (0x3769 bytes)
21166199: 1383169965.742303 MAPWRITE 0x11972 thru 0x21497 (0xfb26 bytes)
Correct content saved for comparison
(maybe hexdump "/misc/export/nfs_x_2" vs "/misc/export/nfs_x_2.fsxgood")

on c03 a very long listing ending in:

…
2170216: 1383169960.525813 MAPWRITE 0x32e000 thru 0x33c2c1 (0xe2c2 bytes)
2170217: 1383169960.526777 TRUNCATE DOWN	from 0x743f40 to 0x1fe27c
2170218: 1383169960.531574 MAPREAD  0x1c02b4 thru 0x1cc215 (0xbf62 bytes)
2170219: 1383169960.531687 CLOSE/OPEN
2170220: 1383169960.532293 TRUNCATE UP	from 0x1fe27c to 0x68dab9
2170221: 1383169960.533532 MAPWRITE 0x343000 thru 0x34c4d4 (0x94d5 bytes)
2170222: 1383169960.800438 CLOSE/OPEN
2170223: 1383169960.800480 MAPREAD  0x61c245 thru 0x620e19 (0x4bd5 bytes)
2170224: 1383169960.800536 CLOSE/OPEN
2170225: 1383169960.800563 WRITE    0x7c000 thru 0x8b4de (0xf4df bytes)
2170226: 1383169960.801359 CLOSE/OPEN
2170227: 1383169960.801386 TRUNCATE DOWN	from 0x68dab9 to 0x206e69
Correct content saved for comparison
(maybe hexdump "/misc/export/nfs_x_4" vs "/misc/export/nfs_x_4.fsxgood")

Issue Links

• is duplicated by: LU-5263 ll_read_ahead_pages() ASSERTION( page_idx > ria->ria_stoff )