high CPU load on storage servers when uploading large mutable file

[zooko]

Jody Harris and Justin Stottlemyer both reported that uploading a large mutable file causes high CPU load on storage servers. Brian then found this bug: ​http://foolscap.lothar.com/trac/ticket/149 (O(n²) CPU/malloc during receive of large strings) which could explain their problems. Jody's ​report was on the mailing list and Justin's was #962.

The next step is for Brian to fix this issue in foolscap and then for Jody and Justin to test out the new version of foolscap with Tahoe-LAFS and see if that fixes that problem.

[zooko]

Brian: wouldn't this cause a similar high CPU load on storage clients during download of a large mutable file just as it does on storage servers during upload of a large mutable file? As far as I understand, the high CPU load is incurred whenever a large string is transferred through foolscap.

[zooko]

In the initial message I wrote:

The next step is for Brian to fix this issue in foolscap

Well actually Brian doesn't have to be the one to do it! I posted some untested example code over on ​http://foolscap.lothar.com/trac/ticket/149#comment:4 which shows one way that I might do it if I were fixing the code. Perhaps I or someone else could write the appropriate unit tests and implement that solution or another solution, provided that Brian indicates willingness to accept such patches into foolscap.

[warner]

Yes, the foolscap bug affects the recipient of a large token (such as the single large block in a large mutable file). That will be either the storage server during upload, or the client during download.

Your sample code is a good starting point.. I want to clean up the token-parsing state machine at the same time, so I'll be incorporating your ideas into the full fix. Thanks!

[zooko]

I've offered a patch over on ​http://foolscap.lothar.com/trac/ticket/149 . Review needed, I guess. Although Brian hasn't indicated that he's willing to accept this sort of patch (replacing the current string buffer in banana.py a StringChain) and he has started on a patch that fixes the issue in a different way.

[zooko]

Yay Brian accepted the patch and released foolscap v0.5.1. Here is the request to upload foolscap v0.5.1 to Lucid: ​https://bugs.launchpad.net/ubuntu/+source/foolscap/+bug/548993

[zooko]

maco package foolscap 0.5.1 for Ubuntu Lucid and ChosenOne ran some experiments. His experiments showed that storage servers running foolscap 0.5.1 did not accept shares of large mutable files faster than when they were running foolscap 0.4.2:

While using 0.4.2:

​http://pastie.org/private/39twijkh8ip5ffzeiog

    * Current Size: 41943040
          o Per-Server Response Times:
                + [uydf5ds4]: 846ms

​http://pastie.org/private/ofjv1dgmw44q44nt1jo4nw

    * Current Size: 104857600
          o Per-Server Response Times:
                + [uydf5ds4]: 6.07s

​http://pastie.org/private/zcns60kuyx2rjdpfhnl2g

    * Current Size: 209715200
          o Per-Server Response Times:
                + [uydf5ds4]: 20 seconds

After upgrading to foolscap 0.5.1:

​http://pastie.org/private/g9xfymdchzvxqpkoxdowkq

    * Current Size: 209715200
          o Per-Server Response Times:
                + [uydf5ds4]: 36 seconds

​http://pastie.org/private/fnkdkn7jkhm7yriidkx0ba

    * Current Size: 209715200
          o Per-Server Response Times:
                + [uydf5ds4]: 69 seconds

Hm. In fact, the pattern, if there is one, is that it takes twice as long every time he uploads a file!

[zooko]

I tried to reproduce ChosenOne's results. I don't think I succeeded:

size MB push rate MBps (all results from several trials)
------- ------------------------------------------------
10      2.88 1.97 1.35 2.17
20      1.99 2.39 2.89
40      1.37 1.18 2.88 
80      3.02 1.18 1.22 3.02
160     2.12 0.82 1.10 2.12
320     1.75

