Bug 1369364

Created attachment 1193257 [details]
pmap

Created attachment 1193258 [details]
Statedump before drop_caches

Created attachment 1193259 [details]
Statedump after drop_caches

http://termbin.com/66ud — the script I use trying to reproduce the leak.

Observing the following in pmap:

===
00007fe430000000    132K rw---   [ anon ]
00007fe430021000  65404K -----   [ anon ]
00007fe438000000   6564K rw---   [ anon ] ← this value increases over time...
00007fe438669000  58972K -----   [ anon ] ← ...while this value decreases over time
00007fe43c000000    132K rw---   [ anon ]
00007fe43c021000  65404K -----   [ anon ]
00007fe440000000   6800K rw---   [ anon ]
00007fe4406a4000  58736K -----   [ anon ]
00007fe44552c000      4K -----   [ anon ]
00007fe44552d000   8192K rw---   [ anon ]
00007fe445d2d000      4K -----   [ anon ]
00007fe445d2e000  16908K rw---   [ anon ]
00007fe446db1000      4K -----   [ anon ]
00007fe446db2000  18744K rw---   [ anon ]                                                                                                                                                    00007fe448000000   9068K rw---   [ anon ]
00007fe4488db000  56468K -----   [ anon ]
00007fe44c027000  29424K rw---   [ anon ]
00007fe44dce3000     52K r-x-- meta.so
00007fe44dcf0000   2044K ----- meta.so
...snip...
===

Other anonymous allocations change over time as well, I have pointed only to one pair observing similar pattern.

I may also be experiencing this bug.

Distributed volume w/ 3.7.14, no patches.  One server is FreeBSD 10.x, the other is CentOS 6.  Both bricks are ZFS backed.

===
[root@colossus2 ~]# gluster volume info ftp
 
Volume Name: ftp
Type: Distribute
Volume ID: f3f2b222-575c-4c8d-92f1-e640fd7edfbb
Status: Started
Number of Bricks: 2
Transport-type: tcp
Bricks:
Brick1: 192.168.110.1:/tank/bricks/ftp
Brick2: 192.168.110.2:/ftp/bricks/ftp
Options Reconfigured:
performance.client-io-threads: on
cluster.weighted-rebalance: off
performance.readdir-ahead: on
nfs.disable: on
===

After approximately 24 hours of heaving reading on the client (copying 93728 files totaling 1.4Tb out of the fuse mount point, elsewhere on the system to a non-gluster space) , I found that the glusterfs process was consuming all system memory, including swap, approximately 34Gb.  Remounting the fuse volume freed up the memory.

Let me know if you need anything else.

Oops.  I am on 3.7.13.  Fat fingers.

I've run another test: http://termbin.com/cgzj

The idea of it is to split read/write workload across two clients. I'm attaching statedumps of both reader and writer.

Unfortunately, it seems, memory accounting for FUSE translator suffers from integer overflow (underflow?), because I get something like this:

===
[mount/fuse.fuse - usage-type gf_fuse_mt_iov_base memusage]
size=4262955128
num_allocs=1
max_size=4294967088
max_num_allocs=3
total_allocs=18389093
===

Another observation: reader consumes more memory than writer. Given cache-size is 32M (and if even it is used across 5 xlators), total RAM consumption should not exceed 160-200M). However, reader RAM:

===
root     30865  8.7  3.5 1054244 433676 ?      Ssl  Aug25  61:01 /usr/sbin/glusterfs --volfile-server=gluster.server.com --volfile-id=test /mnt/net/glusterfs/test2
===

and writer RAM:

===
root     30796  3.3  2.0 722464 249352 ?       Ssl  Aug25  23:11 /usr/sbin/glusterfs --volfile-server=gluster.server.com --volfile-id=test /mnt/net/glusterfs/test1
===

Created attachment 1194221 [details]
Statedump (reader)

Created attachment 1194222 [details]
Statedump (writer)

I also have the same bug, using versions 3.7.13 and 3.7.14 (compiled from sources, no patch) and 3.8.1 (using package from gluster download page).

Tested on an up-to-date Debian 8.

Same observations: memory always growing on any operations (recursive listing, reads, writes), even when always reading the same files. Even after days of non-activities.
Memory can grow until OOM-killer activates (>6Go of memory the time I let it go to that point).

