Re: NFS Regression in commit 0b26a0bf6ff398

From: Eric B Munson
Date: Thu Feb 24 2011 - 14:58:21 EST


On Tue, 15 Feb 2011, Trond Myklebust wrote:

> On Tue, 2011-02-15 at 19:56 -0500, Eric B Munson wrote:
> > While testing some 2.6.38 work my rsync backup script started consuming
> > large amounts of memory (all available before dying with no more available
> > memory). I have bisected the problem back to 0b26a0bf6ff398. I am
> > unfamiliar with the NFS code so I don't know where to start looking for a
> > possible fix. My backups files from my home directory to an NFS mounted
> > directory. The NFS server is a Synology DS-411+ if it matters. Let me know
> > if there is any other information I can provide.
>
> Exactly which 2.6.38 kernel are you running, and which NFS version?
>
> I'm having trouble seeing how the patch in question can be responsible
> for what you are seeing, so please could you provide more details of
> your test setup.
>

Trond,

I just updated to 2.6.38-rc6 and I still see the regression. I will add some
more information here that might be useful.

The entries from ps -ef:

user 3116 3096 0 14:45 pts/4 00:00:00 /bin/bash /home/emunson/bin/bu
user 3117 3116 3 14:45 pts/4 00:00:05 rsync -avz --delete --exclude=*.
user 3118 3117 26 14:45 pts/4 00:00:41 rsync -avz --delete --exclude=*.
user 3119 3118 0 14:45 pts/4 00:00:01 rsync -avz --delete --exclude=*.

strace from 3117:
user@machine:~$ sudo strace -p 3117
Process 3117 attached - interrupt to quit
select(6, [5], [], NULL, {33, 382426}) = 0 (Timeout)
select(6, [5], [], NULL, {60, 0}) = 0 (Timeout)
select(6, [5], [], NULL, {60, 0}) = 0 (Timeout)
select(6, [5], [], NULL, {60, 0}) = 0 (Timeout)
select(6, [5], [], NULL, {60, 0}

strace from 3118:
...
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
lstat("linux-2.6/net/netfilter/xt_dscp.c", {st_mode=S_IFREG|0644, st_size=2890, ...}) = 0
...

These stream by very quickly.

and finally from 3119:
user@machine:~$ sudo strace -p 3119
Process 3119 attached - interrupt to quit
select(5, NULL, [4], [4], {15, 621031}) = 0 (Timeout)
select(5, NULL, [4], [4], {60, 0}) = 0 (Timeout)
select(5, NULL, [4], [4], {60, 0}) = 0 (Timeout)
select(5, NULL, [4], [4], {60, 0}) = 0 (Timeout)
select(5, NULL, [4], [4], {60, 0}

Now from my /etc/fstab:

/dev/mapper/isw_gbdfddifh_Volume02 / ext4 errors=remount-ro 0 1
/dev/mapper/isw_gbdfddifh_Volume03 none swap sw 0 0

#NFS
192.168.1.50:/volume1/backup /mnt/backup nfs rsize=1048576,wsize=1048576,user 0 0
192.168.1.50:/volume1/data /mnt/data nfs rsize=1048576,wsize=1048576,user 0 0
192.168.1.50:/volume1/music /mp3 nfs rsize=1048576,wsize=1048576,user 0 0
192.168.1.50:/volume1/video /video nfs rsize=1048576,wsize=1048576,user 0 0

The backup script is reading from my home dir (locally mounted on partition 2 of a
fake raid stripe). And writing to /mnt/backup/bert-ubuntu.

And here is the error I get when rsync finally dies:

ERROR: out of memory in flist_expand [generator]
rsync error: error allocating core memory buffers (code 22) at util.c(117) [generator=3.0.7]
rsync: connection unexpectedly closed (9324 bytes received so far) [sender]
rsync error: error in rsync protocol data stream (code 12) at io.c(601) [sender=3.0.7]

At the point when this happens, rsync is consuming almost all of the free memory on the system.

I am nost sure if there is anything else that might help, please let me know if you need more
information.

Attachment: signature.asc
Description: Digital signature