Details
-
Bug
-
Resolution: Duplicate
-
Blocker
-
Lustre 2.4.0
-
3
-
6194
Description
HAd this crash running sanityn test 12:
[45366.990436] Lustre: DEBUG MARKER: == sanityn test 12: test lock ordering (link, stat, unlink) ============= 10:01:13 (1358607673) [45367.146837] Lustre: DEBUG MARKER: start dir: /mnt/lustre/lockdir=144115205255725085 file: /mnt/lustre/lockdir/lockfile=144115205255725083 [45445.727378] LustreError: 20512:0:(lov_io.c:222:lov_sub_get()) ASSERTION( stripe < lio->lis_stripe_count ) failed: [45445.728276] LustreError: 20512:0:(lov_io.c:222:lov_sub_get()) LBUG [45445.728751] Pid: 20512, comm: statmany [45445.729089] [45445.729090] Call Trace: [45445.729696] [<ffffffffa0a7a915>] libcfs_debug_dumpstack+0x55/0x80 [libcfs] [45445.730184] [<ffffffffa0a7af17>] lbug_with_loc+0x47/0xb0 [libcfs] [45445.730673] [<ffffffffa14041ba>] lov_sub_get+0x4aa/0x690 [lov] [45445.731129] [<ffffffffa1400132>] lov_sublock_env_get+0xd2/0x140 [lov] [45445.731612] [<ffffffffa1401841>] lov_sublock_alloc+0xf1/0x450 [lov] [45445.732086] [<ffffffffa1402a2c>] lov_lock_init_raid0+0x3ec/0xe50 [lov] [45445.732632] [<ffffffffa13fa2ae>] lov_lock_init+0x1e/0x60 [lov] [45445.733135] [<ffffffffa0bec52c>] cl_lock_hold_mutex+0x34c/0x660 [obdclass] [45445.733652] [<ffffffffa0bec9a2>] cl_lock_request+0x62/0x270 [obdclass] [45445.734143] [<ffffffffa090b1f9>] cl_glimpse_lock+0x179/0x480 [lustre] [45445.734635] [<ffffffffa090ba65>] cl_glimpse_size0+0x1a5/0x1d0 [lustre] [45445.735142] [<ffffffffa08c5298>] ll_inode_revalidate_it+0x198/0x1c0 [lustre] [45445.735748] [<ffffffffa08c5309>] ll_getattr_it+0x49/0x170 [lustre] [45445.736230] [<ffffffffa08c5467>] ll_getattr+0x37/0x40 [lustre] [45445.736719] [<ffffffff81214fa3>] ? security_inode_getattr+0x23/0x30 [45445.737183] [<ffffffff81180891>] vfs_getattr+0x51/0x80 [45445.737613] [<ffffffff810385d8>] ? pvclock_clocksource_read+0x58/0xd0 [45445.738070] [<ffffffff81180920>] vfs_fstatat+0x60/0x80 [45445.738508] [<ffffffff81180a6b>] vfs_stat+0x1b/0x20 [45445.738919] [<ffffffff81180a94>] sys_newstat+0x24/0x50 [45445.739332] [<ffffffff8109b05a>] ? do_gettimeofday+0x1a/0x50 [45445.740967] [<ffffffff8100c5b5>] ? math_state_restore+0x45/0x60 [45445.741415] [<ffffffff814fb72e>] ? do_device_not_available+0xe/0x10 [45445.741875] [<ffffffff8100befb>] ? device_not_available+0x1b/0x20 [45445.742317] [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b [45445.742763] [45445.744348] Kernel panic - not syncing: LBUG
Crashdump is in /exports/crashdumps/192.168.10.217-2013-01-19-10\:02\:36
Attachments
Issue Links
Activity
Duplicate of LU-2766, the same issue with different symptom.
Unfortunately this is still present in 2.4. Oleg's description matches up very well with what I'm seeing on 2.4 and 2.5, so reopening seems best. Based on stack traces and the shared reproducer, I assume this is really the same issue as LU-2766.
Do you think this is the same bug as was previously being hit here, or a different bug with the same symptom (this wasn't hit with racer, and was apparently fixed by landing the patch)? Reopening this bug (which is marked a blocker) that was fixed and landed for 2.4.0 complicates the tracking process.
It might be better to close this one again and open a separate bug related to racer + layout swap. While the symptom (LASSERT()) is serious, the stress of swapping the layout of two files in a loop is very unlikely to be seen in real life, so I won't rank this as a blocker.
Saw this running racer today on 2.4.51-3-g9f5eea8. Reproduces much more readily if you do:
# llmount.sh
# cd /mnt/lustre
# touch 0 1
# while true; do
lfs swap_layouts $((RANDOM % 2)) $((RANDOM % 2))
done &
# while true; do
lfs swap_layouts $((RANDOM % 2)) $((RANDOM % 2))
done &
The same is true of LU-2766.
patches are at: http://review.whamcloud.com/5157, http://review.whamcloud.com/5158, http://review.whamcloud.com/5159. Oleg is verifying them.
I've known the root cause of the problem, need time to cook a patch
[ 756.853670] LustreError: 25456:0:(lov_object.c:595:lov_layout_change()) ASSERTION( list_empty(&hdr->coh_locks) ) failed: [ 756.854210] LustreError: 25456:0:(lov_object.c:595:lov_layout_change()) LBUG [ 756.854498] Pid: 25456, comm: ll_sa_25403 [ 756.854724] [ 756.854725] Call Trace: [ 756.855090] [<ffffffffa0449915>] libcfs_debug_dumpstack+0x55/0x80 [libcfs] [ 756.855355] [<ffffffffa0449f17>] lbug_with_loc+0x47/0xb0 [libcfs] [ 756.855617] [<ffffffffa0a711af>] lov_layout_change+0x2df/0x350 [lov] [ 756.855874] [<ffffffffa0a714b7>] lov_conf_set+0x297/0x6a0 [lov] [ 756.856124] [<ffffffffa045a401>] ? libcfs_debug_msg+0x41/0x50 [libcfs] [ 756.856384] [<ffffffffa04629eb>] ? cfs_hash_add_unique+0x1b/0x40 [libcfs] [ 756.856807] [<ffffffffa061ad08>] cl_conf_set+0x58/0x100 [obdclass] [ 756.857073] [<ffffffffa0dd71c8>] ll_layout_conf+0x78/0x250 [lustre] [ 756.857334] [<ffffffffa0de62ea>] ll_layout_lock_set+0x40a/0xd30 [lustre] [ 756.857599] [<ffffffffa0947320>] ? lmv_set_lock_data+0x100/0x480 [lmv] [ 756.857862] [<ffffffffa0de73ef>] ll_layout_refresh+0x7df/0xd80 [lustre] [ 756.858128] [<ffffffffa0e0a560>] ? ll_md_blocking_ast+0x0/0x720 [lustre] [ 756.858411] [<ffffffffa0765370>] ? ldlm_completion_ast+0x0/0x950 [ptlrpc] [ 756.858685] [<ffffffffa0e2d2ed>] vvp_io_fini+0xfd/0x1b0 [lustre] [ 756.858939] [<ffffffffa0a7b7ad>] ? lov_io_fini+0x16d/0x3d0 [lov] [ 756.859202] [<ffffffffa062c807>] cl_io_fini+0x77/0x260 [obdclass] [ 756.859460] [<ffffffffa0e24985>] cl_glimpse_size0+0xc5/0x1d0 [lustre] [ 756.859725] [<ffffffffa0e1cde2>] ll_agl_trigger+0xd2/0x350 [lustre] [ 756.859983] [<ffffffffa0e233a7>] ll_statahead_thread+0x2d7/0xf40 [lustre] [ 756.860245] [<ffffffff81057d60>] ? default_wake_function+0x0/0x20 [ 756.860501] [<ffffffffa0e230d0>] ? ll_statahead_thread+0x0/0xf40 [lustre] [ 756.860776] [<ffffffff8100c14a>] child_rip+0xa/0x20 [ 756.861012] [<ffffffffa0e230d0>] ? ll_statahead_thread+0x0/0xf40 [lustre] [ 756.861279] [<ffffffffa0e230d0>] ? ll_statahead_thread+0x0/0xf40 [lustre] [ 756.861537] [<ffffffff8100c140>] ? child_rip+0x0/0x20 [ 756.861769] [ 756.885413] Kernel panic - not syncing: LBUG
Sometimes instead of the crash I am getting this sort of a locked up thread:
.111182] Lustre: DEBUG MARKER: == sanityn test 12: test lock ordering (link, sta .378607] Lustre: DEBUG MARKER: start dir: /mnt/lustre/lockdir=144115205255725085 .812526] LNet: Service thread pid 12451 was inactive for 40.00s. The thread migh .813279] Pid: 12451, comm: mdt00_001 .813563] .813564] Call Trace: .813979] [<ffffffff814fb054>] ? _spin_lock_irqsave+0x24/0x30 .814234] [<ffffffff814f8ad1>] schedule_timeout+0x191/0x2e0 .814507] [<ffffffff8107bcd0>] ? process_timeout+0x0/0x10 .814762] [<ffffffffa0e00771>] cfs_waitq_timedwait+0x11/0x20 [libcfs] .815052] [<ffffffffa053184d>] ldlm_completion_ast+0x4dd/0x950 [ptlrpc] .815338] [<ffffffffa052d360>] ? ldlm_expired_completion_wait+0x0/0x260 [ptlrpc] .815791] [<ffffffff81057d60>] ? default_wake_function+0x0/0x20 .816062] [<ffffffffa0530f98>] ldlm_cli_enqueue_local+0x1f8/0x5d0 [ptlrpc] .816351] [<ffffffffa0531370>] ? ldlm_completion_ast+0x0/0x950 [ptlrpc] .816692] [<ffffffffa09dc830>] ? mdt_blocking_ast+0x0/0x2a0 [mdt] .816980] [<ffffffffa09dedc0>] mdt_object_lock0+0x360/0xb10 [mdt] .817278] [<ffffffffa09dc830>] ? mdt_blocking_ast+0x0/0x2a0 [mdt] .817584] [<ffffffffa0531370>] ? ldlm_completion_ast+0x0/0x950 [ptlrpc] .817878] [<ffffffffa09df614>] mdt_object_lock+0x14/0x20 [mdt] .818158] [<ffffffffa09fef3a>] mdt_reint_link+0x3fa/0x910 [mdt] .818459] [<ffffffffa0559c5e>] ? lustre_pack_reply_flags+0xae/0x1f0 [ptlrpc] .818918] [<ffffffffa09faa91>] mdt_reint_rec+0x41/0xe0 [mdt] .819194] [<ffffffffa09f4133>] mdt_reint_internal+0x4f3/0x7e0 [mdt] .819495] [<ffffffffa09f4464>] mdt_reint+0x44/0xe0 [mdt] .819764] [<ffffffffa09e4782>] mdt_handle_common+0x8e2/0x1680 [mdt] .820052] [<ffffffffa0a19ed5>] mds_regular_handle+0x15/0x20 [mdt] .820352] [<ffffffffa0568483>] ptlrpc_server_handle_request+0x463/0xe60 [ptlrpc] .820872] [<ffffffffa0e0065e>] ? cfs_timer_arm+0xe/0x10 [libcfs] .821172] [<ffffffffa0561221>] ? ptlrpc_wait_event+0xb1/0x2a0 [ptlrpc] .821474] [<ffffffff81051f73>] ? __wake_up+0x53/0x70 .821758] [<ffffffffa056af8d>] ptlrpc_main+0xb3d/0x18c0 [ptlrpc] .822055] [<ffffffffa056a450>] ? ptlrpc_main+0x0/0x18c0 [ptlrpc] .822333] [<ffffffff8100c14a>] child_rip+0xa/0x20 .822608] [<ffffffffa056a450>] ? ptlrpc_main+0x0/0x18c0 [ptlrpc] .822904] [<ffffffffa056a450>] ? ptlrpc_main+0x0/0x18c0 [ptlrpc] .823181] [<ffffffff8100c140>] ? child_rip+0x0/0x20 .823438] .. (this thread actually finished after 100 seconds) ... .864250] INFO: task statmany:14503 blocked for more than 120 seconds. .865404] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this messag .867239] statmany D 0000000000000000 2608 14503 14484 0x00000000 .868449] ffff880055affb10 0000000000000086 ffff880055affad8 ffff880055affad4 .869752] ffff880055affaf8 ffff8800bcc23080 ffff8800063167c0 0000000000000000 .870198] ffff8800aa03e8b8 ffff880055afffd8 000000000000fba8 ffff8800aa03e8b8 .870647] Call Trace: .870842] [<ffffffff814fabbd>] rwsem_down_failed_common+0x8d/0x1d0 .871102] [<ffffffff81054aaa>] ? enqueue_task_fair+0x14a/0x4e0 .871356] [<ffffffff81096d6a>] ? sched_clock_cpu+0x6a/0x110 .871610] [<ffffffff814fad56>] rwsem_down_read_failed+0x26/0x30 .871867] [<ffffffff8127c104>] call_rwsem_down_read_failed+0x14/0x30 .872156] [<ffffffff814f9ec7>] ? down_read+0x37/0x40 .872474] [<ffffffffa0717cba>] lov_lsm_addref+0x2a/0x130 [lov] .872796] [<ffffffffa0717dea>] lov_lsm_get+0x2a/0x40 [lov] .873063] [<ffffffffa0b28c95>] ccc_inode_lsm_get+0x15/0x20 [lustre] .873332] [<ffffffffa0addb83>] ll_merge_lvb+0x53/0x5e0 [lustre] .873600] [<ffffffff814f919e>] ? mutex_unlock+0xe/0x10 .873863] [<ffffffffa0f6dd0a>] ? cl_lock_mutex_put+0x7a/0x90 [obdclass] .874149] [<ffffffffa0b283a8>] cl_glimpse_lock+0x328/0x480 [lustre] .874445] [<ffffffffa0b28a65>] cl_glimpse_size0+0x1a5/0x1d0 [lustre] .874735] [<ffffffffa0ae2298>] ll_inode_revalidate_it+0x198/0x1c0 [lustre] .875036] [<ffffffffa0ae2309>] ll_getattr_it+0x49/0x170 [lustre] .875322] [<ffffffffa0ae2467>] ll_getattr+0x37/0x40 [lustre] .875598] [<ffffffff81214fa3>] ? security_inode_getattr+0x23/0x30 .875875] [<ffffffff81180891>] vfs_getattr+0x51/0x80 .876154] [<ffffffff810385d8>] ? pvclock_clocksource_read+0x58/0xd0 .876439] [<ffffffff81180920>] vfs_fstatat+0x60/0x80 .876696] [<ffffffff81180a6b>] vfs_stat+0x1b/0x20 .876947] [<ffffffff81180a94>] sys_newstat+0x24/0x50 .877203] [<ffffffff8109b05a>] ? do_gettimeofday+0x1a/0x50 .877473] [<ffffffff8100c5b5>] ? math_state_restore+0x45/0x60 .877751] [<ffffffff814fb72e>] ? do_device_not_available+0xe/0x10 .878001] [<ffffffff8100befb>] ? device_not_available+0x1b/0x20 .878277] [<ffffffff8100b0f2>] system_call_fastpath+0x16/0x1b .878552] INFO: task ll_imp_inval:14515 blocked for more than 120 seconds. .878838] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this messag .879297] ll_imp_inval D 0000000000000003 4640 14515 2 0x00000000 .879607] ffff8800b5f31980 0000000000000046 0000000000000000 ffffffff810385d8 .880107] ffff8800ffffffff 00075e5906b4fe40 ffff8800ffffffff ffff8800b5f31980 .880590] ffff8800ac106af8 ffff8800b5f31fd8 000000000000fba8 ffff8800ac106af8 .881064] Call Trace: .881268] [<ffffffff810385d8>] ? pvclock_clocksource_read+0x58/0xd0 .881548] [<ffffffff814fabbd>] rwsem_down_failed_common+0x8d/0x1d0 .881807] [<ffffffff814fad23>] rwsem_down_write_failed+0x23/0x30 .882054] [<ffffffff8127c133>] call_rwsem_down_write_failed+0x13/0x20 .882339] [<ffffffff814f9e85>] ? down_write+0x45/0x50 .882605] [<ffffffffa0716e44>] lov_conf_lock+0x34/0xc0 [lov] .882877] [<ffffffffa0717268>] lov_conf_set+0x48/0x6a0 [lov] .883163] [<ffffffffa0f65aad>] ? cl_env_nested_get+0x5d/0xc0 [obdclass] .883465] [<ffffffffa0e189eb>] ? cfs_hash_add_unique+0x1b/0x40 [libcfs] .883771] [<ffffffffa0f63d08>] cl_conf_set+0x58/0x100 [obdclass] .884076] [<ffffffffa0adb1c8>] ll_layout_conf+0x78/0x250 [lustre] .884365] [<ffffffffa0b0e947>] ll_md_blocking_ast+0x3e7/0x720 [lustre] .884655] [<ffffffff81051f73>] ? __wake_up+0x53/0x70 .884936] [<ffffffffa051106c>] ldlm_cancel_callback+0x6c/0x1a0 [ptlrpc] .885243] [<ffffffffa052afda>] ldlm_cli_cancel_local+0x8a/0x470 [ptlrpc] .885561] [<ffffffffa052f8cb>] ldlm_cli_cancel+0x5b/0x360 [ptlrpc] .885848] [<ffffffffa0519c1d>] cleanup_resource+0x12d/0x300 [ptlrpc] .886128] [<ffffffffa0519e1f>] ldlm_resource_clean+0x2f/0x60 [ptlrpc] .886993] [<ffffffffa0e167af>] cfs_hash_for_each_relax+0x17f/0x360 [libcfs] .887434] [<ffffffffa0519df0>] ? ldlm_resource_clean+0x0/0x60 [ptlrpc] .887717] [<ffffffffa0519df0>] ? ldlm_resource_clean+0x0/0x60 [ptlrpc] .887997] [<ffffffffa0e1817f>] cfs_hash_for_each_nolock+0x7f/0x1c0 [libcfs] .888463] [<ffffffffa051685e>] ldlm_namespace_cleanup+0x2e/0xc0 [ptlrpc] .888800] [<ffffffffa04bbc81>] mdc_import_event+0x1c1/0xa30 [mdc] .889143] [<ffffffffa057993f>] ptlrpc_invalidate_import+0x29f/0x8c0 [ptlrpc] .889596] [<ffffffffa0e10401>] ? libcfs_debug_msg+0x41/0x50 [libcfs] .889870] [<ffffffffa0579f60>] ? ptlrpc_invalidate_import_thread+0x0/0x2e0 [ptlr .890341] [<ffffffffa0579faf>] ptlrpc_invalidate_import_thread+0x4f/0x2e0 [ptlrp .890807] [<ffffffff8100c14a>] child_rip+0xa/0x20 .891077] [<ffffffffa0579f60>] ? ptlrpc_invalidate_import_thread+0x0/0x2e0 [ptlr .892918] [<ffffffffa0579f60>] ? ptlrpc_invalidate_import_thread+0x0/0x2e0 [ptlr .893398] [<ffffffff8100c140>] ? child_rip+0x0/0x20 (these two threads never complete)
TGCC site hits the same issue/LBUG running an MPI-IO app on 2.1.3 (
LU-3524), I mean the original/title "(lov_io.c:212:lov_sub_get()) ASSERTION( stripe < lio->lis_stripe_count ) failed" LBUG for this ticket, so based on this can we definitely trust that this particular problem is layout related ?