Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S932854Ab1D1OZ6 (ORCPT ); Thu, 28 Apr 2011 10:25:58 -0400 Received: from cantor2.suse.de ([195.135.220.15]:44594 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1760558Ab1D1OZz (ORCPT ); Thu, 28 Apr 2011 10:25:55 -0400 Date: Thu, 28 Apr 2011 16:25:51 +0200 From: Jan Kara To: Colin Ian King Cc: Chris Mason , James Bottomley , linux-fsdevel , linux-mm , linux-kernel , linux-ext4 Subject: Re: [BUG] fatal hang untarring 90GB file, possibly writeback related. Message-ID: <20110428142551.GD1696@quack.suse.cz> References: <1303923177-sup-2603@think> <1303924902.2583.13.camel@mulgrave.site> <1303925374-sup-7968@think> <1303926637.2583.17.camel@mulgrave.site> <1303934716.2583.22.camel@mulgrave.site> <1303990590.2081.9.camel@lenovo> <1303993705-sup-5213@think> <1303998140.2081.11.camel@lenovo> <1303998300-sup-4941@think> <1303999282.2081.15.camel@lenovo> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1303999282.2081.15.camel@lenovo> User-Agent: Mutt/1.5.20 (2009-06-14) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 10021 Lines: 162 On Thu 28-04-11 15:01:22, Colin Ian King wrote: > > > Could you post the soft lockups you're seeing? > > As requested, attached Hum, what keeps puzzling me is that in all the cases of hangs I've seen so far, we are stuck waiting for IO to finish for a long time - e.g. in the traces below kjournald waits for PageWriteback bit to get cleared. Also we are stuck waiting for page locks which might be because those pages are being read in? All in all it seems that the IO is just incredibly slow. But it's not clear to me what pushes us into that situation (especially since ext4 refuses to do any IO from ->writepage (i.e. kswapd) when the underlying blocks are not already allocated. Honza [ 287.088371] INFO: task rs:main Q:Reg:749 blocked for more than 30 seconds. [ 287.088374] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 287.088376] rs:main Q:Reg D 0000000000000000 0 749 1 0x00000000 [ 287.088381] ffff880072c17b68 0000000000000082 ffff880072c17fd8 ffff880072c16000 [ 287.088392] 0000000000013d00 ffff88003591b178 ffff880072c17fd8 0000000000013d00 [ 287.088396] ffffffff81a0b020 ffff88003591adc0 ffff88001fffc3e8 ffff88001fc13d00 [ 287.088400] Call Trace: [ 287.088404] [] ? sync_page+0x0/0x50 [ 287.088408] [] io_schedule+0x70/0xc0 [ 287.088411] [] sync_page+0x40/0x50 [ 287.088414] [] __wait_on_bit+0x5f/0x90 [ 287.088418] [] wait_on_page_bit+0x78/0x80 [ 287.088421] [] ? wake_bit_function+0x0/0x50 [ 287.088425] [] __lock_page_or_retry+0x3d/0x70 [ 287.088428] [] filemap_fault+0x397/0x4a0 [ 287.088431] [] __do_fault+0x54/0x520 [ 287.088434] [] ? unmap_region+0x113/0x170 [ 287.088437] [] ? prio_tree_insert+0x150/0x1c0 [ 287.088440] [] handle_pte_fault+0xfa/0x210 [ 287.088442] [] ? pte_alloc_one+0x37/0x50 [ 287.088446] [] ? _raw_spin_lock+0xe/0x20 [ 287.088448] [] ? __pte_alloc+0xb5/0x100 [ 287.088451] [] handle_mm_fault+0x16d/0x250 [ 287.088454] [] do_page_fault+0x1a7/0x540 [ 287.088457] [] ? do_mmap_pgoff+0x335/0x370 [ 287.088460] [] ? sys_mmap_pgoff+0x167/0x230 [ 287.088463] [] page_fault+0x25/0x30 [ 287.088466] INFO: task NetworkManager:764 blocked for more than 30 seconds. [ 287.088468] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 287.088470] NetworkManager D 0000000000000002 0 764 1 0x00000000 [ 287.088473] ffff880074ffbb68 0000000000000082 ffff880074ffbfd8 ffff880074ffa000 [ 287.088477] 0000000000013d00 ffff880036051a98 ffff880074ffbfd8 0000000000013d00 [ 287.088481] ffff8801005badc0 ffff8800360516e0 ffff88001ffef128 ffff88001fc53d00 [ 287.088484] Call Trace: [ 287.088488] [] ? sync_page+0x0/0x50 [ 287.088491] [] io_schedule+0x70/0xc0 [ 287.088494] [] sync_page+0x40/0x50 [ 287.088497] [] __wait_on_bit+0x5f/0x90 [ 287.088500] [] wait_on_page_bit+0x78/0x80 [ 287.088503] [] ? wake_bit_function+0x0/0x50 [ 287.088506] [] __lock_page_or_retry+0x3d/0x70 [ 287.088509] [] filemap_fault+0x397/0x4a0 [ 287.088513] [] ? pollwake+0x0/0x60 [ 287.088516] [] __do_fault+0x54/0x520 [ 287.088519] [] ? pollwake+0x0/0x60 [ 287.088522] [] handle_pte_fault+0xfa/0x210 [ 287.088525] [] ? __free_pages+0x2d/0x40 [ 287.088527] [] ? __pte_alloc+0xdf/0x100 [ 287.088530] [] handle_mm_fault+0x16d/0x250 [ 287.088533] [] do_page_fault+0x1a7/0x540 [ 287.088537] [] ? read_tsc+0x9/0x20 [ 287.088540] [] ? ktime_get_ts+0xb1/0xf0 [ 287.088543] [] ? poll_select_set_timeout+0x82/0x90 [ 287.088546] [] page_fault+0x25/0x30 [ 287.088559] INFO: task unity-panel-ser:1521 blocked for more than 30 seconds. [ 287.088561] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 287.088562] unity-panel-ser D 0000000000000000 0 1521 1 0x00000000 [ 287.088566] ffff880061f37b68 0000000000000082 ffff880061f37fd8 ffff880061f36000 [ 287.088570] 0000000000013d00 ffff880068c7c858 ffff880061f37fd8 0000000000013d00 [ 287.088573] ffff88003591c4a0 ffff880068c7c4a0 ffff88001fff0c88 ffff88001fc13d00 [ 287.088577] Call Trace: [ 287.088581] [] ? sync_page+0x0/0x50 [ 287.088583] [] io_schedule+0x70/0xc0 [ 287.088587] [] sync_page+0x40/0x50 [ 287.088589] [] __wait_on_bit+0x5f/0x90 [ 287.088593] [] wait_on_page_bit+0x78/0x80 [ 287.088596] [] ? wake_bit_function+0x0/0x50 [ 287.088599] [] __lock_page_or_retry+0x3d/0x70 [ 287.088602] [] filemap_fault+0x397/0x4a0 [ 287.088605] [] __do_fault+0x54/0x520 [ 287.088608] [] handle_pte_fault+0xfa/0x210 [ 287.088610] [] ? __free_pages+0x2d/0x40 [ 287.088613] [] ? __pte_alloc+0xdf/0x100 [ 287.088616] [] handle_mm_fault+0x16d/0x250 [ 287.088619] [] do_page_fault+0x1a7/0x540 [ 287.088622] [] ? do_mmap_pgoff+0x335/0x370 [ 287.088625] [] page_fault+0x25/0x30 [ 287.088629] INFO: task jbd2/sda4-8:1845 blocked for more than 30 seconds. [ 287.088630] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 287.088632] jbd2/sda4-8 D 0000000000000000 0 1845 2 0x00000000 [ 287.088636] ffff880068f6baf0 0000000000000046 ffff880068f6bfd8 ffff880068f6a000 [ 287.088639] 0000000000013d00 ffff880061d603b8 ffff880068f6bfd8 0000000000013d00 [ 287.088643] ffff88003591c4a0 ffff880061d60000 ffff88001fff8548 ffff88001fc13d00 [ 287.088647] Call Trace: [ 287.088650] [] ? sync_page+0x0/0x50 [ 287.088653] [] io_schedule+0x70/0xc0 [ 287.088656] [] sync_page+0x40/0x50 [ 287.088659] [] __wait_on_bit+0x5f/0x90 [ 287.088662] [] wait_on_page_bit+0x78/0x80 [ 287.088665] [] ? wake_bit_function+0x0/0x50 [ 287.088668] [] filemap_fdatawait_range+0xfd/0x190 [ 287.088672] [] filemap_fdatawait+0x2b/0x30 [ 287.088675] [] journal_finish_inode_data_buffers+0x63/0x170 [ 287.088678] [] jbd2_journal_commit_transaction+0x6e4/0x1190 [ 287.088682] [] ? try_to_del_timer_sync+0x85/0xe0 [ 287.088685] [] kjournald2+0xbb/0x220 [ 287.088688] [] ? autoremove_wake_function+0x0/0x40 [ 287.088691] [] ? kjournald2+0x0/0x220 [ 287.088694] [] kthread+0x96/0xa0 [ 287.088697] [] kernel_thread_helper+0x4/0x10 [ 287.088700] [] ? kthread+0x0/0xa0 [ 287.088703] [] ? kernel_thread_helper+0x0/0x10 [ 287.088705] INFO: task dirname:5969 blocked for more than 30 seconds. [ 287.088707] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 287.088709] dirname D 0000000000000002 0 5969 5214 0x00000000 [ 287.088712] ffff88005bd9d8b8 0000000000000086 ffff88005bd9dfd8 ffff88005bd9c000 [ 287.088716] 0000000000013d00 ffff88005d65b178 ffff88005bd9dfd8 0000000000013d00 [ 287.088720] ffff8801005e5b80 ffff88005d65adc0 ffff88001ffe5228 ffff88001fc53d00 [ 287.088723] Call Trace: [ 287.088726] [] ? sync_page+0x0/0x50 [ 287.088729] [] io_schedule+0x70/0xc0 [ 287.088732] [] sync_page+0x40/0x50 [ 287.088735] [] __wait_on_bit+0x5f/0x90 [ 287.088738] [] wait_on_page_bit+0x78/0x80 [ 287.088741] [] ? wake_bit_function+0x0/0x50 [ 287.088744] [] __lock_page_or_retry+0x3d/0x70 [ 287.088747] [] filemap_fault+0x397/0x4a0 [ 287.088750] [] __do_fault+0x54/0x520 [ 287.088753] [] handle_pte_fault+0xfa/0x210 [ 287.088756] [] ? pte_alloc_one+0x37/0x50 [ 287.088759] [] ? _raw_spin_lock+0xe/0x20 [ 287.088761] [] ? __pte_alloc+0xb5/0x100 [ 287.088764] [] handle_mm_fault+0x16d/0x250 [ 287.088767] [] do_page_fault+0x1a7/0x540 [ 287.088770] [] ? mmap_region+0x1f7/0x500 [ 287.088773] [] ? free_pgd_range+0x356/0x4a0 [ 287.088776] [] page_fault+0x25/0x30 [ 287.088779] [] ? __clear_user+0x3f/0x70 [ 287.088782] [] ? __clear_user+0x21/0x70 [ 287.088786] [] clear_user+0x36/0x40 [ 287.088788] [] padzero+0x2d/0x40 [ 287.088791] [] load_elf_binary+0x95a/0xe00 [ 287.088794] [] search_binary_handler+0xda/0x300 [ 287.088797] [] ? load_elf_binary+0x0/0xe00 [ 287.088800] [] do_execve+0x24c/0x2d0 [ 287.088802] [] sys_execve+0x4a/0x80 [ 287.088805] [] stub_execve+0x6c/0xc0 -- Jan Kara SUSE Labs, CR -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/