Memory leak during massive file upload (or download) through SFTP frontend

[francois]

Today, I copied about 12'000 files for a total size of about 52 GB into Tahoe with the SFTP frontend.

Here's what top has to say about the Tahoe process after this operation.

 2765 francois  20   0 2059m 1.5g 2472 D    2 75.4 527:08.83 python

I will update this ticket as soon as I can gather more details.

David-Sarah Hopwood proposed to do the same test a second time via the wapi to help locate the leak.

Here is what Brian Warner proposed on IRC:

keep track of the process size vs time, with munin or a script that saves values and then graph them with gnuplot or something

I think tahoe's /stats WAPI will give you process-memory-size info

the idea is to do some operation repeatedly, measure process-space change while that's running, then switch to some other operation and measure that slope, and look for differences

'cp' to an SFTP-mounted FUSEish thing, vs 'tahoe cp' might be a good comparison

[zooko]

Also try the handy new tool "smem":

​http://www.selenic.com/smem/

That process that you are reporting on is the gateway process, right? (I.e., the SFTP server and the Tahoe-LAFS storage client.)

[zooko]

This is serious! If it happens when not using SFTP then it is a critical regression in Tahoe-LAFS. If it happens when using SFTP then it is a critical problem in the new SFTP support. :-/

[francois]

In both graphs, x axis is in 10 seconds increments and y is in bytes.

The first graph was generated by logging memory usage, as reported by smem during the upload of 53 GB of files with tahoe cp. Please note that the increase in memory usage (at x==4000) was due to the opening of a single file with SFTP during this process.

The second graph was generated by logggin memory usage during the upload of the same files through the SFTP frontend. The upload was stopped before it finished.

The conclusion I take from these graphs, is that the leak probably lies in the SFTP frontend.

[francois]

For the record, those were the scripts used to generated both graphs.

$ smem-log.sh 1 [t]ahoe-client.tac | tee /tmp/tahoe-sftp-smem.log

The gnuplot script.

set xlabel "seconds"
set ylabel "bytes"
plot "tahoe-sftp-smem.log" using 0:6 with lines title 'Swap', \
              "tahoe-sftp-smem.log" using 0:7 with lines title 'USS',  \
              "tahoe-sftp-smem.log" using 0:8 with lines title 'PSS',  \
              "tahoe-sftp-smem.log" using 0:9 with lines title 'RSS'

smem-log.sh

#!/bin/sh

while :; do
  SMEM=$(smem -P $2 -H)

  if [ $? -eq 0 ]; then
    echo "\"$(date)\" $SMEM"
  fi
  sleep $1
done

[zooko]

François: what is the script used to initiate the 12,000 file uploads? There should be two scripts--one using tahoe cp and one using SFTP, right? I want to see how many files are being uploaded in parallel vs. in serial.

[zooko]

"memory usage, as reported by smem" -- more specifically what does smem report here? resident/virtual-size/ ?

[zooko]

Replying to zooko:

"memory usage, as reported by smem" -- more specifically what does smem report here? resident/virtual-size/ ?

Well fdz posted the script:

  SMEM=$(smem -P $2 -H)

Oh, and I see the graph says "swap/PSS/USS/RSS".

[francois]

Replying to zooko:

François: what is the script used to initiate the 12,000 file uploads? There should be two scripts--one using tahoe cp and one using SFTP, right? I want to see how many files are being uploaded in parallel vs. in serial.

The files were uploaded sequentially.

And, my bad, the values on the y axis are in kbytes and not bytes as mentionned in 5.

[davidsarah]

It turns out that the SFTP code was logging all of the data going through it to the foolscap log. I've fixed that in the branch, so please pull and try again (if only to eliminate this as a possible cause of the leak).

[francois]

Replying to davidsarah:

It turns out that the SFTP code was logging all of the data going through it to the foolscap log. I've fixed that in the branch, so please pull and try again (if only to eliminate this as a possible cause of the leak).

Same test with latest code. The memory leak is probably somewhere else.

[zooko]

One way to investigate this would be to take one of the SFTP unit tests and wrap it in a call to ​pyutil.memutil.check_for_obj_leakage() and make that be a new unit test.

The docstring of check_for_obj_leakage() explains how to (carefully) interpret its results.

[francois]

Further testing has shown that the leak can also be reproduced by downloading files from Tahoe (i.e. copying them from the SFTP server to the local system).

[davidsarah]

Graph of objects *possibly* leaked by an SFTP upload, and their backreferences

[davidsarah]

