On Jun 05, 2008 23:28 +0200, Jakob Goldbach wrote:> I just had to go through the "Dilger procedure" after MDS
crashing when
> mounting MDT. The system is running fine now - glad that I just learned
> about this procedure.
Hmm, looking at the size of this stack, I wonder if it is a stack
overflow problem related to bug 15575? That was fixed in 1.6.5.
At least the second stack looks to be related, and the first one
is very deep...
It does also appear that it is doing a reschedule while atomic in
the first stack, though given the number of functions there it will
be hard to determine what is making this "atomic"... Boy, do I love
Linux stack traces with every function ever called on the stack...
> [ 79.012936] BUG: scheduling while atomic: mount.lustre/0xffff8101/1361
> [ 79.014247]
> [ 79.014247] Call Trace:
> [ 79.015240] [<ffffffff8025973a>] __sched_text_start+0x7a/0x769
> [ 79.016616] [<ffffffff8023ab95>] lock_timer_base+0x1b/0x3c
> [ 79.017943] [<ffffffff8022f226>] del_timer+0x4e/0x57
> [ 79.018971] [<ffffffff802130a8>] sync_buffer+0x0/0x3f
> [ 79.020003] [<ffffffff8025a59a>] io_schedule+0x28/0x34
> [ 79.021235] [<ffffffff802130e3>] sync_buffer+0x3b/0x3f
> [ 79.022490] [<ffffffff8025a8f5>] __wait_on_bit+0x40/0x6f
> [ 79.023780] [<ffffffff802130a8>] sync_buffer+0x0/0x3f
> [ 79.024955] [<ffffffff8025a990>]
out_of_line_wait_on_bit+0x6c/0x78
> [ 79.026373] [<ffffffff80286a91>] wake_bit_function+0x0/0x23
> [ 79.027743] [<ffffffff80222c9f>] __bread+0x62/0x77
> [ 79.028724] [<ffffffff88318de2>]
:ldiskfs:read_block_bitmap+0xa2/0xf0
> [ 79.030245] [<ffffffff88319695>]
:ldiskfs:ldiskfs_free_blocks_sb+0x115/0x510
> [ 79.031856] [<ffffffff88319b21>]
:ldiskfs:ldiskfs_free_blocks+0x91/0xe0
> [ 79.033392] [<ffffffff8831ed1a>]
:ldiskfs:ldiskfs_free_data+0x8a/0x110
> [ 79.034944] [<ffffffff8831f19c>]
:ldiskfs:ldiskfs_truncate+0x20c/0x650
> [ 79.036261] [<ffffffff802dbeab>] start_this_handle+0x355/0x405
> [ 79.037705] [<ffffffff8831fbb4>]
:ldiskfs:ldiskfs_delete_inode+0x84/0xf0
> [ 79.039043] [<ffffffff8831fb30>]
:ldiskfs:ldiskfs_delete_inode+0x0/0xf0
> [ 79.040636] [<ffffffff8022c804>] generic_delete_inode+0x8e/0x10b
> [ 79.042042] [<ffffffff883ce891>] :mds:mds_obd_destroy+0xa11/0xad0
> [ 79.044727] [<ffffffff880f361b>]
:obdclass:llog_lvfs_close+0x6b/0x130
The fput->dput->iput->generic_drop_inode() part of the chain
_appears_ to be where the stack is going, and following it down further
ldiskfs_delete_inode->
ldiskfs_truncate->
ldiskfs_free_data->
ldiskfs_free_blocks->
ldiskfs_free_blocks_sb->
read_block_bitmap->
__bread()
is calling might_sleep(), so the fact that we schedule later on
shouldn''t come as a surprise, unless, it seems, the kernel is compiled
without CONFIG_DEBUG_SPINLOCK_SLEEP enabled. In that case, this kind
of problem would be hit only when we actually DO sleep waiting for IO,
> [ 79.046201] [<ffffffff880f46c1>]
:obdclass:llog_lvfs_destroy+0x841/0xa10
It seems we are going into llog_lvfs_destroy() while processing the
configuration log, which is a bit strange, unless this is due to the
MDS->LOV->OSC hitting an empty log during startup and deleting it.
That in itself shouldn''t be harmful...
There is (as can be seen below) a twisty maze of callbacks related to
the distributed logging code, but it doesn''t appear to be holding a
spinlock that would make it atomic. Looking at my kernel, in_atomic()
is set for a number of reasons (IRQ, NMI, etc) but the most common
reason is because of spinlock, unless CONFIG_PREEMPT is enabled.
> [ 79.047756] [<ffffffff880f0a0f>]
:obdclass:llog_cat_id2handle+0x4cf/0x5f0
> [ 79.050501] [<ffffffff880fa9c5>]
:obdclass:cat_cancel_cb+0x405/0x630
> [ 79.051984] [<ffffffff880f0129>]
:obdclass:llog_process+0xa09/0xe20
In 1.6.5 (due to bug 15575) a new thread is started at this point to process
the per-OSC log.
> [ 79.054539] [<ffffffff880fa5c0>]
:obdclass:cat_cancel_cb+0x0/0x630
> [ 79.055959] [<ffffffff880fa3b3>]
:obdclass:llog_obd_origin_setup+0x773/0x980
> [ 79.058716] [<ffffffff880fb37d>] :obdclass:llog_setup+0x78d/0x860
> [ 79.060114] [<ffffffff8840ea94>] :osc:osc_llog_init+0x104/0x390
> [ 79.061491] [<ffffffff880f9855>]
:obdclass:__llog_ctxt_put+0x25/0xe0
> [ 79.062957] [<ffffffff880f8979>]
:obdclass:obd_llog_init+0x179/0x210
> [ 79.064362] [<ffffffff882632ca>] :lov:lov_llog_init+0x2ca/0x400
> [ 79.065556] [<ffffffff880f8979>]
:obdclass:obd_llog_init+0x179/0x210
> [ 79.068313] [<ffffffff883941ad>] :mds:mds_llog_init+0x1ad/0x270
> [ 79.070777] [<ffffffff880f8979>]
:obdclass:obd_llog_init+0x179/0x210
> [ 79.073520] [<ffffffff880f8dc5>]
:obdclass:llog_cat_initialize+0x3b5/0x670
> [ 79.075090] [<ffffffff88277c61>] :lov:lov_get_info+0x9f1/0xaa0
> [ 79.076405] [<ffffffff8828f6c1>] :lov:qos_add_tgt+0x681/0x730
> [ 79.077573] [<ffffffff8839d5ac>]
:mds:mds_lov_update_desc+0xbcc/0xd30
> [ 79.079050] [<ffffffff883a03ec>] :mds:mds_notify+0x36c/0x690
> [ 79.080630] [<ffffffff8826c657>] :lov:lov_notify+0xa97/0xfd0
> [ 79.081820] [<ffffffff8826d73f>] :lov:lov_add_target+0xbaf/0xd20
> [ 79.083220] [<ffffffff88276fc5>]
:lov:lov_process_config+0x2f5/0x5a0
> [ 79.084497] [<ffffffff88119e45>]
:obdclass:class_setup+0xa25/0xbe0
> [ 79.085998] [<ffffffff8811c713>]
:obdclass:class_process_config+0x1873/0x19f0
> [ 79.087645] [<ffffffff8811f6da>]
:obdclass:class_config_llog_handler+0x153a/0x1990
> [ 79.090595] [<ffffffff880f5cfc>]
:obdclass:llog_lvfs_next_block+0x2ac/0x710
> [ 79.092190] [<ffffffff880f0129>]
:obdclass:llog_process+0xa09/0xe20
> [ 79.096723] [<ffffffff8811e02f>]
:obdclass:class_config_parse_llog+0x43f/0x5b0
> [ 79.102093] [<ffffffff88350e03>]
:mgc:mgc_process_log+0x20f3/0x2640
> [ 79.107469] [<ffffffff88354fc2>]
:mgc:mgc_process_config+0xe02/0x1280
> [ 79.109041] [<ffffffff881235bc>]
:obdclass:lustre_process_log+0xb2c/0xee0
> [ 79.114807] [<ffffffff8812dc27>]
:obdclass:server_fill_super+0x18c7/0x1ee0
> [ 79.131643] [<ffffffff8812e240>]
:obdclass:lustre_fill_super+0x0/0x1ae0
The rest of this stack appears to be free of spinlocks.
> [ 79.133004] [<ffffffff802a9805>] get_sb_nodev+0x4f/0x97
> [ 79.134075] [<ffffffff802a910b>] vfs_kern_mount+0x93/0x11a
> [ 79.135339] [<ffffffff802a91d4>] do_kern_mount+0x36/0x4d
> [ 79.136603] [<ffffffff802b1982>] do_mount+0x68c/0x6ff
> [ 79.146265] [<ffffffff802472dd>] sys_mount+0x8a/0xd7
> [ 79.147348] [<ffffffff80256d82>] system_call+0x7e/0x83
> [ 79.148544]
> [ 79.148991] Unable to handle kernel paging request at 00000000dc6bd3c0
RIP:
> [ 79.150031] [<ffffffff80259b26>] __sched_text_start+0x466/0x769
> [ 79.152010] PGD 12a825067 PUD 0
> [ 79.152857] Oops: 0000 [1] SMP
> [ 79.153722] CPU 0
> [ 79.154243] Modules linked in: osc mds fsfilt_ldiskfs mgs mgc ldiskfs
crc16 lustre lov lquota mdc ksocklnd ptlrpc obdclass lnet lvfs libcfs bonding
dm_snapshot dm_mirror dm_mod generic piix ehci_hcd uhci_hcd serio_raw ide_core
> [ 79.159949] Pid: 1361, comm: mount.lustre Not tainted
2.6.18.8-bnx2-1.6.7b-cciss-3.6.18-5-lustre-1.6.4.3 #2
> [ 79.161839] RIP: 0010:[<ffffffff80259b26>]
[<ffffffff80259b26>] __sched_text_start+0x466/0x769
> [ 79.163876] RSP: 0018:ffff810129416428 EFLAGS: 00010083
> [ 79.165063] RAX: ffffffff80565b80 RBX: ffff8100010232a0 RCX:
ffff81012a7b4890
> [ 79.166653] RDX: 000000002b833000 RSI: 000000126da5b456 RDI:
ffff81012a7b4890
> [ 79.168235] RBP: ffff8101294164b8 R08: 000000000000000e R09:
0000000000000001
> [ 79.169873] R10: 0000000500000000 R11: ffffffff80308b2e R12:
ffff81012a7b48d0
> [ 79.171286] R13: 0000000000000000 R14: ffff8100010232a0 R15:
000000126da5b456
> [ 79.172891] FS: 00002b1bc60256d0(0000) GS:ffffffff8051a000(0000)
knlGS:0000000000000000
> [ 79.174483] CS: 0010 DS: 0000 ES: 0000 CR0: 000000008005003b
> [ 79.175868] CR2: 00000000dc6bd3c0 CR3: 000000012a470000 CR4:
00000000000006e0
> [ 79.177265] Process mount.lustre (pid: 1361, threadinfo
ffff810129416000, task ffff81012a7b4890)
> [ 79.179246] Stack: 0000000000000082 ffffffff8023ab95 0000000000000005
ffff81012a7b4890
> [ 79.181207] ffff81012a7b4890 00000000081c78be ffff81012a7b4a70
ffffc20000018080
> [ 79.183084] 0000000000000082 ffff81012bb25928 ffff81012aa4a2f0
ffff810129416548
> [ 79.184872] Call Trace:
> [ 79.185601] [<ffffffff8023ab95>] lock_timer_base+0x1b/0x3c
> [ 79.186856] [<ffffffff802130a8>] sync_buffer+0x0/0x3f
> [ 79.188000] [<ffffffff8025a59a>] io_schedule+0x28/0x34
> [ 79.189216] [<ffffffff802130e3>] sync_buffer+0x3b/0x3f
> [ 79.190405] [<ffffffff8025a8f5>] __wait_on_bit+0x40/0x6f
> [ 79.191691] [<ffffffff802130a8>] sync_buffer+0x0/0x3f
> [ 79.192848] [<ffffffff8025a990>]
out_of_line_wait_on_bit+0x6c/0x78
> [ 79.194199] [<ffffffff80286a91>] wake_bit_function+0x0/0x23
> [ 79.195488] [<ffffffff80222c9f>] __bread+0x62/0x77
> [ 79.196605] [<ffffffff88318de2>]
:ldiskfs:read_block_bitmap+0xa2/0xf0
> [ 79.198071] [<ffffffff88319695>]
:ldiskfs:ldiskfs_free_blocks_sb+0x115/0x510
> [ 79.199681] [<ffffffff88319b21>]
:ldiskfs:ldiskfs_free_blocks+0x91/0xe0
> [ 79.201172] [<ffffffff8831ed1a>]
:ldiskfs:ldiskfs_free_data+0x8a/0x110
> [ 79.202645] [<ffffffff8831f19c>]
:ldiskfs:ldiskfs_truncate+0x20c/0x650
> [ 79.203937] [<ffffffff802dbeab>] start_this_handle+0x355/0x405
> [ 79.205123] [<ffffffff8831fbb4>]
:ldiskfs:ldiskfs_delete_inode+0x84/0xf0
> [ 79.206676] [<ffffffff8831fb30>]
:ldiskfs:ldiskfs_delete_inode+0x0/0xf0
> [ 79.208188] [<ffffffff8022c804>] generic_delete_inode+0x8e/0x10b
> [ 79.209572] [<ffffffff883ce891>] :mds:mds_obd_destroy+0xa11/0xad0
> [ 79.211006] [<ffffffff8022a2d7>] mntput_no_expire+0x19/0x8b
> [ 79.212383] [<ffffffff880f361b>]
:obdclass:llog_lvfs_close+0x6b/0x130
> [ 79.213856] [<ffffffff880f46c1>]
:obdclass:llog_lvfs_destroy+0x841/0xa10
> [ 79.215684] [<ffffffff880f0a0f>]
:obdclass:llog_cat_id2handle+0x4cf/0x5f0
> [ 79.217022] [<ffffffff8021557d>] cache_grow+0x2ee/0x343
> [ 79.218241] [<ffffffff880fa9c5>]
:obdclass:cat_cancel_cb+0x405/0x630
> [ 79.219828] [<ffffffff880f0129>]
:obdclass:llog_process+0xa09/0xe20
> [ 79.221330] [<ffffffff8020c894>] dput+0x23/0x152
> [ 79.222420] [<ffffffff880fa5c0>]
:obdclass:cat_cancel_cb+0x0/0x630
> [ 79.223661] [<ffffffff880fa3b3>]
:obdclass:llog_obd_origin_setup+0x773/0x980
> [ 79.225255] [<ffffffff8021819f>] vsnprintf+0x55e/0x5a3
> [ 79.226488] [<ffffffff880fb37d>] :obdclass:llog_setup+0x78d/0x860
> [ 79.227893] [<ffffffff8840ea94>] :osc:osc_llog_init+0x104/0x390
> [ 79.229275] [<ffffffff880f9855>]
:obdclass:__llog_ctxt_put+0x25/0xe0
> [ 79.230739] [<ffffffff880f8979>]
:obdclass:obd_llog_init+0x179/0x210
> [ 79.232202] [<ffffffff882632ca>] :lov:lov_llog_init+0x2ca/0x400
> [ 79.233576] [<ffffffff880f8979>]
:obdclass:obd_llog_init+0x179/0x210
> [ 79.234861] [<ffffffff8022a2d7>] mntput_no_expire+0x19/0x8b
> [ 79.236221] [<ffffffff883941ad>] :mds:mds_llog_init+0x1ad/0x270
> [ 79.237588] [<ffffffff8029abcb>] map_vm_area+0x229/0x2a8
> [ 79.238814] [<ffffffff880f8979>]
:obdclass:obd_llog_init+0x179/0x210
> [ 79.240305] [<ffffffff8029af5b>] __vmalloc_area_node+0x12b/0x153
> [ 79.241744] [<ffffffff880f8dc5>]
:obdclass:llog_cat_initialize+0x3b5/0x670
> [ 79.243379] [<ffffffff88277c61>] :lov:lov_get_info+0x9f1/0xaa0
> [ 79.244551] [<ffffffff8828f6c1>] :lov:qos_add_tgt+0x681/0x730
> [ 79.245954] [<ffffffff8839d5ac>]
:mds:mds_lov_update_desc+0xbcc/0xd30
> [ 79.247431] [<ffffffff883a03ec>] :mds:mds_notify+0x36c/0x690
> [ 79.248593] [<ffffffff8826c657>] :lov:lov_notify+0xa97/0xfd0
> [ 79.249895] [<ffffffff8826d73f>] :lov:lov_add_target+0xbaf/0xd20
> [ 79.251104] [<ffffffff88276fc5>]
:lov:lov_process_config+0x2f5/0x5a0
> [ 79.252560] [<ffffffff88119e45>]
:obdclass:class_setup+0xa25/0xbe0
> [ 79.253987] [<ffffffff8811c713>]
:obdclass:class_process_config+0x1873/0x19f0
> [ 79.255750] [<ffffffff8811f6da>]
:obdclass:class_config_llog_handler+0x153a/0x1990
> [ 79.257435] [<ffffffff80224869>] do_filp_open+0x2d/0x3d
> [ 79.258734] [<ffffffff880f5cfc>]
:obdclass:llog_lvfs_next_block+0x2ac/0x710
> [ 79.260274] [<ffffffff880f0129>]
:obdclass:llog_process+0xa09/0xe20
> [ 79.261527] [<ffffffff88081f48>] :libcfs:cfs_alloc+0x28/0x60
> [ 79.262699] [<ffffffff8811e1a0>]
:obdclass:class_config_llog_handler+0x0/0x1990
> [ 79.264384] [<ffffffff8811e02f>]
:obdclass:class_config_parse_llog+0x43f/0x5b0
> [ 79.266025] [<ffffffff8020c8a5>] dput+0x34/0x152
> [ 79.266984] [<ffffffff880a3052>] :lvfs:lustre_rename+0x482/0x530
> [ 79.268363] [<ffffffff880edfea>] :obdclass:llog_close+0x1aa/0x230
> [ 79.269620] [<ffffffff88350e03>]
:mgc:mgc_process_log+0x20f3/0x2640
> [ 79.271057] [<ffffffff88351b90>] :mgc:mgc_blocking_ast+0x0/0x450
> [ 79.272465] [<ffffffff88187eb0>]
:ptlrpc:ldlm_completion_ast+0x0/0x6a0
> [ 79.273927] [<ffffffff8834e85c>] :mgc:config_log_find+0x19c/0x340
> [ 79.275393] [<ffffffff88354fc2>]
:mgc:mgc_process_config+0xe02/0x1280
> [ 79.276901] [<ffffffff881235bc>]
:obdclass:lustre_process_log+0xb2c/0xee0
> [ 79.278350] [<ffffffff88123a40>]
:obdclass:server_find_mount+0x80/0x190
> [ 79.279679] [<ffffffff881297a6>]
:obdclass:server_start_targets+0xb36/0x17e0
> [ 79.281332] [<ffffffff8022d4ac>] __up_write+0x21/0x10d
> [ 79.282569] [<ffffffff8812dc27>]
:obdclass:server_fill_super+0x18c7/0x1ee0
> [ 79.284209] [<ffffffff80208d6d>] __d_lookup+0xb0/0x100
> [ 79.285443] [<ffffffff88081f48>] :libcfs:cfs_alloc+0x28/0x60
> [ 79.286748] [<ffffffff881218bf>]
:obdclass:lustre_init_lsi+0x29f/0x660
> [ 79.288061] [<ffffffff8812e240>]
:obdclass:lustre_fill_super+0x0/0x1ae0
> [ 79.289689] [<ffffffff8812fba3>]
:obdclass:lustre_fill_super+0x1963/0x1ae0
> [ 79.291253] [<ffffffff802a95f5>] set_anon_super+0x3c/0xab
> [ 79.292509] [<ffffffff802a95b9>] set_anon_super+0x0/0xab
> [ 79.293753] [<ffffffff8812e240>]
:obdclass:lustre_fill_super+0x0/0x1ae0
> [ 79.295307] [<ffffffff802a9805>] get_sb_nodev+0x4f/0x97
> [ 79.296378] [<ffffffff802a910b>] vfs_kern_mount+0x93/0x11a
> [ 79.297503] [<ffffffff802a91d4>] do_kern_mount+0x36/0x4d
> [ 79.298573] [<ffffffff802b1982>] do_mount+0x68c/0x6ff
> [ 79.299597] [<ffffffff802088d3>] __handle_mm_fault+0x530/0x91a
> [ 79.300980] [<ffffffff80218776>] remove_vma+0x55/0x5c
> [ 79.302120] [<ffffffff8021f84a>] __up_read+0x13/0x8a
> [ 79.303274] [<ffffffff8020a6af>] do_page_fault+0x3d1/0x706
> [ 79.304385] [<ffffffff8020c2e4>] do_path_lookup+0x268/0x28c
> [ 79.305672] [<ffffffff80297807>] zone_statistics+0x3e/0x6d
> [ 79.306937] [<ffffffff8020dcbc>] __alloc_pages+0x5c/0x29b
> [ 79.308172] [<ffffffff802472dd>] sys_mount+0x8a/0xd7
> [ 79.309361] [<ffffffff80256d82>] system_call+0x7e/0x83
> [ 79.310598]
> [ 79.310975]
> [ 79.310975] Code: 48 8b 14 d5 c0 53 52 80 48 03 42 08 c7 40 08 01 00 00
00 49
> [ 79.313904] RIP [<ffffffff80259b26>]
__sched_text_start+0x466/0x769
> [ 79.315396] RSP <ffff810129416428>
> [ 79.316117] CR2: 00000000dc6bd3c0
> [ 79.316939] <3>LustreError:
1266:0:(client.c:975:ptlrpc_expire_one_request()) @@@ timeout (sent at
1212696480, 5s ago) req at ffff81012aa50200 x7/t0 o8->iloapp3-OST0000_UUID
at 172.16.4.70@tcp:6 lens 240/272 ref 1 fl Rpc:/0/0 rc 0/-22
> [ 95.018738] warning: many lost ticks.
> [ 95.018739] Your time source seems to be instable or some driver is
hogging interupts
> [ 95.021152] rip mwait_idle+0x36/0x4a
> [ 95.021973] Falling back to HPET
>
> _______________________________________________
> Lustre-discuss mailing list
> Lustre-discuss at lists.lustre.org
> http://lists.lustre.org/mailman/listinfo/lustre-discuss
Cheers, Andreas
--
Andreas Dilger
Sr. Staff Engineer, Lustre Group
Sun Microsystems of Canada, Inc.