From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755174Ab0BKOJp (ORCPT ); Thu, 11 Feb 2010 09:09:45 -0500 Received: from lucidpixels.com ([75.144.35.66]:52852 "EHLO lucidpixels.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754747Ab0BKOJn (ORCPT ); Thu, 11 Feb 2010 09:09:43 -0500 Date: Thu, 11 Feb 2010 09:09:39 -0500 (EST) From: Justin Piszcz To: linux-kernel@vger.kernel.org, linux-raid@vger.kernl.org, xfs@oss.sgi.com, Alan Piszcz Subject: 2.6.32.3 x86_64 - XFS hangs, all I/O to D-state bug (again) Message-ID: User-Agent: Alpine 2.00 (DEB 1167 2008-08-23) MIME-Version: 1.0 Content-Type: TEXT/PLAIN; format=flowed; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org 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.