Some memory data, tests performed on 3.8.1 gluster version (both servers and client are 64b Debian 8 up-to-date with default kernel options; test volume is a replica-2 volume without any tuning; mount is performed using "mount -t glusterfs" without any option):
What I did:
1. mounting the volume, removing all its content, umounting it
2. mounting the volume
3. performing a cp -Rp /usr/* /root/MNT
4. performing a rm -rf /root/MNT/*
5. re-doing 3, 4

VSZ/RSS of gluster client process are respectively:
- 381896 / 35688 just after mount
- 644040 / 309240 after 1st cp -Rp
- 644040 / 310128 after 1st rm -rf
- 709576 / 310128 after 1st kill -USR1 (it was just for testing)
- 840648 / 421964 after 2nd cp -Rp
- 840648 / 422224 after 2nd rm -rf

I created a small script in order to perform these operations in loop:
while /bin/true
do
  cp -Rp /usr/* /root/MNT/
  + get VSZ/RSS of glusterfs process
  rm -rf /root/MNT/*
  + get VSZ/RSS of glusterfs process
done

It gives:
1037256 645500
1037256 645840
1168328 757348
1168328 757620
1299400 869128
1299400 869328
1364936 980712
1364936 980944
1496008 1092384
1496008 1092404
1627080 1203796
1627080 1203996
1692616 1315572
1692616 1315504
1823688 1426812
1823688 1427340
1954760 1538716
1954760 1538772
2085832 1647676
2085832 1647708
2151368 1750392
2151368 1750708
2282440 1853864
2282440 1853764
2413512 1952668
2413512 1952704
2479048 2056500
2479048 2056712

I let it turning and gluster client finished by being killed by OOM-killer:
[1246854.291996] Out of memory: Kill process 931 (glusterfs) score 742 or sacrifice child
[1246854.292102] Killed process 931 (glusterfs) total-vm:3527624kB, anon-rss:3100328kB, file-rss:0kB

So on this machine ~3.5Gb of VSZ.

Created attachment 1195709 [details]
Valgrind Memcheck results

Attached Valgrind's Memcheck tool output for reading workload.

Thank you. I will take a look at this.

Nithya, please, take a look at my message to ML regarding Massif tool — I'd like to profile GlusterFS client with that too (but have some troubles) [1] [2].

[1] https://www.gluster.org/pipermail/gluster-devel/2016-August/050665.html

[2] https://www.gluster.org/pipermail/gluster-devel/2016-August/050666.html

I've tried different kinds of workload and rechecked it with 3.7.15, and it seems that leak is reproduced reliably with the following command on volume with lots of files:

find /mnt/volume -type f -print0 | xargs -0 stat

In half an hour RSS went from 150M to 1G.

Valgrind's Memcheck shows nothing. I still need some help on Massif tool.

Okay, I've finally managed how to deal with Massif tool, and here are the results.

Volume layout and options are the same as pointed in this BZ description. After mount RSS is 90M, after performing this command for some time (there are millions of files):

===
find /mnt/net/glusterfs/test -print0 | xargs -0 stat >/dev/null
===

RSS grows to 900M (and counting). VSZ also grows from ~400M to ~1200M (and counting). Performing drop_caches lowers RSS/VSZ usage only by ~100M.

There are 3 Massif logs attached, the main is for PID 23664. Also, I attach client statedump.

drop_caches was called before taking statedump and unmounting the volume.

Created attachment 1198653 [details]
Massif — Statedump for main PID

Created attachment 1198654 [details]
Massif — log for main PID

Created attachment 1198655 [details]
Massif — log for PID 23668

Created attachment 1198656 [details]
Massif — log for PID 23669

Oleksandr,
     As per the massif tool output, the heal size is only ~113MB:

--------------------------------------------------------------------------------
  n        time(i)         total(B)   useful-heap(B) extra-heap(B)    stacks(B)
--------------------------------------------------------------------------------
 89 500,793,720,910      112,228,416      109,224,305     3,004,111            0
 90 504,760,946,959      113,760,568      110,649,152     3,111,416            0

I also went through the major stack-traces which are active during the last snapshot. Nothing seems new. Most of them are related to last inode-allocations.
But you were saying the RSS was around 900M, I am wondering if you captured this at the same time or not.

Pranith

Re-run profiling with --pages-as-heap=yes as requested by Pranith in #gluster-dev.

===
root     10696 15.2  7.9 1557544 969640 pts/0  Sl+  вер07  95:47 valgrind --tool=massif --pages-as-heap=yes --run-libc-freeres=no --trace-children=yes --sim-hints=fuse-compatible /usr/sbin/glusterfs -N --volfile-server=glusterfs.example.com --volfile-id=some_volume /mnt/net/glusterfs/test
===

Main PID is 10696, attaching Massif output and statedump.

Created attachment 1198918 [details]
Massif — log for main PID 10696

Created attachment 1198919 [details]
Massif — Statedump for main PID 10696

Pranith, as you may see in #c23 and #c24, now all the memory gets into statistics:

===
--------------------------------------------------------------------------------
  n        time(i)         total(B)   useful-heap(B) extra-heap(B)    stacks(B)
--------------------------------------------------------------------------------
 50 1,164,197,215,106    1,481,912,320    1,481,912,320             0            0
 51 1,166,294,532,574    1,481,912,320    1,481,912,320             0            0
 52 1,168,332,670,161    1,481,912,320    1,481,912,320             0            0
 53 1,176,305,259,696    1,549,017,088    1,549,017,088             0            0
 54 1,176,353,806,434    1,549,021,184    1,549,021,184             0            0
===

I can reproduce the memory rise but statedumps don't seem to contain anything useful. I have started looking through the Massif files and will continue to run the tests to see what I can find.

Status so far:

I don't see anything in the Massif logs to pinpoint a leak. the quick-read translator was one point to consider but I can see the leak even with it disabled.

I am trying the following:

Created a single brick distribute volume with default options except for quick-read which I have disabled.
Copying 100000 zero byte files to the gluster fuse mount. RSS goes from 30m to 69m. 
Run rm -rf *. RSS jumps to 104m but then comes down to 74m once the operation is complete.

I will take another look at the readdirp code.

Just letting you know I am still looking into this but have not had much luck yet.
Will update when I have something.

Valgrind etc doesn't show any mem leaks so far but I do see the mem usage rising. I am wondering if this could be because of memory fragmentation rather than memory leaks.

Still looking. All ideas welcome.

Created attachment 1205471 [details]
Massif log visualization

REVIEW: http://review.gluster.org/15593 (protocol/client: reduce memory usage) posted (#1) for review on master by N Balachandran (nbalacha)

Oleksandr,

Do you see a difference with if you turn off performance.readdir-ahead? Apparently this is a known memory hog.

Still looking into how to improve things.

Discussed a lot on IRC, so dropping needinfo flag.

+

Hi,

  I think i have found one code path specific to memory leak in fuse xlator but it will leak only when a user
  will run umount and mount again.As per fuse xlator code it calls eh_new function to allocate event
  history on transatlor and max. size of this buffer is 1024,it is a circular buffer to store the messages but 
  memory is not released for this buffer in fini function.
  Every time when a user will run command mount/umount it will have a leak of messages in this circular buffer.

  To clean this leak need to update the code of fini in fuse xlator as below

>>>>>>>>>>>>>>>>>
   
@@ -5778,6 +5778,9 @@ fini (xlator_t *this_xl)
         if ((priv = this_xl->private) == NULL)
                 return;
 
+        if (this_xl->history)
+                eh_destroy (this_xl->history);
+


>>>>>>>>>>>>>>>>>>>>
  
Regards
Mohit Agrawal

I tested this again with the last version (3.10.0-1_amd64.deb). Two servers + one client, all 3.10.0-1 from .deb package (from gluster site), on up-to-date debian 8 64b. One replica 2 volume created for this test, without any option set.

From client, performing:
0. unpacking gluster sources in mountpoint
1. rm -rf glusterfs-3.10.0-* ;  for i in `seq 1 50`; do cp -R glusterfs-3.10.0/ glusterfs-3.10.0-$i; done
2. go to 1
In the same time the memory on the glusterfs process on client (VSZ and RSS size):
431704 10568
(…)
497240 20500
(…)
693848 264396
(…)
759384 388924
(…)
955992 606768
(…)
Note: RSS grows mostly continuously, whereas VSZ grows by "jumps" (i.e. 693848 then suddenly 759384).

Note bis: removing all content, then performing syncs (and sending 3 to /proc/sys/vm/drop_caches), don't make memory (VSZ nor RSS) to reduce, even 1 hour later (well, not exaclty, while removing all content RSS goes from 607300 to 603920).

Regards
--
Y.

This bug is getting closed because GlusteFS-3.7 has reached its end-of-life.

Note: This bug is being closed using a script. No verification has been performed to check if it still exists on newer releases of GlusterFS.
If this bug still exists in newer GlusterFS releases, please reopen this bug against the newer release.