So my best hypothesis is that ChosenOne was somehow still using foolscap 0.4.2 when he did the second set of experiments and he thought he was using foolscap 0.5.1. However, I asked him several times to check for that when he was running those experiments and he did check and he was pretty sure the storage servers were running 0.5.1. So, I think we need someone else to try to reproduce this. I guess it is possible that the foolscap-0.5.1 package from Ubuntu (which is what ChosenOne was testing) has some terrible performance flaw in it but foolscap-0.5.1 upstream doesn't. Note that there is a lot of variance. In my experiments (which were performed under not-really-controlled conditions where I was using my laptop for other things at the same time as running the benchmarks) there was large variance -- 2 x or 3 x between successive runs at the same file size. So another next step would be for ChosenOne to try to reproduce his own experiment and run the 200 MiB mutable file upload several times with foolscap-0.5.1 and several times with foolscap-0.4.2 and see if there is a pattern after, say, half-a-dozen runs each. Oh, and one time I accidentally left off the "mutable" checkbox and uploaded a 40 MB file as an immutable file. Look what happened!

# Encode And Push: 3 minutes (216.7kBps)

    * Cumulative Encoding: 6.31s (6.34MBps)
    * Cumulative Pushing: 2 minutes (224.4kBps)
    * Send Hashes And Close: 928ms

With foolscap-0.5.1, Tahoe-LAFS v1.6.1 uploads mutable files much faster than immutable files. It's kind of disappointing how slow Tahoe-LAFS is at immutable file upload (and nobody knows why! #320, #392, #809).

On the other hand, the slowness of uploading immutable files is probably mostly due to waiting unnecessarily for round trips, so it is "network nice" -- uploading a large immutable file probably won't slam your network and interfere with your web browsing as much as uploading a large mutable file will. Also, the behavior will be about the same for a file of any size.

The slowdown that we had with large mutable files (the subject of this ticket) was due to burning up the CPU on the receiver's side, which is definitely not nice and which got less nice the larger your file was, so I'm very glad this ticket has been fixed.

If it has.

Assigning to ChosenOne to try to reproduce it.

[zooko]

Note that my attempts to reproduce this in comment:8 are on my Macbook Pro running Mac OS 10.4, not on Ubuntu.

[zooko]