Hmm, how do we know this is not the same bug as #891 ?

The difference between the behaviour of SFTP and tahoe cp doesn't necessarily imply that it isn't, because the SFTP implementation might be allowing more concurrency. François, are you absolutely sure that each SFTP upload (that is, the upload to storage servers, not just the gateway) is completing before starting the next?

[francois]

OK, I've been running each SFTP unit test many times in a row to see how increase in memory usage was influenced by each test.

term1 $ trial -u allmydata.test.test_sftp.Handler.test_basic
term2 $ while :; do smem -P test_basi[c] -H; sleep 10; done

Here are the results.

• All SFTP tests -> Leak
• test_basic -> No leak
• test_convert_error -> No leak
• test_execCommand_and_openShell -> No leak
• test_extendedRequest -> No leak
• test_makeDirectory -> No leak
• test_not_implemented-> No leak
• test_openDirectory_and_attrs -> No leak
• test_openFile_read -> Perhaps a very small leak (4.5 MB increase after ~30 iterations)
• test_openFile_write -> Huge LEAK (420 MB increase after 110 iterations)
• test_removeDirectory -> Small leak (about 3 MB increase after 100 iterations)
• test_removeFile -> Small leak (about 2.1 MB increase after 100 iterations)
• test_renameFile -> Small leak (5 MB increase after 100 iterations)
• test_renameFile_posix -> Small leak (4.5 MB increase after 100 iterations)

So, the main culprit is test_openFile_write!

[francois]

Additional testing has shown that the major memory leak comes from the last part on test_openFile_write which begins in ​test_sftp.py line 887.

[francois]

Yay! David-Sarah found the cause of the most significant leak in the SFTP frontend and fixed it in 3c44389440097dff.

There are still some minor leaks (two order of magnitude smaller) as mentioned in 16 but we can probably bear with them for 1.7.0-beta.

[zooko]

I reviewed 3c44389440097dff and saw no problems.

[zooko]

I guess we're leaving this ticket open to investigate the smaller ones after 1.7.

[davidsarah]

François: can you reproduce the graph in comment:12 with current trunk?

[francois]

Replying to davidsarah:

François: can you reproduce the graph in comment:12 with current trunk?

Here is the result of the test with 1.6.1-r4477. The graph shows that the actual memory leak is not as small as I thought in comment:18. Perhaps functions that are still leaking memory are being called much more often than openFile_write in a typical SFTP session.

[zooko]

This is a serious bug. It is correctly marked "critical" in Priority. What's the next step? I think it is either to use a tool like ​check_for_obj_leakage in a controlled deterministic unit-test style exercise of the SFTP front-end code, or else for someone to experiment with a live system and try to figure out what sorts of usage patterns trigger the memory consumption.

Any other ideas?

[zooko]

In ​http://tahoe-lafs.org/pipermail/tahoe-dev/2010-October/005464.html François says that he also gets a memory leak during tahoe deep-check --add-lease --repair in addition to getting a memory leak while using the sftp frontend. Could there be two leaks? Or is it likely to be the same one in these two cases?

[warner]

I think his email describes the leak here in #1045, but not necessarily in deep-check. The distinguisher will be if there are lots of MutableFileNodes hanging around. The #1045 leak appears to be related to making lots of changes to a single mutable file, whereas deep-check is going to be reading from lots and lots of files (probably mostly immutable, but possibly some mutable, depending upon how you use directories).

[warner]

Oh, Francois, could you mention whether these uploads are all going to the same directory, or if they're going to a variety of directories? I think the "massive" qualifier in the title might best apply to the number of changes being made to a single directory, rather than the total size of the data being uploaded.

Looking at the difference between A) upload 10000 files of 1MB each, versus B) upload 10 files of 1GB each, would help distinguish between problems with large files and problems with large/churning directories. And uploading then all into one directory versus spread across 1000 directories would help distinguish between mutable-file-modification in general, and lots-of-generations on a single mutable file.

[davidsarah]

Replying to warner:

... And uploading then all into one directory versus spread across 1000 directories would help distinguish between mutable-file-modification in general, and lots-of-generations on a single mutable file.

Please make this:

• upload all into the root directory (of the SFTP user);
• upload all into one subdirectory;
• upload spread across 1000 subdirectories.

This will test whether it is significant that ​a reference to the root dirnode is held for as long as the SFTP user session is logged in.

[davidsarah]

mutable/common.py: make the ResponseCache? only cache shares with the last-seen seqnum for a given storage index. No unit tests; do not apply to trunk yet.

