Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1755426AbZJ0PVU (ORCPT ); Tue, 27 Oct 2009 11:21:20 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1753086AbZJ0PVS (ORCPT ); Tue, 27 Oct 2009 11:21:18 -0400 Received: from gir.skynet.ie ([193.1.99.77]:39571 "EHLO gir.skynet.ie" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1755361AbZJ0PVR (ORCPT ); Tue, 27 Oct 2009 11:21:17 -0400 Date: Tue, 27 Oct 2009 15:21:19 +0000 From: Mel Gorman To: KOSAKI Motohiro Cc: Frans Pop , Chris Mason , David Rientjes , "Rafael J. Wysocki" , Linux Kernel Mailing List , Kernel Testers List , Pekka Enberg , Reinette Chatre , Bartlomiej Zolnierkiewicz , Karol Lewandowski , Mohamed Abbas , Jens Axboe , "John W. Linville" , linux-mm@kvack.org Subject: Re: [Bug #14141] order 2 page allocation failures in iwlagn Message-ID: <20091027152118.GI8900@csn.ul.ie> References: <3onW63eFtRF.A.xXH.oMTxKB@chimera> <20091019161815.GA11487@think> <20091020104839.GC11778@csn.ul.ie> <200910262206.13146.elendil@planet.nl> <20091027145435.GG8900@csn.ul.ie> <2f11576a0910270816s3e1b268ah91b5f2d0cc0d562e@mail.gmail.com> MIME-Version: 1.0 Content-Type: text/plain; charset=iso-8859-15 Content-Disposition: inline Content-Transfer-Encoding: 8bit In-Reply-To: <2f11576a0910270816s3e1b268ah91b5f2d0cc0d562e@mail.gmail.com> User-Agent: Mutt/1.5.17+20080114 (2008-01-14) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 8612 Lines: 167 On Wed, Oct 28, 2009 at 12:16:30AM +0900, KOSAKI Motohiro wrote: > 2009/10/27 Mel Gorman : > > On Mon, Oct 26, 2009 at 10:06:09PM +0100, Frans Pop wrote: > >> On Tuesday 20 October 2009, Mel Gorman wrote: > >> > I've attached a patch below that should allow us to cheat. When it's > >> > applied, it outputs who called congestion_wait(), how long the timeout > >> > was and how long it waited for. By comparing before and after sleep > >> > times, we should be able to see which of the callers has significantly > >> > changed and if it's something easily addressable. > >> > >> The results from this look fairly interesting (although I may be a bad > >> judge as I don't really know what I'm looking at ;-). > >> > >> I've tested with two kernels: > >> 1) 2.6.31.1: 1 test run > >> 2) 2.6.31.1 + congestion_wait() reverts: 2 test runs > >> > >> The 1st kernel had the expected "freeze" while reading commits in gitk; > >> reading commits with the 2nd kernel was more fluent. > >> I did 2 runs with the 2nd kernel as the first run had a fairly long music > >> skip and more SKB errors than expected. The second run was fairly normal > >> with no music skips at all even though it had a few SKB errors. > >> > >> Data for the tests: > >> ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? 1st kernel ? ? ?2nd kernel 1 ? ?2nd kernel 2 > >> end reading commits ? ? ? ? ? 1:15 ? ? ? ? ? ?1:00 ? ? ? ? ? ?0:55 > >> ? "freeze" ? ? ? ? ? ? ? ? ? ?yes ? ? ? ? ? ? no ? ? ? ? ? ? ?no > >> branch data shown ? ? ? ? ? ? 1:55 ? ? ? ? ? ?1:15 ? ? ? ? ? ?1:10 > >> system quiet ? ? ? ? ? ? ? ? ?2:25 ? ? ? ? ? ?1:50 ? ? ? ? ? ?1:45 > >> # SKB allocation errors ? ? ? ? ? ? ? 10 ? ? ? ? ? ? ?53 ? ? ? ? ? ? ?5 > >> > >> Note that the test is substantially faster with the 2nd kernel and that the > >> SKB errors don't really affect the duration of the test. > >> > > > > Ok. I think that despite expectations, the writeback changes have > > changed the timing significantly enough to be worth examining closer. > > > >> > >> - without the revert 'background_writeout' is called a lot less frequently, > >> ? but when it's called it gets long delays > >> - without the revert you have 'wb_kupdate', which is relatively expensive > >> - with the revert 'shrink_list' is relatively expensive, although not > >> ? really in absolute terms > >> > > > > Lets look at the callers that waited in congestion_wait() for at least > > 25 jiffies. > > > > 2.6.31.1-async-sync-congestion-wait i.e. vanilla kernel > > generated with: cat kern.log_1_test | awk -F ] '{print $2}' | sort -k 5 -n | uniq -c > > ? ? 24 ?background_writeout ?congestion_wait sync=0 delay 25 timeout 25 > > ? ?203 ?kswapd ? ? ? ? ? ? ? congestion_wait sync=0 delay 25 timeout 25 > > ? ? ?5 ?shrink_list ? ? ? ? ?congestion_wait sync=0 delay 25 timeout 25 > > ? ?155 ?try_to_free_pages ? ?congestion_wait sync=0 delay 25 timeout 25 > > ? ?145 ?wb_kupdate ? ? ? ? ? congestion_wait sync=0 delay 25 timeout 25 > > ? ? ?2 ?kswapd ? ? ? ? ? ? ? congestion_wait sync=0 delay 26 timeout 25 > > ? ? ?8 ?wb_kupdate ? ? ? ? ? congestion_wait sync=0 delay 26 timeout 25 > > ? ? ?1 ?try_to_free_pages ? ?congestion_wait sync=0 delay 54 timeout 25 > > > > 2.6.31.1-write-congestion-wait i.e. kernel with patch reverted > > generated with: cat kern.log_2.1_test | awk -F ] '{print $2}' | sort -k 5 -n | uniq -c > > ? ? ?2 ?background_writeout ?congestion_wait rw=1 delay 25 timeout 25 > > ? ?188 ?kswapd ? ? ? ? ? ? ? congestion_wait rw=1 delay 25 timeout 25 > > ? ? 14 ?shrink_list ? ? ? ? ?congestion_wait rw=1 delay 25 timeout 25 > > ? ?181 ?try_to_free_pages ? ?congestion_wait rw=1 delay 25 timeout 25 > > ? ? ?5 ?kswapd ? ? ? ? ? ? ? congestion_wait rw=1 delay 26 timeout 25 > > ? ? 10 ?try_to_free_pages ? ?congestion_wait rw=1 delay 26 timeout 25 > > ? ? ?3 ?try_to_free_pages ? ?congestion_wait rw=1 delay 27 timeout 25 > > ? ? ?1 ?kswapd ? ? ? ? ? ? ? congestion_wait rw=1 delay 29 timeout 25 > > ? ? ?1 ?__alloc_pages_nodemask congestion_wait rw=1 delay 30 timeout 5 > > ? ? ?1 ?try_to_free_pages ? ?congestion_wait rw=1 delay 31 timeout 25 > > ? ? ?1 ?try_to_free_pages ? ?congestion_wait rw=1 delay 35 timeout 25 > > ? ? ?1 ?kswapd ? ? ? ? ? ? ? congestion_wait rw=1 delay 51 timeout 25 > > ? ? ?1 ?try_to_free_pages ? ?congestion_wait rw=1 delay 56 timeout 25 > > > > So, wb_kupdate and background_writeout are the big movers in terms of waiting, > > not the direct reclaimers which is what we were expecting. Of those big > > movers, wb_kupdate is the most interested because compare the following > > > > $ cat kern.log_2.1_test | awk -F ] '{print $2}' | sort -k 5 -n | uniq -c | grep wb_kup > > [ no output ] > > $ $ cat kern.log_1_test | awk -F ] '{print $2}' | sort -k 5 -n | uniq -c | grep wb_kup > > ? ? ?1 ?wb_kupdate ? ? ? ? ? congestion_wait sync=0 delay 15 timeout 25 > > ? ? ?1 ?wb_kupdate ? ? ? ? ? congestion_wait sync=0 delay 23 timeout 25 > > ? ?145 ?wb_kupdate ? ? ? ? ? congestion_wait sync=0 delay 25 timeout 25 > > ? ? ?8 ?wb_kupdate ? ? ? ? ? congestion_wait sync=0 delay 26 timeout 25 > > > > The vanilla kernel is not waiting in wb_kupdate at all. > > > > Jens, before the congestion_wait() changes, wb_kupdate was waiting on > > congestion and afterwards it's not. Furthermore, look at the number of pages > > that are queued for writeback in the two page allocation failure reports. > > > > without-revert: writeback:65653 > > with-revert: ? ?writeback:21713 > > > > So, after the move to async/sync, a lot more pages are getting queued > > for writeback - more than three times the number of pages are queued for > > writeback with the vanilla kernel. This amount of congestion might be why > > direct reclaimers and kswapd's timings have changed so much. > > > > Chris Mason hinted at this but I didn't quite "get it" at the time but is it > > possible that writeback_inodes() is converting what is expected to be async > > IO into sync IO? One way of checking this is if Frans could test the patch > > below that makes wb_kupdate wait on sync instead of async. > > > > If this makes a difference, I think the three main areas of trouble we > > are now seeing are > > > > ? ? ? ?1. page allocator regressions - mostly fixed hopefully > > ? ? ? ?2. page writeback change in timing - theory yet to be confirmed > > ? ? ? ?3. drivers using more atomics - iwlagn specific, being dealt with > > > > Of course, the big problem is if the changes are due to major timing > > differences in page writeback, then mainline is a totally different > > shape of problem as pdflush has been replaced there. > > > > ==== > > Have wb_kupdate wait on sync IO congestion instead of async > > > > wb_kupdate is expected to only have queued up pages for async IO. > > However, something screwy is happening because it never appears to go to > > sleep. Frans, can you test with this patch instead of the revert please? > > Preferably, keep the verbose-congestion_wait patch applied so we can > > still get an idea who is going to sleep and for how long when calling > > congestion_wait. thanks > > > > Not-signed-off-hacket-job: Mel Gorman > > --- > > > > diff --git a/mm/page-writeback.c b/mm/page-writeback.c > > index 81627eb..cb646dd 100644 > > --- a/mm/page-writeback.c > > +++ b/mm/page-writeback.c > > @@ -787,7 +787,7 @@ static void wb_kupdate(unsigned long arg) > > ? ? ? ? ? ? ? ?writeback_inodes(&wbc); > > ? ? ? ? ? ? ? ?if (wbc.nr_to_write > 0) { > > ? ? ? ? ? ? ? ? ? ? ? ?if (wbc.encountered_congestion || wbc.more_io) > > - ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? congestion_wait(BLK_RW_ASYNC, HZ/10); > > + ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? congestion_wait(BLK_RW_SYNC, HZ/10); > > ? ? ? ? ? ? ? ? ? ? ? ?else > > ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ?break; ?/* All the old data is written */ > > ? ? ? ? ? ? ? ?} > > Hmm, This doesn't looks correct to me. > > BLK_RW_ASYNC mean async write. > BLK_RW_SYNC mean read and sync-write. > > wb_kupdate use WB_SYNC_NONE. it's async write. > I don't think it's correct either which is why I described it as "something screwy is happening because it never appears to go to sleep". This is despite there being a whole lot of pages queued for writeback according to the page allocation failure reports. -- Mel Gorman Part-time Phd Student Linux Technology Center University of Limerick IBM Dublin Software Lab -- 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/