Re: [BUG] fatal hang untarring 90GB file, possibly writeback related.

[Mel Gorman <mgorman@suse.de>]

On Tue, May 03, 2011 at 09:22:33AM -0500, James Bottomley wrote:
> On Tue, 2011-05-03 at 09:13 -0500, James Bottomley wrote:
> > I've got a ftrace output of kswapd ... it's 500k compressed, so I'll
> > send under separate cover.
> 
> Here it is ... it's under 2.6.38.4 vanilla, but the code is similar. 
> 

I was quiet because I was off trying to reproduce this but not having
much luck. It doesn't seem directly related to filesystems or
cgroups. For example, here is what I see with ext4 without cgroups

                2.6.34-vanilla    2.6.37-vanilla    2.6.38-vanilla       rc6-vanilla
download tar           70 ( 0.00%)   68 ( 2.94%)   69 ( 1.45%)   70 ( 0.00%)
unpack tar            601 ( 0.00%)  605 (-0.66%)  604 (-0.50%)  605 (-0.66%)
copy source files     319 ( 0.00%)  321 (-0.62%)  320 (-0.31%)  332 (-3.92%)
create tarfile       1368 ( 0.00%) 1372 (-0.29%) 1371 (-0.22%) 1363 ( 0.37%)
delete source dirs     21 ( 0.00%)   21 ( 0.00%)   23 (-8.70%)   22 (-4.55%)
expand tar            263 ( 0.00%)  261 ( 0.77%)  257 ( 2.33%)  259 ( 1.54%)

(all results are in seconds)

When running in cgroups, the results are similar - bit slower but
not remarkably so. ext3 is slower but not enough to count as the bug.

The trace you posted is very short but kswapd is not going to sleep
in it. It's less than a seconds worth on different cpus so it's hard
to draw any conclusion from it other than sleeping_prematurely()
is often deciding that kswapd should not sleep.

So lets consider what keeps it awake.

1. High-order allocations? You machine is using i915 and RPC, something
   neither of my test machine uses. i915 is potentially a source for
   high-order allocations. I'm attaching a perl script. Please run it as
   ./watch-highorder.pl --output /tmp/highorders.txt
   while you are running tar. When kswapd is running for about 30
   seconds, interrupt it with ctrl+c twice in quick succession and
   post /tmp/highorders.txt

2. All unreclaimable is not being set or we are not balancing at all.
   Can you post the output of sysrq+m while the machine is struggling
   please?

3. Slab may not be shrinking for some reason. Can you run a shell
   script like this during the whole test and record its output please?

   #!/bin/bash
   while [ 1 ]; do
	   echo time: `date +%s`
	   cat /proc/vmstat
	   sleep 2
   done

   Similarly if this is a slab issue, it'd be nice to know who it is so

   #!/bin/bash
   while [ 1 ]; do
	   echo time: `date +%s`
	   cat /proc/slabinfo
	   sleep $MONITOR_UPDATE_FREQUENCY
   done

4. Lets get a better look at what is going on in kswapd

   echo 1 > /sys/kernel/debug/tracing/events/vmscan/enable
   cat /sys/kernel/debug/tracing/trace_pipe > vmscan-ftrace.txt

Out of curiousity, what's the exact machine you are testing on
because I want to see what sort of hardware combination triggers
this problem? Is the tar local or is it copied over NFS? What is the
configuration of the disk or partition you are copying to?

Thanks

-- 
Mel Gorman
SUSE Labs