Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757035Ab1D1Wkq (ORCPT ); Thu, 28 Apr 2011 18:40:46 -0400 Received: from cantor2.suse.de ([195.135.220.15]:33026 "EHLO mx2.suse.de" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751614Ab1D1Wkn (ORCPT ); Thu, 28 Apr 2011 18:40:43 -0400 Date: Fri, 29 Apr 2011 00:40:38 +0200 From: Jan Kara To: Colin Ian King Cc: Jan Kara , Chris Mason , James Bottomley , linux-fsdevel , linux-mm , linux-kernel , linux-ext4 , mgorman@novell.com Subject: Re: [BUG] fatal hang untarring 90GB file, possibly writeback related. Message-ID: <20110428224038.GG1696@quack.suse.cz> References: <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> <20110428142551.GD1696@quack.suse.cz> <20110428143329.GE1696@quack.suse.cz> <1304002701.2081.21.camel@lenovo> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <1304002701.2081.21.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: 16762 Lines: 257 On Thu 28-04-11 15:58:21, Colin Ian King wrote: > On Thu, 2011-04-28 at 16:33 +0200, Jan Kara wrote: > > On Thu 28-04-11 16:25:51, Jan Kara wrote: > > > 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. > > Hmm, maybe because the system is under memory pressure (and kswapd is not > > able to get rid of dirty pages), we page out clean pages. Thus also pages > > of executables which need to be paged in soon anyway thus putting heavy > > read load on the system which makes writes crawl? I'm not sure why > > compaction should make this any worse but maybe it can. > > > > James, Colin, can you capture output of 'vmstat 1' while you do the > > copying? Thanks. > > Attached. Thanks. So I there are a few interesting points in the vmstat output: For first 30 seconds, we are happily copying data - relatively steady read throughput (about 20-40 MB/s) and occasional peak from flusher thread flushing dirty data. During this time free memory drops from about 1.4 GB to about 22!!! MB - mm seems to like to really use the machine ;). Then things get interesting: procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 1 0 83372 5228 1450776 0 0 39684 90132 450 918 0 4 74 22 0 1 0 22416 5228 1509864 0 0 29452 48492 403 869 1 2 80 18 2 0 0 20056 5384 1513996 0 0 2248 2116 434 1191 4 4 71 21 0 1 0 19800 5932 1514600 0 0 644 104 454 1166 8 3 64 24 1 0 0 21848 5940 1515244 0 0 292 380 468 1775 15 6 75 3 1 0 0 20936 5940 1515876 0 0 296 296 496 1846 18 8 74 0 1 0 0 17792 5940 1516580 0 0 356 356 484 1862 23 8 69 0 1 0 0 17544 5940 1517364 0 0 412 412 482 1812 16 7 77 0 4 0 0 18148 5948 1517968 0 0 288 344 436 1749 19 9 69 3 0 2 220 137528 1616 1402468 0 220 74708 2164 849 1806 3 6 63 28 0 3 224 36184 1628 1499648 0 4 50820 86204 532 1272 0 4 64 32 0 2 19680 53688 1628 1484388 32 19456 6080 62972 242 287 0 2 63 34 0 2 36928 1407432 1356 150980 0 17252 1564 17276 368 764 1 3 73 22 So when free memory reached about 20 MB, both read and write activity almost stalled for 7 s (probably everybody waits for free memory). Then mm manages to free 100 MB from page cache, things move on for two seconds, then we swap out! about 36 MB and page reclaim also finally decides it maybe has too much of page cache and reaps most of it (1.3 GB in one go). Then things get going again, although there are still occasional stalls such as this (about 30s later): 1 3 36688 753192 1208 792344 0 0 35948 32768 435 6625 0 6 61 33 0 2 36668 754996 1344 792760 0 0 252 58736 2832 16239 0 1 60 39 0 2 36668 750132 1388 796688 0 0 2508 1524 325 959 1 3 68 28 1 0 36668 751160 1400 797968 0 0 620 620 460 1470 6 6 50 38 1 0 36668 750516 1400 798520 0 0 300 300 412 1764 17 8 75 1 1 0 36668 750648 1408 799108 0 0 280 340 423 1816 18 6 73 3 1 0 36668 748856 1408 799752 0 0 336 328 409 1788 18 8 75 0 1 0 36668 748120 1416 800604 0 0 428 452 407 1723 14 10 75 2 1 0 36668 750048 1416 801176 0 0 296 296 405 1779 18 7 75 1 0 1 36668 650428 1420 897252 0 0 48100 556 658 1718 10 3 71 15 0 2 36668 505444 1424 1037012 0 0 69888 90272 686 1491 1 4 68 27 0 1 36668 479264 1428 1063372 0 0 12984 40896 324 674 1 1 76 23 ... I'm not sure what we were blocked on here since there is still plenty of free memory (750 MB). These stalls repeat once in a while but things go on. Then at about 350s, things just stop: procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 3 1 75280 73564 1844 1503848 0 0 43396 81976 627 1061 0 25 42 32 3 3 75280 73344 1852 1504256 0 0 256 20 240 149 0 26 25 49 3 3 75280 73344 1852 1504268 0 0 0 0 265 140 0 29 13 58 3 3 75280 73468 1852 1504232 0 0 0 0 265 132 0 22 34 44 3 3 75280 73468 1852 1504232 0 0 0 0 339 283 0 25 26 49 3 3 75280 73468 1852 1504232 0 0 0 0 362 327 0 25 25 50 3 3 75280 73468 1852 1504232 0 0 0 0 317 320 0 26 25 49 3 3 75280 73468 1852 1504232 0 0 0 0 361 343 0 26 25 50 and nothing really happens for 150 s, except more and more tasks blocking in D state (second column). 3 6 75272 73416 1872 1503872 0 0 0 0 445 700 0 25 25 50 0 7 75264 67940 1884 1509008 64 0 5056 16 481 876 0 22 23 55 Then suddently things get going again: 0 2 75104 76808 1892 1502552 352 0 14292 40456 459 14865 0 2 39 59 0 1 75104 75704 1900 1503412 0 0 820 32 405 788 1 1 72 27 1 0 75104 76512 1904 1505576 0 0 1068 1072 454 1586 8 7 74 11 I guess this 150 s stall is when kernel barfs the "task blocked for more than 30 seconds" messages. And from the traces we know that everyone is waiting for PageWriteback or page lock during this time. Also James's vmstat report shows that IO is stalled when kswapd is spinning. Really strange. James in the meantime identified that cgroups are somehow involved. Are you using systemd by any chance? Maybe cgroup IO throttling screws us? 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-fsdevel" in > > > the body of a message to majordomo@vger.kernel.org > > > More majordomo info at http://vger.kernel.org/majordomo-info.html > -- 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/