From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754568Ab0BKONd (ORCPT ); Thu, 11 Feb 2010 09:13:33 -0500 Received: from lucidpixels.com ([75.144.35.66]:46292 "EHLO lucidpixels.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752381Ab0BKONb (ORCPT ); Thu, 11 Feb 2010 09:13:31 -0500 Date: Thu, 11 Feb 2010 09:13:31 -0500 (EST) From: Justin Piszcz To: linux-kernel@vger.kernel.org, linux-raid@vger.kernel.org, xfs@oss.sgi.com, Alan Piszcz Subject: Re: 2.6.32.3 x86_64 - XFS hangs, all I/O to D-state bug (again) In-Reply-To: Message-ID: References: User-Agent: Alpine 2.00 (DEB 1167 2008-08-23) MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII; format=flowed Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org The errors in the e-mail had bad formatting, please see the following: http://home.comcast.net/~jpiszcz/20100211/crash.txt In addition, the linux-raid list had a typo in it, fixed. On Thu, 11 Feb 2010, Justin Piszcz wrote: > Hello, > > While tarring and compressing (bzip2) a lot of files, the following error > occurred, note the output is not clean because this was taken from > netconsole. > > When this occurs, the host cannot be rebooted with reboot/proceses cannot > be killed and the box locks up. There are no apparent hardware issues. > > Before, asterisk would trigger this bug, since asterisk no longer runs on > this host, it ran for ~2-3 months without any problems, until now. > > Please cc me as I am not on the lists, thanks. > > Is this a md raid issue or XFS? From the trace it appears to be an XFS bug? > > Feb 11 07:38:14 l1 [ 20.270270] e100: eth1 NIC Link is Up 100 Mbps Full > Duplex Feb 11 07:47:54 l1 [ 600.432165] INFO: task scp:4871 blocked for more > than 120 seconds. Feb 11 07:47:54 l1 [ 600.432177] "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 11 > 07:47:54 l1 [ 600.432182] scp D > Feb 11 07:47:54 l1 ffff8801eee6f14c Feb 11 07:47:54 l1 0 4871 4870 > 0x00000000 Feb 11 07:47:54 l1 [ 600.432188] ffff880220c87950 > Feb 11 07:47:54 l1 0000000000000082 > Feb 11 07:47:54 l1 0000000000200200 > Feb 11 07:47:54 l1 ffff88023eb71400 > Feb 11 07:47:54 l1 Feb 11 07:47:54 l1 [ 600.432196] 000000000000c928 > Feb 11 07:47:54 l1 ffff8801f7a55fd8 > Feb 11 07:47:54 l1 ffff880205fc6150 > Feb 11 07:47:54 l1 ffff880205fc63c8 > Feb 11 07:47:54 l1 Feb 11 07:47:54 l1 [ 600.432203] 0000000000001000 > Feb 11 07:47:54 l1 ffffffff8108d02a > Feb 11 07:47:54 l1 ffff8801eee6f0c0 > Feb 11 07:47:54 l1 ffff880205fc63c8 > Feb 11 07:47:54 l1 Feb 11 07:47:54 l1 [ 600.432209] Call Trace: Feb 11 > 07:47:54 l1 [ 600.432230] [] ? > generic_file_buffered_write+0x1aa/0x290 Feb 11 07:47:54 l1 [ 600.432236] > [] ? __down_write_nested+0x7d/0xb0 Feb 11 07:47:54 l1 [ > 600.432242] [] ? xfs_write+0x23d/0x950 Feb 11 07:47:54 l1 > [ 600.432250] [] ? do_sync_write+0xe3/0x130 Feb 11 > 07:47:54 l1 [ 600.432260] [] ? > autoremove_wake_function+0x0/0x30 Feb 11 07:47:54 l1 [ 600.432266] > [] ? fsnotify+0x4/0x1a0 Feb 11 07:47:54 l1 [ 600.432271] > [] ? common_interrupt+0xe/0x13 Feb 11 07:47:54 l1 [ > 600.432276] [] ? vfs_write+0xcb/0x180 Feb 11 07:47:54 l1 [ > 600.432280] [] ? sys_write+0x53/0xa0 Feb 11 07:47:54 l1 [ > 600.432285] [] ? system_call_fastpath+0x16/0x1b Feb 11 > 07:47:54 l1 [ 600.432291] INFO: task flush-9:3:4874 blocked for more than > 120 seconds. Feb 11 07:47:54 l1 [ 600.432294] "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 11 > 07:47:54 l1 [ 600.432297] flush-9:3 D > Feb 11 07:47:54 l1 ffff88021948d750 Feb 11 07:47:54 l1 0 4874 2 > 0x00000000 Feb 11 07:47:54 l1 [ 600.432309] ffff88023fa3c8c0 > Feb 11 07:47:54 l1 0000000000000046 > Feb 11 07:47:54 l1 000000001948d750 > Feb 11 07:47:54 l1 ffffffff8163d788 > Feb 11 07:47:54 l1 Feb 11 07:47:54 l1 [ 600.432323] 000000000000c928 > Feb 11 07:47:54 l1 ffff8801f79fbfd8 > Feb 11 07:47:54 l1 ffff88021948d750 > Feb 11 07:47:54 l1 ffff88021948d9c8 > Feb 11 07:47:54 l1 Feb 11 07:47:54 l1 [ 600.432329] 000000013f467bb0 > Feb 11 07:47:54 l1 ffffffff8108c183 > Feb 11 07:47:54 l1 0000000000000000 > Feb 11 07:47:54 l1 ffff88021948d9c8 > Feb 11 07:47:54 l1 Feb 11 07:47:54 l1 [ 600.432337] Call Trace: Feb 11 > 07:47:54 l1 [ 600.432341] [] ? find_lock_page+0x23/0x80 > Feb 11 07:47:54 l1 [ 600.432344] [] ? > find_or_create_page+0x41/0xc0 Feb 11 07:47:54 l1 [ 600.432349] > [] ? schedule_timeout+0x195/0x1f0 Feb 11 07:47:54 l1 [ > 600.432352] [] ? __down+0x61/0xa0 Feb 11 07:47:54 l1 [ > 600.432356] [] ? down+0x46/0x50 Feb 11 07:47:54 l1 [ > 600.432360] [] ? _xfs_buf_find+0x134/0x220 Feb 11 07:47:54 > l1 [ 600.432363] [] ? xfs_buf_get_flags+0x6e/0x190 Feb 11 > 07:47:54 l1 [ 600.432366] [] ? > xfs_buf_read_flags+0x12/0xa0 Feb 11 07:47:54 l1 [ 600.432371] > [] ? xfs_trans_read_buf+0x1f6/0x350 Feb 11 07:47:54 l1 [ > 600.432377] [] ? xfs_read_agf+0x68/0x190 Feb 11 07:47:54 > l1 [ 600.432380] [] ? xfs_alloc_read_agf+0x30/0xd0 Feb 11 > 07:47:54 l1 [ 600.432383] [] ? > xfs_alloc_fix_freelist+0x379/0x450 Feb 11 07:47:54 l1 [ 600.432388] > [] ? xfs_iext_remove+0x35/0x80 Feb 11 07:47:54 l1 [ > 600.432393] [] ? > xfs_bmap_add_extent_delay_real+0x5ef/0x11a0 Feb 11 07:47:54 l1 [ 600.432396] > [] ? xfs_trans_log_buf+0x63/0xa0 Feb 11 07:47:54 l1 [ > 600.432401] [] ? xlog_state_get_iclog_space+0x60/0x2c0 Feb > 11 07:47:54 l1 [ 600.432404] [] ? __down_read+0x17/0xae > Feb 11 07:47:54 l1 [ 600.432408] [] ? > xfs_alloc_vextent+0x310/0x4b0 Feb 11 07:47:54 l1 [ 600.432412] > [] ? xfs_bmap_btalloc+0x598/0xa40 Feb 11 07:47:54 l1 [ > 600.432417] [] ? xfs_bmapi+0x9e2/0x11a0 Feb 11 07:47:54 l1 > [ 600.432422] [] ? xfs_trans_reserve+0x9f/0x210 Feb 11 > 07:47:54 l1 [ 600.432425] [] ? > xfs_iomap_write_allocate+0x23e/0x3b0 Feb 11 07:47:54 l1 [ 600.432429] > [] ? xfs_iomap+0x2c0/0x300 Feb 11 07:47:54 l1 [ > 600.432433] [] ? xfs_map_blocks+0x25/0x30 Feb 11 07:47:54 > l1 [ 600.432437] [] ? xfs_page_state_convert+0x414/0x6c0 > Feb 11 07:47:54 l1 [ 600.432443] [] ? > radix_tree_gang_lookup_tag_slot+0xc3/0xf0 Feb 11 07:47:54 l1 [ 600.432447] > [] ? xfs_vm_writepage+0x77/0x130 Feb 11 07:47:54 l1 [ > 600.432453] [] ? __writepage+0xa/0x40 Feb 11 07:47:54 l1 [ > 600.432456] [] ? write_cache_pages+0x1df/0x3c0 Feb 11 > 07:47:54 l1 [ 600.432459] [] ? __writepage+0x0/0x40 Feb > 11 07:47:54 l1 [ 600.432464] [] ? > writeback_single_inode+0xd2/0x390 Feb 11 07:47:54 l1 [ 600.432468] > [] ? writeback_inodes_wb+0x3ff/0x5e0 Feb 11 07:47:54 l1 [ > 600.432473] [] ? wb_writeback+0x11e/0x1f0 Feb 11 07:47:54 > l1 [ 600.432479] [] ? try_to_del_timer_sync+0x5e/0x90 Feb > 11 07:47:54 l1 [ 600.432484] [] ? > wb_do_writeback+0x17b/0x180 Feb 11 07:47:54 l1 [ 600.432487] > [] ? bdi_writeback_task+0x5d/0xa0 Feb 11 07:47:54 l1 [ > 600.432492] [] ? bdi_start_fn+0x0/0xf0 Feb 11 07:47:54 l1 > [ 600.432496] [] ? bdi_start_fn+0x7e/0xf0 Feb 11 07:47:54 > l1 [ 600.432499] [] ? bdi_start_fn+0x0/0xf0 Feb 11 > 07:47:54 l1 [ 600.432503] [] ? kthread+0x96/0xa0 Feb 11 > 07:47:54 l1 [ 600.432508] [] ? child_rip+0xa/0x20 Feb 11 > 07:47:54 l1 [ 600.432513] [] ? kthread+0x0/0xa0 Feb 11 > 07:47:54 l1 [ 600.432517] [] ? child_rip+0x0/0x20 Feb 11 > 07:49:54 l1 [ 720.432171] INFO: task scp:4871 blocked for more than 120 > seconds. Feb 11 07:49:54 l1 [ 720.432187] "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 11 > 07:49:54 l1 [ 720.432192] scp D > Feb 11 07:49:54 l1 ffff8801eee6f14c Feb 11 07:49:54 l1 0 4871 4870 > 0x00000000 Feb 11 07:49:54 l1 [ 720.432198] ffff880220c87950 > Feb 11 07:49:54 l1 0000000000000082 > Feb 11 07:49:54 l1 0000000000200200 > Feb 11 07:49:54 l1 ffff88023eb71400 > Feb 11 07:49:54 l1 Feb 11 07:49:54 l1 [ 720.432206] 000000000000c928 > Feb 11 07:49:54 l1 ffff8801f7a55fd8 > Feb 11 07:49:54 l1 ffff880205fc6150 > Feb 11 07:49:54 l1 ffff880205fc63c8 > Feb 11 07:49:54 l1 Feb 11 07:49:54 l1 [ 720.432217] 0000000000001000 > Feb 11 07:49:54 l1 ffffffff8108d02a > Feb 11 07:49:54 l1 ffff8801eee6f0c0 > Feb 11 07:49:54 l1 ffff880205fc63c8 > Feb 11 07:49:54 l1 Feb 11 07:49:54 l1 [ 720.432224] Call Trace: Feb 11 > 07:49:54 l1 [ 720.432238] [] ? > generic_file_buffered_write+0x1aa/0x290 Feb 11 07:49:54 l1 [ 720.432243] > [] ? __down_write_nested+0x7d/0xb0 Feb 11 07:49:54 l1 [ > 720.432249] [] ? xfs_write+0x23d/0x950 Feb 11 07:49:54 l1 > [ 720.432254] [] ? do_sync_write+0xe3/0x130 Feb 11 > 07:49:54 l1 [ 720.432259] [] ? > autoremove_wake_function+0x0/0x30 Feb 11 07:49:54 l1 [ 720.432265] > [] ? fsnotify+0x4/0x1a0 Feb 11 07:49:54 l1 [ 720.432270] > [] ? common_interrupt+0xe/0x13 Feb 11 07:49:54 l1 [ > 720.432275] [] ? vfs_write+0xcb/0x180 Feb 11 07:49:54 l1 [ > 720.432280] [] ? sys_write+0x53/0xa0 Feb 11 07:49:54 l1 [ > 720.432285] [] ? system_call_fastpath+0x16/0x1b Feb 11 > 07:49:54 l1 [ 720.432291] INFO: task flush-9:3:4874 blocked for more than > 120 seconds. Feb 11 07:49:54 l1 [ 720.432295] "echo 0 > > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Feb 11 > 07:49:54 l1 [ 720.432298] flush-9:3 D > Feb 11 07:49:54 l1 ffff88021948d750 Feb 11 07:49:54 l1 0 4874 2 > 0x00000000 Feb 11 07:49:54 l1 [ 720.432306] ffff88023fa3c8c0 > Feb 11 07:49:54 l1 0000000000000046 > Feb 11 07:49:54 l1 000000001948d750 > Feb 11 07:49:54 l1 ffffffff8163d788 > Feb 11 07:49:54 l1 Feb 11 07:49:54 l1 [ 720.432322] 000000000000c928 > Feb 11 07:49:54 l1 ffff8801f79fbfd8 > Feb 11 07:49:54 l1 ffff88021948d750 > Feb 11 07:49:54 l1 ffff88021948d9c8 > Feb 11 07:49:54 l1 Feb 11 07:49:54 l1 [ 720.432329] 000000013f467bb0 > Feb 11 07:49:54 l1 ffffffff8108c183 > Feb 11 07:49:54 l1 0000000000000000 > Feb 11 07:49:54 l1 ffff88021948d9c8 > Feb 11 07:49:54 l1 Feb 11 07:49:54 l1 [ 720.432336] Call Trace: Feb 11 > 07:49:54 l1 [ 720.432340] [] ? find_lock_page+0x23/0x80 > Feb 11 07:49:54 l1 [ 720.432343] [] ? > find_or_create_page+0x41/0xc0 Feb 11 07:49:54 l1 [ 720.432348] > [] ? schedule_timeout+0x195/0x1f0 Feb 11 07:49:54 l1 [ > 720.432351] [] ? __down+0x61/0xa0 Feb 11 07:49:54 l1 [ > 720.432356] [] ? down+0x46/0x50 Feb 11 07:49:54 l1 [ > 720.432361] [] ? _xfs_buf_find+0x134/0x220 Feb 11 07:49:54 > l1 [ 720.432365] [] ? xfs_buf_get_flags+0x6e/0x190 Feb 11 > 07:49:54 l1 [ 720.432368] [] ? > xfs_buf_read_flags+0x12/0xa0 Feb 11 07:49:54 l1 [ 720.432373] > [] ? xfs_trans_read_buf+0x1f6/0x350 Feb 11 07:49:54 l1 [ > 720.432378] [] ? xfs_read_agf+0x68/0x190 Feb 11 07:49:54 > l1 [ 720.432382] [] ? xfs_alloc_read_agf+0x30/0xd0 Feb 11 > 07:49:54 l1 [ 720.432386] [] ? > xfs_alloc_fix_freelist+0x379/0x450 Feb 11 07:49:54 l1 [ 720.432391] > [] ? xfs_iext_remove+0x35/0x80 Feb 11 07:49:54 l1 [ > 720.432396] [] ? > xfs_bmap_add_extent_delay_real+0x5ef/0x11a0 Feb 11 07:49:54 l1 [ 720.432399] > [] ? xfs_trans_log_buf+0x63/0xa0 Feb 11 07:49:54 l1 [ > 720.432404] [] ? xlog_state_get_iclog_space+0x60/0x2c0 Feb > 11 07:49:54 l1 [ 720.432410] [] ? __down_read+0x17/0xae > Feb 11 07:49:54 l1 [ 720.432415] [] ? > xfs_alloc_vextent+0x310/0x4b0 Feb 11 07:49:54 l1 [ 720.432420] > [] ? xfs_bmap_btalloc+0x598/0xa40 Feb 11 07:49:54 l1 [ > 720.432426] [] ? xfs_bmapi+0x9e2/0x11a0 Feb 11 07:49:54 l1 > [ 720.432430] [] ? xfs_trans_reserve+0x9f/0x210 Feb 11 > 07:49:54 l1 [ 720.432434] [] ? > xfs_iomap_write_allocate+0x23e/0x3b0 Feb 11 07:49:54 l1 [ 720.432437] > [] ? xfs_iomap+0x2c0/0x300 Feb 11 07:49:54 l1 [ > 720.432441] [] ? xfs_map_blocks+0x25/0x30 Feb 11 07:49:54 > l1 [ 720.432445] [] ? xfs_page_state_convert+0x414/0x6c0 > Feb 11 07:49:54 l1 [ 720.432451] [] ? > radix_tree_gang_lookup_tag_slot+0xc3/0xf0 Feb 11 07:49:54 l1 [ 720.432455] > [] ? xfs_vm_writepage+0x77/0x130 Feb 11 07:49:54 l1 [ > 720.432459] [] ? __writepage+0xa/0x40 Feb 11 07:49:54 l1 [ > 720.432462] [] ? write_cache_pages+0x1df/0x3c0 Feb 11 > 07:49:54 l1 [ 720.432466] [] ? __writepage+0x0/0x40 Feb > 11 07:49:54 l1 [ 720.432472] [] ? > writeback_single_inode+0xd2/0x390 Feb 11 07:49:54 l1 [ 720.432476] > [] ? writeback_inodes_wb+0x3ff/0x5e0 Feb 11 07:49:54 l1 [ > 720.432480] [] ? wb_writeback+0x11e/0x1f0 Feb 11 07:49:54 > l1 [ 720.432485] [] ? try_to_del_timer_sync+0x5e/0x90 Feb > 11 07:49:54 l1 [ 720.432489] [] ? > wb_do_writeback+0x17b/0x180 Feb 11 07:49:54 l1 [ 720.432493] > [] ? bdi_writeback_task+0x5d/0xa0 Feb 11 07:49:54 l1 [ > 720.432497] [] ? bdi_start_fn+0x0/0xf0 Feb 11 07:49:54 l1 > [ 720.432500] [] ? bdi_start_fn+0x7e/0xf0 Feb 11 07:49:54 > l1 [ 720.432503] [] ? bdi_start_fn+0x0/0xf0 Feb 11 > 07:49:54 l1 [ 720.432506] [] ? kthread+0x96/0xa0 Feb 11 > 07:49:54 l1 [ 720.432511] [] ? child_rip+0xa/0x20 Feb 11 > 07:49:54 l1 [ 720.432515] [] ? kthread+0x0/0xa0 Feb 11 > 07:49:54 l1 [ 720.432519] [] ? child_rip+0x0/0x20 > > Justin. > >