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

Mel Gorman
2011-05-06T07:42:32Z

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