[francois]

Replying to zooko:

In ​http://tahoe-lafs.org/pipermail/tahoe-dev/2010-October/005464.html François says that he also gets a memory leak during tahoe deep-check --add-lease --repair in addition to getting a memory leak while using the sftp frontend. Could there be two leaks? Or is it likely to be the same one in these two cases?

To avoid mixing things up, I have created another ticket about this deep-check leak: #1229.

[francois]

Replying to davidsarah:

This will test whether it is significant that ​a reference to the root dirnode is held for as long as the SFTP user session is logged in.

This is implemented in this ​commit. Unfortunately, it doesn't look sufficient to have ResponseCache correctly gc'ed.

[davidsarah]

Replying to francois:

Replying to davidsarah:

This will test whether it is significant that ​a reference to the root dirnode is held for as long as the SFTP user session is logged in.

This is implemented in this ​commit. Unfortunately, it doesn't look sufficient to have ResponseCache correctly gc'ed.

This change looks correct, but I'd rather not make it if it doesn't solve the underlying problem.

[davidsarah]

Discussion of whether the ResponseCache is needed: ​http://tahoe-lafs.org/pipermail/tahoe-dev/2010-October/005488.html

[davidsarah]

Replying to francois:

Replying to zooko:

In ​http://tahoe-lafs.org/pipermail/tahoe-dev/2010-October/005464.html François says that he also gets a memory leak during tahoe deep-check --add-lease --repair in addition to getting a memory leak while using the sftp frontend.

The following test confirms that the size of the ResponseCache (not the number of entries, interestingly) increases every time we download a mutable file:

    def test_response_cache_memory_leak(self):
        d = self.nodemaker.create_mutable_file("contents")
        def _created(n):
            d = n.download_best_version()
            d.addCallback(lambda res: self.failUnlessEqual(res, "contents"))
            d.addCallback(lambda ign: self.failUnless(isinstance(n._cache, ResponseCache)))

            def _check_cache_size(expected):
                # The total size of cache entries should not increase on the second download.
                d2 = n.download_best_version()
                d2.addCallback(lambda ign: self.failUnlessEqual(len(repr(n._cache.cache)), expected))
                return d2
            d.addCallback(lambda ign: _check_cache_size(len(repr(n._cache.cache))))
            return d
        d.addCallback(_created)
        return d
    test_response_cache_memory_leak.todo = "This isn't fixed (see #1045)."

Could there be two leaks? Or is it likely to be the same one in these two cases?

I think we have no evidence for two independent leaks at this point (but we might need to fix the ResponseCache one in order to see whether there is anything else).

review-needed for the above test.

[zooko]

pyutil's ​memutil.check_for_obj_leakage() might be useful, and so might ​memutil.measure_obj_leakage().

[francois]

Replying to davidsarah:

The following test confirms that the size of the ResponseCache (not the number of entries, interestingly) increases every time we download a mutable file:

Well, the number of entries actually increases in the second dimension of the _cache array. The cache looks like that in a simplified way: _cache[verinfo][offset].

review-needed for the above test.

I reviewed your test and it looks good. I also actually tested it, when the cache is activated it fails and when the cache is deactivated (by commenting trunk/src/allmydata/mutable/servermap.py#L584​) it passes.

[david-sarah@…]

In 59e80b2ec92928bf:

test_mutable.py: add test for ResponseCache? memory leak. refs #1045, #1129

[davidsarah]

make ResponseCache? smarter to avoid memory leaks: don't record timestamps, use DataSpans? to merge entries, and clear the cache when we see a new seqnum. refs #1045, #1229. (This supercedes only-cache-last-seen-seqnum.darcs.patch.)

[warner]

new-responsecache.darcs.patch​ looks great! r+ from me.

[david-sarah@…]

In 4061258c85da2960:

(The changeset message doesn't reference this ticket)

[davidsarah]

francois: please repeat the graph of comment:12 and comment:23 with current trunk.

[francois]

This is much better now!

Thank you very much Brian and David-Sarah for your great work.

This following graph was produced during the upload of about 3.5 GB of audio files (between 1 MB and 10 MB in size) through the SFTP frontend. In this particular workload, a (small) leak of about 4 MB per hour is still visible.

I'd say that we can consider this issue closed but I'll continue to investigate this kind of issue and will open further tickets as necessary.

[francois]

Please find attached a ready-to-merge patch to the NEWS file.

[davidsarah]

NEWS entry in 679c090c82cede16. We'll open a new ticket for the smaller leak.