On 11/2/07, Peter Zijlstra <peterz@xxxxxxxxxxxxx> wrote: > On Fri, 2007-11-02 at 10:21 +0800, Fengguang Wu wrote: > > > Interestingly, no background_writeout() appears, but only > > balance_dirty_pages() and wb_kupdate. Obviously wb_kupdate won't > > block the process. > > Yeah, the background threshold is not (yet) scaled. So it can happen > that the bdi_dirty limit is below the background limit. I still have not seen a trigger of the "throttle_vm_writeout". This time installing 2.6.24-rc1 again it not even triggerd any other debugs apart from the one in wb_kupdate. But 300Mb of new files might still not trigger this with 4Gb of RAM. I'm currently testing 2.6.23-mm1 with this patch and the second writeback-debug patch. > I'm curious though as to these stalls, though, I can't seem to think of > what goes wrong.. esp since most writeback seems to happen from pdflush. I also don't know. But looking at the time the system takes to write out 8kb, I'm starting to suspect that something is writing this out, but not marking it clean... (Or redirtying it immediately?) > (or I'm totally misreading it - quite a possible as I'm still recovering > from a serious cold and not all the green stuff has yet figured out its > proper place wrt brain cells 'n stuff) Get well soon! > I still have this patch floating around: > > --- > Subject: mm: speed up writeback ramp-up on clean systems applied, but did not fix the stalls. Here the complete log from vmstat 10 and the syslog from an install of vanilla 2.6.24-rc1. (Please note: I installed the source of vanilla 2.6.24-rc1, but I am still using 2.6.23-mm1!) All lines with [note] are my comments about what the system was doing, both logs are from the same run, so the notes should be more or less in sync. I used SysRq+L to insert the SysRq-Helptext into the syslog as marker... The visible effects are similar to the unmerge run, but the stalls during the moving did only start later. But the same effect after emerge finished and the almost all dirty data was written, was visible: I can still hear the disks and see the hdd light flickering (mostly on) for much, much longer than it should take to write 8kb. vmstat 10: [note]emerge start 1 0 0 3668496 332 187748 0 0 0 29 39 491 3 0 96 0 1 0 0 3623940 332 188880 0 0 83 17 1724 3893 15 2 81 1 0 0 0 3559488 332 252432 0 0 1021 48 11719 4536 9 4 74 13 2 0 0 3482220 332 311916 0 0 70 60 93 3818 11 3 86 0 1 0 0 3289352 332 486932 0 0 2 35 33 11997 25 3 72 0 1 0 0 3174036 332 596412 0 0 10 33 35 3937 21 4 75 0 2 0 0 3215756 332 555292 0 0 6 28 85 742 12 12 76 0 2 0 0 3202128 332 559792 0 0 32 9 34 1566 31 1 68 0 2 0 0 3192804 332 568072 0 0 60 46 172 4206 30 2 67 1 3 0 0 3202424 332 572620 0 0 0 20 111 2223 27 1 72 0 1 0 0 3196112 332 578900 0 0 0 1649 149 2763 25 2 73 0 1 0 0 3190004 332 584956 0 0 0 17 110 2270 25 1 74 0 1 0 0 3183952 332 590840 0 0 0 11 104 2553 25 1 74 0 1 0 0 3176952 332 597068 0 0 0 2153 124 2886 25 2 72 0 1 0 0 3171044 332 602592 0 0 0 22 109 2580 26 1 73 0 1 0 0 3174896 332 605496 0 0 173 1441 312 2249 9 6 84 1 1 0 0 3165204 332 611856 0 0 569 3221 606 4236 4 7 87 1 0 0 0 3160856 332 613516 0 0 116 2281 570 3077 3 5 92 0 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 0 0 3154712 332 615200 0 0 108 2166 528 3038 3 4 93 0 0 0 0 3156008 332 615420 0 0 18 1941 537 1015 0 2 97 0 0 0 0 3156652 332 615504 0 0 8 2232 547 900 0 2 98 0 0 0 0 3156748 332 615672 0 0 12 1932 537 947 0 2 98 0 0 0 0 3154720 332 615900 0 0 14 2204 584 1256 1 2 97 0 0 0 0 3154256 332 616060 0 0 10 2676 610 1317 1 3 96 0 1 0 0 3152488 332 616284 0 0 9 1994 573 1024 1 2 97 0 0 0 0 3152404 332 616408 0 0 4 2218 540 904 0 2 97 0 0 0 0 3151244 332 617156 0 0 44 2198 598 1921 2 4 94 0 0 0 0 3147224 332 618672 0 0 110 1802 644 2575 3 4 93 0 0 0 0 3144608 332 619824 0 0 80 1590 543 1900 2 4 95 0 0 0 0 3140768 332 621448 0 0 111 1758 657 2735 3 4 93 0 0 0 0 3140816 332 621896 0 0 26 801 531 1667 1 2 98 0 [note] first stall, SysRq+W 1 0 0 3127620 332 621896 0 0 0 640 490 1381 2 1 97 0 0 0 0 3127780 332 621900 0 0 0 627 475 1531 2 1 98 0 0 0 0 3127560 332 621900 0 0 0 587 464 1428 0 0 99 0 1 0 0 3126272 332 622460 0 0 32 945 556 1922 1 2 97 0 [note] installing resumes 0 0 0 3120860 332 624048 0 0 94 1950 785 2582 4 5 91 0 0 0 0 3117392 332 625200 0 0 76 1258 742 2217 2 3 95 0 [note] second stall 0 0 0 3118192 332 625200 0 0 0 617 559 1617 0 1 99 0 0 0 0 3118836 332 625200 0 0 0 603 550 1576 5 1 94 0 0 0 0 3118728 332 625200 0 0 0 682 601 1454 0 0 99 0 0 0 0 3118860 332 625200 0 0 0 653 557 1382 0 1 99 0 [note] installing resumes 1 0 0 3111356 332 624576 0 0 91 1277 789 2086 11 4 84 1 0 0 0 3149768 332 627792 0 0 322 504 655 1444 1 2 96 1 0 0 0 3150064 332 627792 0 0 0 559 623 1340 0 0 99 0 [note] emerge is finished, ~200Mb dirty data 0 0 0 3150220 332 627792 0 0 0 622 553 1553 2 1 97 0 0 0 0 3150456 332 627792 0 0 0 518 595 1315 0 1 99 0 0 0 0 3149380 332 627792 0 0 0 3759 801 1277 0 3 97 0 0 0 0 3148664 332 627840 0 0 0 3925 873 1500 0 4 96 0 0 0 0 3149672 332 627868 0 0 0 2476 800 1355 0 3 97 0 0 0 0 3148012 332 627872 0 0 0 2865 806 1235 0 3 97 0 0 0 0 3150496 332 627936 0 0 0 3074 847 1288 0 3 97 0 procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu---- r b swpd free buff cache si so bi bo in cs us sy id wa 0 0 0 3149568 332 627968 0 0 0 2238 751 1070 0 2 97 0 0 0 0 3150260 332 627988 0 0 0 872 607 1073 0 1 99 0 0 0 0 3150228 332 627988 0 0 0 1711 715 1214 0 2 98 0 0 0 0 3149300 332 627988 0 0 0 2195 752 1042 0 2 98 0 1 0 0 3150036 332 628032 0 0 0 2192 759 1118 0 2 97 0 0 0 0 3150868 332 628032 0 0 0 1035 639 1138 0 1 99 0 0 0 0 3150876 332 628068 0 0 0 1437 740 1153 0 1 98 0 0 0 0 3151152 332 628068 0 0 0 446 545 1381 0 0 100 0 0 0 0 3151212 332 628068 0 0 0 461 551 1412 2 0 98 0 [note] normal writeout finishes ~116kb dirty data left 1 0 0 3151088 332 628068 0 0 0 472 552 1468 0 0 99 0 0 0 0 3151260 332 628068 0 0 0 462 533 1369 0 0 100 0 0 0 0 3151296 332 628068 0 0 0 464 559 1325 0 0 100 0 0 0 0 3150992 332 628068 0 0 0 485 533 1350 0 0 100 0 0 0 0 3151092 332 628068 0 0 0 492 543 1378 0 0 100 0 [note] hit SysRq+W and SysRw+M 0 0 0 3150828 332 628076 0 0 0 430 541 1449 9 1 90 0 0 0 0 3150932 332 628076 0 0 0 459 535 1401 0 0 100 0 0 0 0 3151068 332 628076 0 0 0 465 536 1471 0 0 99 0 0 0 0 3151164 332 628076 0 0 0 453 525 1349 0 0 100 0 0 0 0 3151208 332 628076 0 0 0 474 530 1354 0 0 100 0 1 0 0 3151036 332 628076 0 0 0 449 506 1348 0 0 100 0 0 0 0 3151148 332 628076 0 0 0 476 520 1314 0 0 100 0 0 0 0 3151080 332 628076 0 0 0 467 521 1373 0 0 100 0 0 0 0 3151096 332 628076 0 0 0 464 521 1324 0 0 100 0 0 0 0 3151220 332 628076 0 0 0 461 548 1360 0 0 100 0 0 0 0 3151144 332 628076 0 0 0 417 480 1329 0 0 100 0 0 0 0 3150892 332 628076 0 0 0 492 543 1363 0 0 99 0 0 0 0 3151048 332 628076 0 0 0 436 515 1298 0 0 100 0 0 0 0 3151076 332 628076 0 0 0 434 513 1402 0 0 100 0 0 0 0 3151296 332 628076 0 0 0 430 508 1367 0 0 100 0 0 0 0 3150940 332 628076 0 0 0 472 527 1331 0 0 100 0 0 0 0 3151016 332 628076 0 0 0 472 527 1315 0 0 100 0 0 0 0 3151024 332 628076 0 0 0 227 409 703 0 0 100 0 0 0 0 3151272 332 628080 0 0 0 11 315 262 2 0 98 0 [note] writeout really finishes, disks go idle. from syslog: [note] emerge started, this unpacks the kernel into a tmpfs, patches it to rc1, packs it into a tar.bz2 and then moves the files from the tmpfs to my main xfs root fs [ 322.230000] SysRq : HELP : loglevel0-8 reBoot tErm Full kIll saK showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [ 323.120000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20090 global 25 0 0 wc __ tw 1024 sk 0 [ 328.230000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20091 global 26 0 0 wc __ tw 1024 sk 0 [ 333.290000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20131 global 29 0 0 wc _M tw 1023 sk 0 [ 333.360000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20130 global 29 0 0 wc _M tw 1023 sk 0 [ 333.390000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20129 global 29 0 0 wc __ tw 1023 sk 0 [ 338.300000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20131 global 28 0 0 wc __ tw 1024 sk 0 [ 343.360000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20196 global 1 28 0 wc __ tw 1000 sk 0 [ 348.330000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 20188 global 4 0 0 wc __ tw 1024 sk 0 [ 353.380000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 27417 global 4 0 0 wc __ tw 1024 sk 0 [ 358.380000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 31801 global 4 0 0 wc __ tw 1024 sk 0 [ 363.380000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 40783 global 4 0 0 wc __ tw 1021 sk 0 [ 368.460000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 44080 global 1 0 0 wc __ tw 1023 sk 0 [ 373.460000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 44085 global 1 0 0 wc __ tw 1024 sk 0 [ 378.460000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 44631 global 1 0 0 wc __ tw 1024 sk 0 [ 383.510000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 44709 global 1 0 0 wc __ tw 1024 sk 0 [note] around here the creation of the tar.bz2 started [ 388.520000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45134 global 426 0 0 wc __ tw 1024 sk 0 [ 393.530000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45884 global 1148 0 0 wc __ tw 1024 sk 0 [ 398.530000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47002 global 2262 0 0 wc __ tw 1023 sk 0 [ 403.570000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47619 global 2888 0 0 wc __ tw 1024 sk 0 [ 408.570000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 48276 global 3545 0 0 wc __ tw 1024 sk 0 [ 413.570000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 48740 global 2997 1012 0 wc _M tw -1 sk 0 [ 413.570000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47715 global 2997 1012 0 wc _M tw 1024 sk 0 [ 413.580000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47715 global 1985 2024 0 wc _M tw -1 sk 0 [ 413.590000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46690 global 973 3036 0 wc _M tw -1 sk 0 [ 413.590000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45665 global 7 4002 0 wc __ tw 64 sk 0 [ 418.630000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45595 global 864 0 0 wc __ tw 1024 sk 0 [ 423.630000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46294 global 1563 0 0 wc __ tw 1024 sk 0 [ 428.630000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47036 global 2305 0 0 wc __ tw 1023 sk 0 [ 433.630000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47731 global 3000 0 0 wc __ tw 1024 sk 0 [ 438.630000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 48525 global 3794 0 0 wc __ tw 1024 sk 0 [ 443.630000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 49159 global 4428 0 0 wc __ tw 1024 sk 0 [note] around here the moving from the tmpfs to the xfs started [ 448.630000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 50047 global 4304 1012 0 wc _M tw -1 sk 0 [ 448.640000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 49022 global 3292 2024 0 wc _M tw -1 sk 0 [ 448.650000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47997 global 2234 3082 0 wc _M tw -1 sk 0 [ 448.650000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46972 global 1222 4094 0 wc _M tw -1 sk 0 [ 448.660000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45947 global 210 5106 0 wc _M tw -1 sk 0 [ 448.660000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 44922 global 0 5336 0 wc __ tw 812 sk 0 [ 453.700000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45385 global 654 0 0 wc __ tw 1024 sk 0 [ 458.700000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45881 global 1150 0 0 wc _M tw 1023 sk 0 [ 458.790000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45880 global 1196 0 0 wc _M tw 1023 sk 0 [ 458.810000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45879 global 1196 0 0 wc __ tw 1023 sk 0 [ 463.840000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 44729 global 0 0 0 wc __ tw 1024 sk 0 [ 468.860000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45653 global 869 0 0 wc __ tw 1024 sk 0 [ 473.880000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 51262 global 6380 0 0 wc __ tw 1024 sk 0 [ 478.920000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 56488 global 11523 0 0 wc __ tw 1024 sk 0 [ 485.260000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 58839 global 13842 0 0 wc __ tw 1024 sk 0 [ 490.260000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 60796 global 15746 0 0 wc __ tw 1023 sk 0 [ 495.270000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 64003 global 18907 0 0 wc __ tw 1023 sk 0 [ 502.330000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 67524 global 21467 336 0 wc _M tw -5 sk 0 [ 505.350000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 66495 global 20615 51 0 wc _M tw 0 sk 0 [ 508.140000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 65471 global 19727 213 0 wc _M tw -1 sk 0 [ 508.550000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 64446 global 19483 336 0 wc _M tw 760 sk 0 [ 509.180000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 64182 global 19470 94 0 wc __ tw 1012 sk 0 [ 514.190000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 65780 global 19665 172 0 wc __ tw -1 sk 0 [ 517.310000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 64755 global 18827 14 0 wc __ tw -1 sk 0 [ 520.100000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 63730 global 17929 96 0 wc _M tw -13 sk 0 [ 522.560000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 62693 global 16937 167 0 wc _M tw -1 sk 0 [ 527.050000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 61668 global 16021 95 0 wc _M tw -6 sk 0 [ 530.460000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 60638 global 15115 52 0 wc _M tw -1 sk 0 [ 534.470000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 59613 global 14222 27 0 wc _M tw -4 sk 0 [ 537.760000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 58585 global 13386 54 0 wc _M tw 0 sk 0 [ 541.050000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 57561 global 12737 58 0 wc _M tw 281 sk 0 [ 541.090000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 56818 global 12737 58 0 wc __ tw 1022 sk 0 [ 547.200000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 58858 global 12829 72 0 wc __ tw 0 sk 0 [ 550.480000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 57834 global 12017 62 0 wc __ tw 0 sk 0 [ 552.710000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 56810 global 11133 83 0 wc __ tw 0 sk 0 [ 558.660000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 55786 global 10470 33 0 wc _M tw 0 sk 0 [ 562.750000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 54762 global 10555 69 0 wc _M tw 0 sk 0 [ 565.150000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 53738 global 9562 498 0 wc _M tw -2 sk 0 [ 569.490000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 52712 global 8960 2 0 wc _M tw 0 sk 0 [ 572.910000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 51688 global 8088 205 0 wc _M tw -13 sk 0 [ 574.610000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 50651 global 7114 188 0 wc _M tw -1 sk 0 [ 584.270000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 49626 global 14544 0 0 wc _M tw -1 sk 0 [ 593.050000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 48601 global 24583 736 0 wc _M tw -1 sk 0 [ 600.180000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47576 global 27004 6 0 wc _M tw 587 sk 0 [ 600.180000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47139 global 27004 6 0 wc __ tw 1014 sk 0 [note] first stall, the output from emerge stops, so it seems it can not start processing the next file until the stall ends [ 630.000000] SysRq : Emergency Sync [ 630.120000] Emergency Sync complete [ 632.850000] SysRq : Show Blocked State [ 632.850000] task PC stack pid father [ 632.850000] pdflush D ffff81000f091788 0 285 2 [ 632.850000] ffff810005d4da80 0000000000000046 0000000000000800 0000007000000001 [ 632.850000] ffff81000fd52400 ffffffff8022d61c ffffffff80819b00 ffffffff80819b00 [ 632.850000] ffffffff80815f40 ffffffff80819b00 ffff810100316f98 0000000000000000 [ 632.850000] Call Trace: [ 632.850000] [<ffffffff8022d61c>] task_rq_lock+0x4c/0x90 [ 632.850000] [<ffffffff8022c8ea>] __wake_up_common+0x5a/0x90 [ 632.850000] [<ffffffff805b16e7>] __down+0xa7/0x11e [ 632.850000] [<ffffffff8022da70>] default_wake_function+0x0/0x10 [ 632.850000] [<ffffffff805b1365>] __down_failed+0x35/0x3a [ 632.850000] [<ffffffff803752ce>] xfs_buf_lock+0x3e/0x40 [ 632.850000] [<ffffffff8037740e>] _xfs_buf_find+0x13e/0x240 [ 632.850000] [<ffffffff8037757f>] xfs_buf_get_flags+0x6f/0x190 [ 632.850000] [<ffffffff803776b2>] xfs_buf_read_flags+0x12/0xa0 [ 632.850000] [<ffffffff80368824>] xfs_trans_read_buf+0x64/0x340 [ 632.850000] [<ffffffff80352361>] xfs_itobp+0x81/0x1e0 [ 632.850000] [<ffffffff8026b293>] write_cache_pages+0x123/0x330 [ 632.850000] [<ffffffff80354d0e>] xfs_iflush+0xfe/0x520 [ 632.850000] [<ffffffff803ae5d2>] __down_read_trylock+0x42/0x60 [ 632.850000] [<ffffffff8036ed49>] xfs_inode_flush+0x179/0x1b0 [ 632.850000] [<ffffffff8037ca8f>] xfs_fs_write_inode+0x2f/0x90 [ 632.850000] [<ffffffff802b3aac>] __writeback_single_inode+0x2ac/0x380 [ 632.850000] [<ffffffff804d074e>] dm_table_any_congested+0x2e/0x80 [ 632.850000] [<ffffffff802b3f9d>] generic_sync_sb_inodes+0x20d/0x330 [ 632.850000] [<ffffffff802b4532>] writeback_inodes+0xa2/0xe0 [ 632.850000] [<ffffffff8026bfd6>] wb_kupdate+0xa6/0x140 [ 632.850000] [<ffffffff8026c4b0>] pdflush+0x0/0x1e0 [ 632.850000] [<ffffffff8026c5c0>] pdflush+0x110/0x1e0 [ 632.850000] [<ffffffff8026bf30>] wb_kupdate+0x0/0x140 [ 632.850000] [<ffffffff8024a32b>] kthread+0x4b/0x80 [ 632.850000] [<ffffffff8020c9d8>] child_rip+0xa/0x12 [ 632.850000] [<ffffffff8024a2e0>] kthread+0x0/0x80 [ 632.850000] [<ffffffff8020c9ce>] child_rip+0x0/0x12 [ 632.850000] [ 632.850000] emerge D 0000000000000000 0 6220 6129 [ 632.850000] ffff810103ced9f8 0000000000000086 0000000000000000 0000007000000001 [ 632.850000] ffff81000fd52cf8 ffffffff00000000 ffffffff80819b00 ffffffff80819b00 [ 632.850000] ffffffff80815f40 ffffffff80819b00 ffff810103ced9b8 ffff810103ced9a8 [ 632.850000] Call Trace: [ 632.850000] [<ffffffff805b16e7>] __down+0xa7/0x11e [ 632.850000] [<ffffffff8022da70>] default_wake_function+0x0/0x10 [ 632.850000] [<ffffffff805b1365>] __down_failed+0x35/0x3a [ 632.850000] [<ffffffff803752ce>] xfs_buf_lock+0x3e/0x40 [ 632.850000] [<ffffffff8037740e>] _xfs_buf_find+0x13e/0x240 [ 632.850000] [<ffffffff8037757f>] xfs_buf_get_flags+0x6f/0x190 [ 632.850000] [<ffffffff803776b2>] xfs_buf_read_flags+0x12/0xa0 [ 632.850000] [<ffffffff80368824>] xfs_trans_read_buf+0x64/0x340 [ 632.850000] [<ffffffff80352361>] xfs_itobp+0x81/0x1e0 [ 632.850000] [<ffffffff80375bee>] xfs_buf_rele+0x2e/0xd0 [ 632.850000] [<ffffffff80354d0e>] xfs_iflush+0xfe/0x520 [ 632.850000] [<ffffffff803ae5d2>] __down_read_trylock+0x42/0x60 [ 632.850000] [<ffffffff80355c82>] xfs_inode_item_push+0x12/0x20 [ 632.850000] [<ffffffff80368247>] xfs_trans_push_ail+0x267/0x2b0 [ 632.850000] [<ffffffff8035c742>] xfs_log_reserve+0x72/0x120 [ 632.850000] [<ffffffff80366bf8>] xfs_trans_reserve+0xa8/0x210 [ 632.850000] [<ffffffff803731f2>] kmem_zone_zalloc+0x32/0x50 [ 632.850000] [<ffffffff8035263b>] xfs_itruncate_finish+0xfb/0x310 [ 632.850000] [<ffffffff8036daeb>] xfs_free_eofblocks+0x23b/0x280 [ 632.850000] [<ffffffff80371f93>] xfs_release+0x153/0x200 [ 632.850000] [<ffffffff80378010>] xfs_file_release+0x10/0x20 [ 632.850000] [<ffffffff80294251>] __fput+0xb1/0x220 [ 632.850000] [<ffffffff802910a4>] filp_close+0x54/0x90 [ 632.850000] [<ffffffff802929bf>] sys_close+0x9f/0x100 [ 632.850000] [<ffffffff8020bbbe>] system_call+0x7e/0x83 [ 632.850000] [ 662.180000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 73045 global 39157 0 0 wc __ tw 0 sk 0 [note] emerge resumed [ 664.030000] SysRq : HELP : loglevel0-8 reBoot tErm Full kIll saK showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [ 673.150000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 72021 global 44617 0 0 wc __ tw -3 sk 0 [note] emerge stalled again [ 693.930000] SysRq : HELP : loglevel0-8 reBoot tErm Full kIll saK showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [ 724.580000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 70994 global 48064 26 0 wc _M tw -5 sk 0 [note] emerge resumed again [ 724.710000] SysRq : HELP : loglevel0-8 reBoot tErm Full kIll saK showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [ 751.470000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 69965 global 47914 46 0 wc _M tw -1 sk 0 [note] emerge is finished, but 200Mb of dirty data remain [ 761.950000] SysRq : HELP : loglevel0-8 reBoot tErm Full kIll saK showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [ 775.520000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 68940 global 46911 414 0 wc _M tw 0 sk 0 [ 776.280000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 67916 global 45859 724 0 wc _M tw -2 sk 0 [ 777.370000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 66890 global 44834 325 0 wc _M tw -10 sk 0 [ 778.450000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 65856 global 43828 242 0 wc _M tw -1 sk 0 [ 779.020000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 64831 global 42807 484 0 wc _M tw -1 sk 0 [ 780.440000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 63806 global 41768 47 0 wc _M tw -7 sk 0 [ 781.560000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 62775 global 40730 445 0 wc _M tw 0 sk 0 [ 783.000000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 61751 global 39705 322 0 wc _M tw -3 sk 0 [ 785.140000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 60724 global 38732 310 0 wc _M tw -4 sk 0 [ 786.390000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 59696 global 37673 406 0 wc _M tw -6 sk 0 [ 787.310000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 58666 global 36636 495 0 wc _M tw -9 sk 0 [ 787.720000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 57633 global 35578 955 0 wc _M tw -1 sk 0 [ 789.100000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 56608 global 34592 139 0 wc _M tw 0 sk 0 [ 790.400000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 55584 global 33567 25 0 wc _M tw -3 sk 0 [ 791.780000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 54557 global 32491 305 0 wc _M tw -11 sk 0 [ 793.790000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 53522 global 31499 506 0 wc _M tw -5 sk 0 [ 796.680000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 52493 global 30462 184 0 wc _M tw -3 sk 0 [ 798.930000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 51466 global 29411 340 0 wc _M tw -11 sk 0 [ 800.330000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 50431 global 28377 69 0 wc _M tw -4 sk 0 [ 803.900000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 49403 global 27388 24 0 wc _M tw -2 sk 0 [ 805.600000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 48377 global 26330 142 0 wc _M tw -6 sk 0 [ 807.740000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47347 global 25295 138 0 wc _M tw -1 sk 0 [ 809.680000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46322 global 24296 268 0 wc _M tw -2 sk 0 [ 812.120000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 45296 global 23269 81 0 wc _M tw -5 sk 0 [ 813.940000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 44267 global 22249 303 0 wc _M tw -1 sk 0 [ 815.940000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 43242 global 21205 220 0 wc _M tw -9 sk 0 [ 817.660000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 42209 global 20174 87 0 wc _M tw -7 sk 0 [ 819.430000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 41178 global 19142 31 0 wc _M tw -5 sk 0 [ 820.360000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 40149 global 18113 316 0 wc _M tw -7 sk 0 [ 822.310000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 39118 global 17098 85 0 wc _M tw 0 sk 0 [ 824.680000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 38094 global 16064 168 0 wc _M tw 0 sk 0 [ 829.250000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 37070 global 15059 44 0 wc _M tw 0 sk 0 [ 832.300000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 36046 global 14001 89 0 wc _M tw -2 sk 0 [ 836.030000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 35020 global 13741 0 0 wc _M tw 760 sk 0 [ 836.050000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 34756 global 13649 92 0 wc _M tw 922 sk 0 [ 836.290000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 34654 global 13649 0 0 wc _M tw 1022 sk 0 [ 836.720000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 34652 global 13650 0 0 wc __ tw 1023 sk 0 [ 843.210000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 60278 global 12631 110 0 wc __ tw 0 sk 0 [ 845.380000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 59254 global 11590 72 0 wc __ tw -1 sk 0 [ 852.340000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 58229 global 10566 56 0 wc __ tw -1 sk 0 [ 854.360000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 57204 global 9551 103 0 wc __ tw 0 sk 0 [ 857.140000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 56180 global 8529 33 0 wc __ tw 0 sk 0 [ 860.800000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 55156 global 7480 509 0 wc _M tw -9 sk 0 [ 863.350000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 54123 global 6443 343 0 wc _M tw -10 sk 0 [ 866.020000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 53089 global 5420 215 0 wc _M tw 0 sk 0 [ 870.080000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 52065 global 4393 104 0 wc _M tw 0 sk 0 [ 872.210000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 51041 global 3385 334 0 wc _M tw -5 sk 0 [ 874.280000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 50012 global 2343 234 0 wc _M tw 0 sk 0 [ 884.350000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 48988 global 1330 52 0 wc _M tw -4 sk 0 [ 889.810000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 47960 global 294 122 0 wc _M tw 0 sk 0 [note] the system is down to 116kb dirty data, but still writing back heavyly [ 905.280000] SysRq : HELP : loglevel0-8 reBoot tErm Full kIll saK showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [note] after a while in this state I hit SysRq+W and SysRq+M to capture more state [ 967.770000] SysRq : Show Blocked State [ 967.770000] task PC stack pid father [ 967.770000] pdflush D ffff810080043640 0 285 2 [ 967.770000] ffff810005d4da80 0000000000000046 ffff810005d4da48 0000007000000001 [ 967.770000] 0000000000000400 0000000000000001 ffffffff80819b00 ffffffff80819b00 [ 967.770000] ffffffff80815f40 ffffffff80819b00 ffff810005d4da40 ffff810005d4da30 [ 967.770000] Call Trace: [ 967.770000] [<ffffffff805b16e7>] __down+0xa7/0x11e [ 967.770000] [<ffffffff8022da70>] default_wake_function+0x0/0x10 [ 967.770000] [<ffffffff805b1365>] __down_failed+0x35/0x3a [ 967.770000] [<ffffffff803752ce>] xfs_buf_lock+0x3e/0x40 [ 967.770000] [<ffffffff8037740e>] _xfs_buf_find+0x13e/0x240 [ 967.770000] [<ffffffff8037757f>] xfs_buf_get_flags+0x6f/0x190 [ 967.770000] [<ffffffff803776b2>] xfs_buf_read_flags+0x12/0xa0 [ 967.770000] [<ffffffff80368824>] xfs_trans_read_buf+0x64/0x340 [ 967.770000] [<ffffffff80352361>] xfs_itobp+0x81/0x1e0 [ 967.770000] [<ffffffff8026b293>] write_cache_pages+0x123/0x330 [ 967.770000] [<ffffffff80354d0e>] xfs_iflush+0xfe/0x520 [ 967.770000] [<ffffffff803ae5d2>] __down_read_trylock+0x42/0x60 [ 967.770000] [<ffffffff8036ed49>] xfs_inode_flush+0x179/0x1b0 [ 967.770000] [<ffffffff8037ca8f>] xfs_fs_write_inode+0x2f/0x90 [ 967.770000] [<ffffffff802b3aac>] __writeback_single_inode+0x2ac/0x380 [ 967.770000] [<ffffffff804d074e>] dm_table_any_congested+0x2e/0x80 [ 967.770000] [<ffffffff802b3f9d>] generic_sync_sb_inodes+0x20d/0x330 [ 967.770000] [<ffffffff802b4532>] writeback_inodes+0xa2/0xe0 [ 967.770000] [<ffffffff8026bfd6>] wb_kupdate+0xa6/0x140 [ 967.770000] [<ffffffff8026c4b0>] pdflush+0x0/0x1e0 [ 967.770000] [<ffffffff8026c5c0>] pdflush+0x110/0x1e0 [ 967.770000] [<ffffffff8026bf30>] wb_kupdate+0x0/0x140 [ 967.770000] [<ffffffff8024a32b>] kthread+0x4b/0x80 [ 967.770000] [<ffffffff8020c9d8>] child_rip+0xa/0x12 [ 967.770000] [<ffffffff8024a2e0>] kthread+0x0/0x80 [ 967.770000] [<ffffffff8020c9ce>] child_rip+0x0/0x12 [ 967.770000] [ 968.640000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46936 global 30 0 0 wc _M tw 757 sk 0 [ 968.670000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46669 global 2 28 0 wc __ tw 996 sk 0 [ 970.520000] SysRq : Show Memory [ 970.530000] Mem-info: [ 970.530000] Node 0 DMA per-cpu: [ 970.530000] CPU 0: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0 [ 970.540000] CPU 1: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0 [ 970.540000] CPU 2: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0 [ 970.540000] CPU 3: Hot: hi: 0, btch: 1 usd: 0 Cold: hi: 0, btch: 1 usd: 0 [ 970.540000] Node 0 DMA32 per-cpu: [ 970.540000] CPU 0: Hot: hi: 186, btch: 31 usd: 66 Cold: hi: 62, btch: 15 usd: 15 [ 970.540000] CPU 1: Hot: hi: 186, btch: 31 usd: 159 Cold: hi: 62, btch: 15 usd: 17 [ 970.540000] CPU 2: Hot: hi: 186, btch: 31 usd: 0 Cold: hi: 62, btch: 15 usd: 0 [ 970.540000] CPU 3: Hot: hi: 186, btch: 31 usd: 0 Cold: hi: 62, btch: 15 usd: 0 [ 970.540000] Node 1 DMA32 per-cpu: [ 970.540000] CPU 0: Hot: hi: 186, btch: 31 usd: 28 Cold: hi: 62, btch: 15 usd: 0 [ 970.540000] CPU 1: Hot: hi: 186, btch: 31 usd: 47 Cold: hi: 62, btch: 15 usd: 0 [ 970.540000] CPU 2: Hot: hi: 186, btch: 31 usd: 155 Cold: hi: 62, btch: 15 usd: 12 [ 970.540000] CPU 3: Hot: hi: 186, btch: 31 usd: 183 Cold: hi: 62, btch: 15 usd: 3 [ 970.540000] Node 1 Normal per-cpu: [ 970.540000] CPU 0: Hot: hi: 186, btch: 31 usd: 0 Cold: hi: 62, btch: 15 usd: 0 [ 970.540000] CPU 1: Hot: hi: 186, btch: 31 usd: 0 Cold: hi: 62, btch: 15 usd: 0 [ 970.540000] CPU 2: Hot: hi: 186, btch: 31 usd: 118 Cold: hi: 62, btch: 15 usd: 19 [ 970.540000] CPU 3: Hot: hi: 186, btch: 31 usd: 163 Cold: hi: 62, btch: 15 usd: 13 [note] I do think, that /proc/meminfo also showed only 8kb of dirty remaining at this point, but I'm not 200% sure... [ 970.540000] Active:70883 inactive:117017 dirty:2 writeback:0 unstable:0 [ 970.540000] free:787733 slab:25286 mapped:12000 pagetables:2237 bounce:0 [ 970.540000] Node 0 DMA free:9448kB min:16kB low:20kB high:24kB active:0kB inactive:0kB present:8868kB pages_scanned:0 all_unreclaimable? no [ 970.540000] lowmem_reserve[]: 0 2004 2004 2004 [ 970.540000] Node 0 DMA32 free:1465640kB min:4040kB low:5048kB high:6060kB active:132340kB inactive:310048kB present:2052320kB pages_scanned:0 all_unreclaimable? no [ 970.540000] lowmem_reserve[]: 0 0 0 0 [ 970.540000] Node 1 DMA32 free:1476216kB min:3040kB low:3800kB high:4560kB active:3528kB inactive:41952kB present:1544000kB pages_scanned:0 all_unreclaimable? no [ 970.540000] lowmem_reserve[]: 0 0 505 505 [ 970.540000] Node 1 Normal free:199628kB min:1016kB low:1268kB high:1524kB active:147664kB inactive:116068kB present:517120kB pages_scanned:0 all_unreclaimable? no [ 970.540000] lowmem_reserve[]: 0 0 0 0 [ 970.540000] Node 0 DMA: 6*4kB 6*8kB 4*16kB 5*32kB 3*64kB 2*128kB 4*256kB 1*512kB 1*1024kB 1*2048kB 1*4096kB = 9448kB [ 970.540000] Node 0 DMA32: 158*4kB 66*8kB 30*16kB 22*32kB 10*64kB 7*128kB 6*256kB 4*512kB 6*1024kB 5*2048kB 352*4096kB = 1465640kB [ 970.540000] Node 1 DMA32: 866*4kB 446*8kB 228*16kB 122*32kB 50*64kB 32*128kB 23*256kB 17*512kB 16*1024kB 11*2048kB 342*4096kB = 1476216kB [ 970.540000] Node 1 Normal: 511*4kB 618*8kB 471*16kB 325*32kB 185*64kB 92*128kB 72*256kB 55*512kB 38*1024kB 26*2048kB 3*4096kB = 199580kB [ 970.540000] Swap cache: add 0, delete 0, find 0/0, race 0+0 [ 970.540000] Free swap = 9775416kB [ 970.540000] Total swap = 9775416kB [ 970.540000] Free swap: 9775416kB [ 970.570000] 1048576 pages of RAM [ 970.570000] 35174 reserved pages [ 970.570000] 149150 pages shared [ 970.570000] 0 pages swap cached [ 1137.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46642 global 1 0 0 wc _M tw 1022 sk 0 [ 1137.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 1 0 0 wc __ tw 1022 sk 0 [ 1138.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 1 0 0 wc __ tw 1024 sk 0 [ 1143.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 1 0 0 wc __ tw 1024 sk 0 [ 1148.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 1 0 0 wc __ tw 1024 sk 0 [note] finally the disks go idle [ 1149.020000] SysRq : HELP : loglevel0-8 reBoot tErm Full kIll saK showMem Nice powerOff showPc show-all-timers(Q) unRaw Sync showTasks Unmount shoW-blocked-tasks [ 1153.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46641 global 2 0 0 wc __ tw 1024 sk 0 [ 1158.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46641 global 2 0 0 wc __ tw 1024 sk 0 [ 1163.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46641 global 2 0 0 wc __ tw 1024 sk 0 [ 1168.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46641 global 2 0 0 wc _M tw 1023 sk 0 [ 1168.160000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 2 0 0 wc _M tw 1023 sk 0 [ 1168.180000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46639 global 2 0 0 wc __ tw 1023 sk 0 [ 1173.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 1 0 0 wc __ tw 1024 sk 0 [ 1178.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 1 0 0 wc __ tw 1024 sk 0 [ 1183.110000] mm/page-writeback.c 676 wb_kupdate: pdflush(285) 46640 global 1 0 0 wc __ tw 1024 sk 0 Torsten - To unsubscribe from this list: send the line "unsubscribe linux-fsdevel" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