ChosenOne reproduced this problem on his Ubuntu Lucid (alpha) at my request. It really seems like on his system there is a superlinear cost (whether CPU cost or some other time-sink I'm not sure) to uploading mutable files. ​http://pastie.org/914448

400 MB	

real	23m3.963s
user	0m0.030s
sys	0m0.930s

# Pushing: 16 minutes (412.1kBps)

​http://pastie.org/private/c8zkyjea2ogn5so6dlxq

## 400MB
   real	15m55.535s
   user	0m0.070s
   sys	0m0.510s
   # Pushing: 7 minutes (923.1kBps)

## 200MB
1
   real	1m58.554s
   user	0m0.020s
   sys	0m0.400s
   # Pushing: 37 seconds (5.57MBps)

2
   real	1m22.431s
   user	0m0.030s
   sys	0m0.400s
   # Pushing: 26 seconds (7.80MBps)
3:
   real	1m2.264s
   user	0m0.020s
   sys	0m0.390s
   # Pushing: 15 seconds (13.65MBps)
4:
   real	0m59.669s
   user	0m0.050s
   sys	0m0.320s
   # Pushing: 16 seconds (12.44MBps)
5:
   real	1m3.264s
   user	0m0.020s
   sys	0m0.320s
   # Pushing: 18 seconds (11.15MBps)
6:
   real	0m56.371s
   user	0m0.020s
   sys	0m0.340s
   # Pushing: 17 seconds (12.07MBps)
7:
   real	1m4.337s
   user	0m0.060s
   sys	0m0.310s
   # Pushing: 21 seconds (9.85MBps)  
8:
   real	0m52.630s
   user	0m0.020s
   sys	0m0.350s
   # Pushing: 18 seconds (11.60MBps)
9:
   real	0m49.644s
   user	0m0.000s
   sys	0m0.330s
   # Pushing: 17 seconds (11.88MBps)
10:
   real	0m47.338s
   user	0m0.000s
   sys	0m0.310s
   # Pushing: 13 seconds (16.04MBps)

[zooko]

ChosenOne: please give us the following information:

1. The set of storage servers connected to your web gateway (this set is visible on the Welcome Page of your web gateway).
2. The output of tahoe --version-and-path
3. The output of apt-cache policy python-foolscap
4. The output of apt-cache policy tahoe-lafs
5. The output of python -c 'import pkg_resources;print pkg_resources.require("foolscap")'
6. The output of python -c 'import foolscap;print foolscap;print foolscap.__version__'

Thanks!

[ChosenOne]

1. There is just one storage server on my local test box, called "test1 (uydf5ds4zxp4d2xvstcklra2nhmbk2nt)"

2. (There were some deprecationwarnings from popen and hashlib that I cut out)

   allmydata-tahoe: 1.5.0 (/usr/lib/pymodules/python2.6), foolscap: 0.5.1 (/usr/lib/pymodules/python2.6/foolscap), pycryptopp: 0.5.17 (/usr/lib/pymodules/python2.6/pycryptopp), zfec: 1.4.5 (/usr/lib/pymodules/python2.6/zfec), Twisted: 8.2.0 (/usr/lib/python2.6/dist-packages/twisted), Nevow: 0.9.31 (/usr/lib/python2.6/dist-packages/nevow), zope.interface: unknown (/usr/local/lib/python2.6/dist-packages/zope/interface), python: 2.6.4 (/usr/bin/python), platform: Linux-Ubuntu_9.10-x86_64-64bit_ELF (None), sqlite: 3.6.16 (unknown), simplejson: 2.0.9 (/usr/local/lib/python2.6/dist-packages/simplejson-2.0.9-py2.6-linux-x86_64.egg/simplejson), pyOpenSSL: 0.9 (/usr/lib/pymodules/python2.6/OpenSSL), setuptools: 0.6c9 (/usr/lib/python2.6/dist-packages/setuptools), pysqlite: 2.4.1 (/usr/lib/python2.6/sqlite3)
   

3. (manually translated into english by myself)

    python-foolscap:
     installed: 0.5.1+dfsg-0ubuntu1
     candidate: 0.5.1+dfsg-0ubuntu1
     version table:
    *** 0.5.1+dfsg-0ubuntu1 0
           100 /var/lib/dpkg/status
        0.4.2+dfsg-1 0
           500 http://de.archive.ubuntu.com karmic/universe Packages
   

4. (see 3)

   tahoe-lafs:
     installed: 1.5.0-0ubuntu1
     candidate: 1.5.0-0ubuntu1
     version table:
    *** 1.5.0-0ubuntu1 0
           500 http://de.archive.ubuntu.com karmic/universe Packages
           100 /var/lib/dpkg/status
   

5.

[foolscap 0.5.1 (/usr/lib/pymodules/python2.6), Twisted 8.2.0 (/usr/lib/python2.6/dist-packages)]

6.

 <module 'foolscap' from '/usr/lib/pymodules/python2.6/foolscap/__init__.py'>
0.5.1

[zooko]

Thanks! In regards to your answer to my question 1, though, did you look at the gateway Welcome Page to make sure that it is connecting to only that one storage server?

If you get a chance I would appreciate it if you would upgrade to Tahoe-LAFS v1.6.1 (from Ubuntu Lucid) and try your ten 200 MB tests again! Thank you.

[davidsarah]

Could be virtual memory thrashing, maybe? What are the page-fault rates for various sizes of file?

[zooko]

If anyone wants to try to reproduce this on Ubuntu Lucid here's the process:

sudo apt-get install tahoe-lafs
mkdir introducer
tahoe create-introducer -C introducer
tahoe start introducer
mkdir server
tahoe create-node -C server --introducer=`cat introducer/introducer.furl`
tahoe start server
mkdir client
tahoe create-client -C client --introducer=`cat introducer/introducer.furl`

Now the client is listening on localhost port 3456. If you open a web browser to http://localhost:3456 then you'll see the web user interface for Tahoe-LAFS. You can click on the button to select a file from your filesystem and the "upload" button to upload that file. The issue that ChosenOne sees only applies to mutable files, so check the "mutable" checkbox. Or you can use the command-line tool:

tahoe put --mutable $FILENAME

Please try uploading a mutable file of about 200 MB several times and then uploading a mutable file of about 400 MB a few times. The look at this list of recent uploads and downloads and how fast they went:

http://localhost:3456/status/

If the 400 MB files were substantially slower (like, half as fast in the "Pushing" measurement) then you've successfully reproduced ChosenOne's bug!

[zooko]

Oops, after I posted those instructions I tried them myself and noticed a bug in the instructions. After tahoe create-client then you need tahoe start client. Sorry about that.

[stott]

Confirmed very high load on 100M+ mutable file.

root@SM-MGMT01:~# time tahoe put --mutable ~/524stottlemyer.zip /usr/lib/pymodules/python2.6/foolscap/banana.py:2: DeprecationWarning?: the sets module is deprecated

import struct, sets, time

200 OK URI:SSK:fynm2m23iii5eiudqdwj4n4qfe:2c7kwpuypkve7rbt62xxil3z7jsvmfdq2h6vrrxejhj7ppo3bzzq

real 2m40.807s user 0m0.270s sys 0m0.080s

allmydata-tahoe: 1.5.0, foolscap: 0.4.2, pycryptopp: 0.5.17, zfec: 1.4.5, Twisted: 8.2.0, Nevow: 0.9.31, zope.interface: unknown, python: 2.6.4rc2, platform: Linux-Ubuntu_9.10-x86_64-64bit_ELF, sqlite: 3.6.16, simplejson: 2.0.9, pyOpenSSL: 0.9, setuptools: 0.6c9, pysqlite: 2.4.1

[stott]

After upgrading to foolscap 0.5.1 performance is roughly 8X faster. CPU is a fraction of previous usage.

time tahoe put --mutable ~/524stottlemyer.zip 200 OK URI:SSK:6mndkeskunhpm555lrxnan6qbe:eqh32z4portwuk3qsp2ltr7wknwrjbakiijzbeqdq5smknc3qzua

real 0m23.484s user 0m0.220s sys 0m0.100s root@SM-MGMT01:/tahoe# tahoe -V /usr/lib/python2.6/dist-packages/formless/annotate.py:730: DeprecationWarning?: object.new() takes no parameters

rv = cls = InterfaceClass?.new(cls, name, bases, dct)

/usr/lib/python2.6/dist-packages/nevow/testutil.py:7: DeprecationWarning?: The popen2 module is deprecated. Use the subprocess module.

from popen2 import Popen3

/usr/lib/python2.6/dist-packages/nevow/guard.py:15: DeprecationWarning?: the md5 module is deprecated; use hashlib instead

import md5

allmydata-tahoe: 1.5.0, foolscap: 0.5.1, pycryptopp: 0.5.17, zfec: 1.4.5, Twisted: 8.2.0, Nevow: 0.9.31, zope.interface: unknown, python: 2.6.4rc2, platform: Linux-Ubuntu_9.10-x86_64-64bit_ELF, sqlite: 3.6.16, simplejson: 2.0.9, pyOpenSSL: 0.9, setuptools: 0.6c9, pysqlite: 2.4.1

[zooko]

It is good to have confirmation that foolscap-0.5.1 is much better than foolscap-0.4.2 in this respect. Note that stott is using Ubuntu 9.10 in these tests. The remaining question is whether anyone can replicate ChosenOne's results one Ubuntu 10.04 (using the Tahoe-LAFS and the foolscap that come packaged by Ubuntu). In particular, is the rate of upload slower for larger files. For example, if stott can upload a 100 MB file at a rate of about 4.2 MB/s (per his comment:18), can he also upload a 200 MB file at about the same rate?

Be ware of memory usage effects -- swapping for example. Mutable files of that size use up substantial RAM.

[stott]

Attempting to reproduce the bug, I was not able to reproduce the results. CPU utilization was linear and performance was linear until I began to use swap space. Memory consumption was not linear with size of the mutable file.

NOTE:CPU Utilization on the gateway was at 100% though the other cores still had spare cycles.

root@sm-mgmt01:~# time tahoe put --mutable 100MB.zip
200 OK
URI:SSK:j5qyjqu32gnwsdkkgoyvdfv5yu:nezeyykufmfs5cel5kdqxx62qfm5ydyaamcods3qdtzrv4xfhz4q

real    0m21.745s
user    0m0.320s
sys     0m0.090s
root@sm-mgmt01:~# time tahoe put --mutable 200MB.zip
200 OK
URI:SSK:lypkcn3sm43dul2tsj4vto3nq4:b3dvlpfbmrwr2qussaefqu6kifx575ao63wlys4exjk3m6fhutva

real    0m42.530s
user    0m0.390s
sys     0m0.210s
root@sm-mgmt01:~# time tahoe put --mutable 300MB.zip
200 OK
URI:SSK:lwpspr6yl2prrdajzcgtw77u7q:i6yor622koofviu5qn5f2kk6nszfg36anajtgho7kf4pp24ui4aa

real    1m6.338s
user    0m0.420s
sys     0m0.200s
root@sm-mgmt01:~# time tahoe put --mutable 400MB.zip
200 OK
URI:SSK:regvthmbtq7zds67qf2k72wafm:mtv5hpilg63kbeaa46bodl6xsk25eous3qctb26aydifq7un2kaq

real    1m31.576s
user    0m0.970s
sys     0m0.700s
root@sm-mgmt01:~# time tahoe put --mutable 500MB.zip 
200 OK
URI:SSK:ibqlpkk4xc5kpeosjlzxc3orsy:6zmdo5bb7mngxzjzo4zg33malvk42ycs5tuu2yznyjmalsj4syxa

real    2m37.083s
user    0m1.300s
sys     0m1.210s

[zooko]

Okay, I think this issue is fixed and the performance problems observed by ChosenOne probably have to do with using up too much RAM and getting into swap. ChosenOne: if you want to investigate and confirm or deny that hypothesis, that would be great. For now, closing this ticket as "fixed".

[zooko]

This was fixed in foolscap v0.5.1. I think we should bump the required version number from >= 0.4.1 to >= 0.5.1 in our _auto_dep.py. I don't imagine it will cause a lot of problems for people to need to upgrade to foolscap 0.5.1.

See also #541 (foolscap 'reference'-token bug workaround in mutable publish) -- we could remove the workaround in mutable publish once we've raised the required version number of foolscap.

[davidsarah]

Replying to zooko:

This was fixed in foolscap v0.5.1. I think we should bump the required version number from >= 0.4.1 to >= 0.5.1 in our _auto_dep.py. I don't imagine it will cause a lot of problems for people to need to upgrade to foolscap 0.5.1.

See also #541 (foolscap 'reference'-token bug workaround in mutable publish) -- we could remove the workaround in mutable publish once we've raised the required version number of foolscap.

According to ​http://foolscap.lothar.com/trac/ticket/104 , that bug was fixed in foolscap 0.4.0, which was required by Tahoe r3870 (2009-05-22). The next Tahoe release after that was v1.5.0 (2009-08-02). So we cannot remove the workaround until we no longer care about interoperating with servers prior to v1.5.0.

[zooko]

So just to summarize, the performance issue in foolscap is fixed, and the only question is whether to raise the requirement that Tahoe-LAFS imposes on which version of foolscap it needs.

[zooko]

I think we should raise the requirement on the version of foolscap so that Tahoe-LAFS users will not encounter this performance issue.

[zooko]

fixed by 5377d99cf38568d2