Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754593Ab1ECSzz (ORCPT ); Tue, 3 May 2011 14:55:55 -0400 Received: from adelie.canonical.com ([91.189.90.139]:39739 "EHLO adelie.canonical.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1754469Ab1ECSzx (ORCPT ); Tue, 3 May 2011 14:55:53 -0400 Subject: Re: [BUG] fatal hang untarring 90GB file, possibly writeback related. From: Colin Ian King To: Jan Kara Cc: Chris Mason , James Bottomley , linux-fsdevel , linux-mm , linux-kernel , linux-ext4 , mgorman@novell.com In-Reply-To: <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> <20110428224038.GG1696@quack.suse.cz> Content-Type: text/plain; charset="UTF-8" Date: Tue, 03 May 2011 19:55:45 +0100 Message-ID: <1304448945.5533.9.camel@lenovo> Mime-Version: 1.0 X-Mailer: Evolution 2.32.2 Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 17654 Lines: 271 On Fri, 2011-04-29 at 00:40 +0200, Jan Kara wrote: > 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. Just to add, this machine has relatively low amount of memory (1GB). I've re-run the tests today with cgroups disabled and it ran for 47 'copy' cycles, 27 'copy' cycles and then 35 'copy' cycles. One extra data point, with maxcpus=1 I get a lockup after 2 'copy' cycles every time, so it's more predictable than the default 4 processor configuration. > > James in the meantime identified that cgroups are somehow involved. Are you > using systemd by any chance? No, I'm using upstart. > 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 > > > > -- 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/