Performance regression for large values of K

[francois]

On the grid described ​here, the download time of a 10 MB file encoded with 20-of-60 is roughly doubled on a client running v1.8.1 than the same client running v.1.7.1.

allmydata-tahoe: 1.8.0-r4843

$ for i in $(seq 1 5); do /usr/bin/time -f "%e" tahoe get tahoe:10MB.bin.20-of-60 > /dev/null; done
40.16
44.87
43.57
51.88
58.40

allmydata-tahoe: 1.8.0c4-r4743

$ for i in $(seq 1 5); do /usr/bin/time -f "%e" tahoe get tahoe:10MB.bin.20-of-60 > /dev/null; done
38.29
39.58
55.32
41.03
45.36

allmydata-tahoe: 1.7.0-r4579

$ for i in $(seq 1 5); do /usr/bin/time -f "%e" tahoe get tahoe:10MB.bin.20-of-60 > /dev/null; done
15.43
21.87
26.77
25.60
20.71
repairer:~# 

[francois]

Here are both a PDF and an HTML version of the download status timeline of a 10 MB 20-of-60 encoded file download.

[francois]

Zooko mentioned that this bug might be a duplicate of #1180, so I modified the default number of in-flight DYHB request from 10 to 60. The result is a slight improvement in download time (about 1 second), so there's probably something else.

diff -rN old-tahoe-lafs/src/allmydata/immutable/downloader/finder.py new-tahoe-lafs/src/allmydata/immutable/downloader/finder.py
31c31
<                  logparent=None, max_outstanding_requests=10):
---
>                  logparent=None, max_outstanding_requests=60):

[francois]

This performance regression most probably appeared when the new-downloader landed in v1.8.0, see ticket #798. In my opinion, this issue shouldn't block release v1.8.1 right now but might possibly be addressed in a potential v1.8.2.

[warner]

In my opinion, this issue shouldn't block release v1.8.1 right now but might possibly be addressed in a potential v1.8.2.

Works for me. I ought to get some analysis time this upcoming (US holiday) weekend. My plan is to point the JS-based visualizer at it, and measure the time spent recomputing the desire/satisfaction bitmaps/Spans, since I've observed a surprising amount of time spent in that portion of the code (it's being called much too frequently, and I think it gets worse with large k).

[francois]

Replying to warner:

Works for me. I ought to get some analysis time this upcoming (US holiday) weekend. My plan is to point the JS-based visualizer at it, and measure the time spent recomputing the desire/satisfaction bitmaps/Spans, since I've observed a surprising amount of time spent in that portion of the code (it's being called much too frequently, and I think it gets worse with large k).

Great! I also hope to find some free time this weekend to work on that.

An quick analysis of Tahoe-LAFS - File Download Status.html​ shows that some segments requests were delayed because a single share request was taking too long. The average time for a share request during this download was about 100 ms, but it raised to a bit more than one second in a few cases such as this one.

qnsglseg	21	[6590:+6554]	+0.896405s	+1.985190s	6554	1.09s

I think that those share requests taking too long are probably due to the overall load on the grid and are probably difficult to avoid. However, it seems that each segment request is currently serialized (#1187). That means that a single slow share request will prevent the next segment download to start which will slowdown the overall file download. The bigger k is, the more shares the client will have to download and therefore the probability of slow share requests will increase.

Now, I don't really understand if and why this issue was not present in v1.7.1 because it seems that segement pipelining wasn't already implemented in the previous downloader.

[zooko]

Replying to francois:

An quick analysis of Tahoe-LAFS - File Download Status.html​ shows that some segments requests were delayed because a single share request was taking too long. The average time for a share request during this download was about 100 ms, but it raised to a bit more than one second in a few cases such as this one.

qnsglseg	21	[6590:+6554]	+0.896405s	+1.985190s	6554	1.09s

I think that those share requests taking too long are probably due to the overall load on the grid and are probably difficult to avoid.

I don't understand why a few of the share requests would take ten times as long as normal. Is the delay on the client, the server, or the network? Brian hypothesized that it had something to do with how the spans data structure gets used more when K is higher. Maybe running the client (gateway, downloader) under a Python profiler would give us a clue. (David-Sarah has pointed out that tahoe has support for that! comment:2:ticket:1267 .)

You could also try running oprofile to get information about what the CPU is doing at the native-code (x86/amd64) level. You could try either or both of these on the client and on the servers.

But, if the slowdown is due to waiting for disk or for network rather than due to spinning the CPU, these tools won't show it. Also if you get unlucky and don't encounter any of these 1-second-long pauses while you are profiling or if you encounter so few of them that the functions responsible for the delay don't accumulate a lot of CPU time over the whole profiling run then they could evade detection.

On the gripping hand, a good profiling result is almost always interesting. It either tells us about some functions that are wasting CPU cycles or it tells us that there are no functions that waste CPU cycles (under this load). So I would encourage you to try it.

Now, I don't really understand if and why this issue was not present in v1.7.1 because it seems that segement pipelining wasn't already implemented in the previous downloader.

Yes this is definitely one of the mysteries. What changed between v1.7.1 and v1.8? The addition of the spans data structure is one thing...

Oh! This would probably help:

​http://tahoe-lafs.org/trac/tahoe-lafs/attachment/ticket/1170/debuggery-trace-spans.dpatch.txt

That patch adds logging of every time Share._received gets touched, which is one of the most commonly-used spans objects.

This tool reads logs like that and benchmarks how fast a given spans implementation can handle such usage: trunk/misc/simulators/bench_spans.py​

Applying that patch to your downloader could tell us whether the Share._received object is getting used a lot, and then running bench_spans.py on the resulting log could tell us whether the current implementation of spans has some inefficient algorithm.

[francois]

As proposed I ran the client under the cProfile Python profiler by directly calling twistd with the following command because the -n is necessary to have profiler output written into a file.

twistd -y tahoe-client.tac --profiler=cProfile --savestats --profile=/tmp/tahoe.profile --debug -n

You'll find the profile generated​ by downloading a 20-of-60 10 MB file and then stopping the client. I'll hopefully address the remaining points tomorrow.

[warner]

zooko said:

I don't understand why a few of the share requests would take ten times as long as normal. Is the delay on the client, the server, or the network? Brian hypothesized that it had something to do with how the spans data structure gets used more when K is higher.

Actually my hypothesis is that the time spent between receipt of the block request and the transmission of the next block request will be higher for larger values of k. This time would not be "charged" against the individual server: it occurs after the clock has been stopped.

​This picture (and the other pictures on #1170) show part of this: it's the delay between the receipt of the last block() request (e.g. at 2.60s) and the transmission of the next request (at around 2.67s).

​Zooming in shows what's happening in that gap. If you could read the "desire" words on the small boxes (which of course is easier when you can interactively zoom the chart, rather than looking at a screenshot), you could see that recomputing the desire/satified bitmaps is being done three times, but the second and third passes are redundant (no new responses have arrived, so the computed bitmap is exactly the same, so that's just wasted time).

If I remember right, the downloader was doing one redundant pass for each hash received, and we fetch more hashes for some segments than others (peaking for NUMSEGS/2), resulting in an uneven distribution of extra delays. My comments in ​http://tahoe-lafs.org/trac/tahoe-lafs/ticket/1170#comment:92 suggest that it's not enough to explain the delays seen here (8% on a 12MB file on a one-CPU testnet), but it *would* be worse with more segments.

[zooko]

You'll find the profile generated​ by downloading a 20-of-60 10 MB file and then stopping the client. I'll hopefully address the remaining points tomorrow.

Okay I did a quick dump of the stats from tahoe.profile​, first sorted by total time spent in each function excluding time spent waiting for functions that it called to return ("tottime"), and then sorted by total time spent in each function including time spent waiting for functions it called to return ("cumtime").

>>> p.sort_stats('time').print_stats(8)
Tue Nov 23 14:36:37 2010    tahoe.profile

         21516265 function calls (21475767 primitive calls) in 240.371 CPU seconds

   Ordered by: internal time
   List reduced from 1491 to 8 due to restriction <8>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1406  147.383    0.105  147.492    0.105 {select.select}
  1370101   21.221    0.000   21.221    0.000 {posix.stat}
    50882   14.011    0.000   51.913    0.001 traceback.py:273(extract_stack)
  1370097    7.485    0.000   28.704    0.000 linecache.py:43(checkcache)
    50882    7.292    0.000    8.031    0.000 traceback.py:27(format_list)
  1370097    3.531    0.000    7.492    0.000 linecache.py:13(getline)
     2031    2.392    0.001    2.392    0.001 {built-in method send}
  1370097    1.749    0.000    3.435    0.000 linecache.py:33(getlines)

         21516265 function calls (21475767 primitive calls) in 240.371 CPU seconds

   Ordered by: cumulative time
   List reduced from 1491 to 44 due to restriction <44>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  240.371  240.371 base.py:1046(run)
        1    0.025    0.025  240.361  240.361 base.py:1051(mainLoop)
     1406    0.062    0.000  190.230    0.135 selectreactor.py:93(doSelect)
     1406  147.383    0.105  147.492    0.105 {select.select}
    50882    1.038    0.000   61.047    0.001 traceback.py:264(format_stack)
    50882   14.011    0.000   51.913    0.001 traceback.py:273(extract_stack)
     1406    0.053    0.000   50.059    0.036 base.py:666(runUntilCurrent)
      874    0.054    0.000   49.797    0.057 eventual.py:18(_turn)
25381/20221    0.116    0.000   46.592    0.002 defer.py:233(callback)
25391/20231    0.392    0.000   46.453    0.002 defer.py:291(_startRunCallbacks)
     6377    0.277    0.000   45.856    0.007 share.py:188(loop)
     6377    0.180    0.000   44.419    0.007 share.py:239(_do_loop)
     4672    0.049    0.000   42.653    0.009 log.py:38(callWithLogger)
     4672    0.063    0.000   42.597    0.009 log.py:33(callWithContext)
     4672    0.035    0.000   42.467    0.009 context.py:58(callWithContext)
     4672    0.053    0.000   42.428    0.009 context.py:32(callWithContext)
     4672    0.048    0.000   42.358    0.009 selectreactor.py:144(_doReadOrWrite)
5200/5143    0.101    0.000   39.445    0.008 defer.py:84(maybeDeferred)
     2212    0.043    0.000   39.311    0.018 tcp.py:345(doRead)
     2136    0.038    0.000   38.325    0.018 tcp.py:116(doRead)
     6377    0.405    0.000   37.374    0.006 share.py:709(_send_requests)
     1893    0.087    0.000   37.301    0.020 banana.py:633(dataReceived)
     4999    0.035    0.000   37.245    0.007 referenceable.py:406(callRemote)
     1893    1.008    0.001   37.210    0.020 banana.py:701(handleData)
     4999    0.273    0.000   37.103    0.007 referenceable.py:418(_callRemote)
     4777    0.029    0.000   34.931    0.007 share.py:741(_send_request)
    25491    0.333    0.000   31.085    0.001 defer.py:166(__init__)
50890/30329    0.944    0.000   30.678    0.001 defer.py:314(_runCallbacks)
     5000    0.100    0.000   30.631    0.006 banana.py:183(send)
     5000    0.120    0.000   30.525    0.006 root.py:92(send)
  1370097    7.485    0.000   28.704    0.000 linecache.py:43(checkcache)
    10106    0.082    0.000   24.185    0.002 defer.py:30(succeed)
     5582    0.183    0.000   22.692    0.004 banana.py:1049(handleClose)
     4999    0.110    0.000   21.742    0.004 call.py:652(receiveClose)
  1370101   21.221    0.000   21.221    0.000 {posix.stat}
     5072    0.829    0.000   19.518    0.004 banana.py:191(produce)
    10072    0.118    0.000   13.274    0.001 root.py:72(next)
    16851    0.085    0.000   12.370    0.001 banana.py:1035(handleToken)
     9998    0.095    0.000   12.250    0.001 call.py:628(receiveChild)
50868/44994    0.268    0.000   11.336    0.000 defer.py:172(addCallbacks)
     4999    0.026    0.000    9.349    0.002 call.py:673(_done)
     4999    0.054    0.000    9.323    0.002 call.py:55(complete)
    50882    7.292    0.000    8.031    0.000 traceback.py:27(format_list)
  1370097    3.531    0.000    7.492    0.000 linecache.py:13(getline)

Here are my comments/questions about this:

• Only the first few rows of the tottime list are at all significant. The total CPU time was 240 seconds, so the 3rd row -- extract_stack -- used about 5% of the CPU time and the 4th row -- checkcache -- used about 3%.
• Why is extract_stack getting caled 50,882 times!? Here are all of the callers which called extract_stack in this run:

  >>> p.print_callers('extract_stack')
     Ordered by: cumulative time
     List reduced from 1491 to 1 due to restriction <'extract_stack'>
  
  Function                         was called by...
                                       ncalls  tottime  cumtime
  traceback.py:273(extract_stack)  <-   50882   14.011   51.913  traceback.py:264(format_stack)
  
  
  <pstats.Stats instance at 0x1004e0950>
  >>> p.print_callers('format_stack')
     Ordered by: cumulative time
     List reduced from 1491 to 1 due to restriction <'format_stack'>
  
  Function                        was called by...
                                      ncalls  tottime  cumtime
  traceback.py:264(format_stack)  <-   25491    0.591   30.752  defer.py:166(__init__)
                                       25391    0.447   30.295  defer.py:291(_startRunCallbacks)
  
  
  <pstats.Stats instance at 0x1004e0950>
  

Ah, this indicates that twisted.internet.defer.debug=True. Okay. I wonder how it got turned on?

• Okay, and why is posix.stat invoked more than a million times? Ah, print_callers() tells me that posix.stat is getting called by checkcache which is getting called by extract_stack. So all told, around 23% of the CPU time (as measured in "tottime" terms instead of "cumtime" terms) was spent in doing the debugging stuff due to defer.debug=True. This makes me wonder what the overall throughput would be if defer.debug were turned off.

Next, I turn my attention to the "cumtime" results.

• Measured this way, the CPU time spent in the defer.debug stuff was 25% of all CPU time. (And this is is a better measure of this than the tottime result is.)
• share.py:188(loop)​ was called 6377 times and took up a total of 19% of all CPU time. This might be a smoking gun showing that Brian's analysis in #1268 is correct and explains the slowdown that this ticket (#1264) is about.
• share.py:709(_send_requests)​, called 6377 times, total of 37.374 seconds (15.5% of the total). 6 milliseconds per call. Is this more evidence in favor of the #1268 theory? What functions does _send_requests call, and how long do they take?

  >>> p.strip_dirs().print_callees('_send_requests')
     Random listing order was used
     List reduced from 1491 to 1 due to restriction <'_send_requests'>
  
  Function                      called...
                                    ncalls  tottime  cumtime
  share.py:709(_send_requests)  ->    9554    0.024    0.067  defer.py:189(addCallback)
                                      9554    0.022    0.064  defer.py:197(addErrback)
                                     11154    0.207    0.652  log.py:144(msg)
                                      4777    0.029   34.931  share.py:741(_send_request)
                                      4777    0.083    0.210  spans.py:46(add)
                                     19131    0.132    0.196  spans.py:142(dump)
                                     11154    0.014    0.014  spans.py:152(__iter__)
                                     12754    0.060    0.605  spans.py:170(__sub__)
                                      6377    0.021    0.069  spans.py:256(get_spans)
                                      4777    0.049    0.066  status.py:97(add_request_sent)
                                     11154    0.034    0.093  {repr}
                                      4777    0.002    0.002  {time.time}
  

Huh-oh, I think this shows that cProfile is giving us bad data! The cumulative time spent in _send_request, including waiting for its callees to return, was 34.931s, and the total time spent in _send_request not waiting for its callees to return was 0.029s, which means that it was waiting for its callees to return for almost 35s. But, the total time spent in all of its callees adds up to about 2s seconds. That doesn't make sense! :-(

Well, it is obviously time for me to go to bed. Hopefully it will make more sense when I get back to this next weekend.

One last comment: it is surprising how much time is spent in banana.py and its children! (That's the code in foolscap to serialize/deserialize things.)

[fijal]

Hey.

I think this might be the case with recursive call - you end up having a cycle that is not correctly reported here (it's kind of hard and you need cycle detection). So you end up calling your children which are yourself. I would suggest using lsprofcalltree (a copy is here ​http://codespeak.net/svn/pypy/trunk/pypy/tool/lsprofcalltree.py) and kcachegrind for display (it's so much easier and contains cycle detection). I know installing KDE on mac is a pain but there is always virtualization technology and whatnot.

Cheers, fijal

[warner]

zooko says:

So all told, around 23% of the CPU time (as measured in "tottime" terms instead of "cumtime" terms) was spent in doing the debugging stuff due to defer.debug=True. This makes me wonder what the overall throughput would be if defer.debug were turned off.

Whoa, yeah, defer.debug should definitely *not* be turned on. We've observed the unit test suite taking like 3x as long when it is. (last time, it was turned on by some accidentally left-in debugging code). What's going on? Francois: do you have any local patches which call twisted.internet.defer.setDebugging(True)? There's nothing in the current trunk which does that. If you run twistd with -d/--debug, it will turn on defer.setDebugging, but from the command line you ran it doesn't look like that's the case.

share.py:188(loop) was called 6377 times and took up a total of 19% of all CPU time. This might be a smoking gun showing that Brian's analysis in #1268 is correct and explains the slowdown that this ticket (#1264) is about.

share.py:709(_send_requests), called 6377 times, total of 37.374 seconds (15.5% of the total). 6 milliseconds per call.

Let's see, k=20, 10MB file, assuming default 128KiB segsize, that gives 77 segments, so a total of 144 nodes in the block hash merkle tree for each share. We fetch half of the leaves and all of the non-leaves, so about 115 nodes per share, and there are 20 shares, so about 2310 block hash nodes total. There are also 77 data blocks per share, so 1540 of those. We also fetch maybe a dozen other pieces (offset table, UEB, some portion of the share hash tree and ciphertext hash tree) for each share, so maybe an extra 240 fetches there. Eyeballing that is about 4090 fetches. So, it's within an order of magnitude of what I'd expect to see.

Each _send_requests call turns into one loop call, yes: that's the #1268 bug. When that gets fixed, we should see 6377 _send_requests but far fewer calls to loop, maybe 20*(77+2)=1580.

Re _send_request and recursion: careful, there are two similarly-named functions here. _send_requests() (plural) loops over _send_request() (singular). Does this resolve the confusion? _send_request() is just a single call to callRemote, and if we're spending a lot of time there, it means we're spending a lot of time in the Foolscap serialization code. Let's see, 4777 calls and 34.931s total, so 7.3ms per call.. that feels high. The arguments being serialized are really simple (two ints), but there are a lot of Deferreds involved, so if defer.setDebugging(True) is really turned on, I'm not as surprised.

We really need a new profiling run with defer.setDebugging turned off.

[francois]

Replying to warner:

Whoa, yeah, defer.debug should definitely *not* be turned on. We've observed the unit test suite taking like 3x as long when it is. (last time, it was turned on by some accidentally left-in debugging code). What's going on? Francois: do you have any local patches which call twisted.internet.defer.setDebugging(True)? There's nothing in the current trunk which does that. If you run twistd with -d/--debug, it will turn on defer.setDebugging, but from the command line you ran it doesn't look like that's the case.

Oh! Sorry, the previous profile was indeed generated by twistd --debug, my bad! Here's a new one.

[zooko]

Replying to francois:

Oh! Sorry, the previous profile was indeed generated by twistd --debug, my bad! Here's a new one.

Did this one take about half as much time to download the 10 MB file? Because profiler reports 130 seconds (which it incorrectly calls CPU seconds when it is really wall clock seconds) for this one, and it reported about 240 for the last one. Hey, in fact, does this mean that almost all of the reported performance regression is due to François accidentally turning on debug mode? :-)

In any case, here are the total and cumulative times, showing all the ones that took more than 1% of the total time:

         8948704 function calls (8908705 primitive calls) in 129.678 CPU seconds

   Ordered by: cumulative time
   List reduced from 1277 to 64 due to restriction <64>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  129.678  129.678 base.py:1046(run)
        1    0.032    0.032  129.678  129.678 base.py:1051(mainLoop)
     1705    0.065    0.000  110.454    0.065 selectreactor.py:93(doSelect)
     1705  101.247    0.059  101.373    0.059 {select.select}
     1705    0.049    0.000   19.137    0.011 base.py:666(runUntilCurrent)
     1173    0.055    0.000   18.963    0.016 eventual.py:18(_turn)
     6428    0.270    0.000   17.554    0.003 share.py:188(loop)
     6428    0.170    0.000   16.151    0.003 share.py:239(_do_loop)
     6428    0.357    0.000    9.349    0.001 share.py:709(_send_requests)
51318/30610    0.784    0.000    9.008    0.000 defer.py:314(_runCallbacks)
     4939    0.052    0.000    8.991    0.002 log.py:38(callWithLogger)
     4939    0.061    0.000    8.932    0.002 log.py:33(callWithContext)
     4939    0.033    0.000    8.804    0.002 context.py:58(callWithContext)
     4939    0.054    0.000    8.766    0.002 context.py:32(callWithContext)
     4939    0.047    0.000    8.695    0.002 selectreactor.py:144(_doReadOrWrite)
25616/20408    0.089    0.000    8.362    0.000 defer.py:233(callback)
25622/20414    0.105    0.000    8.247    0.000 defer.py:291(_startRunCallbacks)
5231/5177    0.043    0.000    7.703    0.001 defer.py:84(maybeDeferred)
     5049    0.030    0.000    7.472    0.001 referenceable.py:406(callRemote)
     5049    0.208    0.000    7.398    0.001 referenceable.py:418(_callRemote)
     4828    0.022    0.000    7.087    0.001 share.py:741(_send_request)
     2495    0.045    0.000    6.566    0.003 tcp.py:345(doRead)
     5050    0.032    0.000    6.500    0.001 banana.py:183(send)
     5050    0.087    0.000    6.468    0.001 root.py:92(send)
     2423    0.026    0.000    6.351    0.003 tcp.py:116(doRead)
     5121    0.787    0.000    6.090    0.001 banana.py:191(produce)
     1891    0.037    0.000    5.503    0.003 banana.py:633(dataReceived)
     1891    0.868    0.000    5.464    0.003 banana.py:701(handleData)
   155707    1.606    0.000    3.148    0.000 abstract.py:161(write)
     8028    0.144    0.000    3.058    0.000 share.py:268(_get_satisfaction)
    23231    0.338    0.000    3.057    0.000 hashtree.py:298(needed_hashes)
51317/45429    0.245    0.000    2.934    0.000 defer.py:172(addCallbacks)
     6428    0.239    0.000    2.831    0.000 share.py:560(_desire)
    23231    0.518    0.000    2.716    0.000 hashtree.py:128(needed_for)
     5629    0.105    0.000    2.706    0.000 banana.py:1049(handleClose)
    40405    0.343    0.000    2.609    0.000 banana.py:485(sendToken)
     5049    0.096    0.000    2.515    0.000 call.py:652(receiveClose)
    44426    0.900    0.000    2.475    0.000 log.py:144(msg)
    60873    0.329    0.000    2.220    0.000 banana.py:22(int2b128)
     2263    0.087    0.000    1.890    0.001 abstract.py:90(doWrite)
     5049    0.017    0.000    1.807    0.000 call.py:673(_done)
     5049    0.041    0.000    1.790    0.000 call.py:55(complete)
   150076    0.508    0.000    1.742    0.000 hashtree.py:118(sibling)
     2263    0.019    0.000    1.732    0.001 tcp.py:364(writeSomeData)
     2032    0.012    0.000    1.723    0.001 tcp.py:140(doWrite)
     2032    0.011    0.000    1.581    0.001 tcp.py:152(writeSomeData)
     2032    1.552    0.001    1.552    0.001 {built-in method send}
    61062    0.312    0.000    1.392    0.000 spans.py:25(__init__)
   155628    0.536    0.000    1.283    0.000 tcp.py:256(startWriting)
    44426    0.848    0.000    1.117    0.000 log.py:227(add_event)
    36748    0.421    0.000    1.091    0.000 spans.py:46(add)

         8948704 function calls (8908705 primitive calls) in 129.678 CPU seconds

   Ordered by: internal time
   List reduced from 1277 to 64 due to restriction <64>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
     1705  101.247    0.059  101.373    0.059 {select.select}
   155707    1.606    0.000    3.148    0.000 abstract.py:161(write)
     2032    1.552    0.001    1.552    0.001 {built-in method send}
    44426    0.900    0.000    2.475    0.000 log.py:144(msg)

We can see the share.py functions in the cumulative listing, showing that we spent 13.5% of the total time inside share.py's loop(), but other than that there aren't any suspicious CPU users. It seems to spend most of its time waiting for the network, which is as it should be.

[zooko]

Replying to zooko:

Did this one take about half as much time to download the 10 MB file? Because profiler reports 130 seconds (which it incorrectly calls CPU seconds when it is really wall clock seconds) for this one, and it reported about 240 for the last one. Hey, in fact, does this mean that almost all of the reported performance regression is due to François accidentally turning on debug mode? :-)

For the record, François assured me on IRC that this is not the case, that the regression from 1.7 to 1.8 is real regardless of debug mode being turned on. I guess the large difference in CPU seconds reported in the debug mode profiling vs. the no-debug-mode profiling doesn't indicate a proportionally large difference in real wall-clock time.

François: if you want to generate some fresh profiling results with your current setup and v1.7 vs. 1.8 that would be cool. We could compare the profiling results from the two versions.

In any case, here are the total and cumulative times, showing all the ones that took more than 1% of the total time:

   Ordered by: cumulative time
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000  129.678  129.678 base.py:1046(run)
        1    0.032    0.032  129.678  129.678 base.py:1051(mainLoop)
     1705    0.065    0.000  110.454    0.065 selectreactor.py:93(doSelect)
     1705  101.247    0.059  101.373    0.059 {select.select}
     1705    0.049    0.000   19.137    0.011 base.py:666(runUntilCurrent)
     1173    0.055    0.000   18.963    0.016 eventual.py:18(_turn)
     6428    0.270    0.000   17.554    0.003 share.py:188(loop)
     6428    0.170    0.000   16.151    0.003 share.py:239(_do_loop)
     6428    0.357    0.000    9.349    0.001 share.py:709(_send_requests)

We can see the share.py functions in the cumulative listing, showing that we spent 13.5% of the total time inside share.py's loop(), but other than that there aren't any suspicious CPU users. It seems to spend most of its time waiting for the network, which is as it should be.

Well, maybe the 13.5% time inside share.py's loop() causes the overall progress to slow down significantly, as François observed from the visualizations in comment:5 and as Brian potentially explained in comment:8.

[warner]

tools for doing comparative download performance tests

[warner]

measured download speed on WAN versus encoding (1MB file) tahoe-1.8.2

[warner]

measured download speed on WAN versus encoding (10MB file) tahoe-1.8.2

[warner]

measured download speed on WAN versus encoding (100MB file) tahoe-1.8.2

[warner]

raw data

[warner]

I just finshed doing the first batch of comparative performance tests on the Atlas Networks hardware, and uploaded my tools and the graphs. I'm calling this environment "atlasperf1". It consists of four machines (one client, the others are storage servers, two server nodes per machine) on fast local connections. The CPUs are dual-core Pentium4s at 3.00GHz, the average ping time is 420us. The client is running tahoe-1.8.2 (the servers are a mix of versions: 1.8.2, 1.7.1, 1.6.1).

I uploaded 1MB/10MB/100MB immutable files with various encodings (from 1-of-1 to 60-of-60, all with k=N). Then I ran a program to download random ones over and over. I graphed the k-vs-time curve for about 1700 trials.

The graph shows a nearly-perfect linear slowdown with increasing k. For a 100MB file, k=5 yields a 50s download, k=30 takes 250s, and k=60 takes about 500s. The same shape holds for 1MB and 10MB files too.

The next test is to try various segment sizes. I've got a few pet theories about the slowdown: the number of foolscap messages being sent, or the limited pipelining of small requests. Both would have a correlation with number of segments. For a fast network, our current one-segment pipeline isn't very big. And with high 'k', the amount of data we're getting from each block can get quite small (k=60 means each block is 128k/60=2.2k, which is scarcely a whole packet), so we've got a lot of tiny little requests flying around.

Possibly mitigations include:

• when segsize/k is small, accept the memory-footprint hit and use a deeper pipeline, to keep the pipes full
• implement a readv() method on the storage servers to reduce the foolscap overhead (if that's in fact an issue)
• advise larger segsize on fast networks

[zooko]

Brian: nice work! Now we're really getting somewhere. :-)

It would be cool to see the New Visualizer report for a k=5, 50s download and a k=50, 500s download. Did you capture those?

[zooko]

Brian pointed out to me, on the phone just now, that 1.8.2 doesn't have the New Visualizer in it. He's running the same experiment with trunk now, and will hopefully get New Visualizer reports from those.

[zooko]

On the topic of segment sizes, you might be interested in ​http://tahoe-lafs.org/trac/tahoe-lafs/ticket/1264 and the various other notes linked from ​http://tahoe-lafs.org/trac/tahoe-lafs/wiki/Performance .

[warner]

That last image shows a comparison of LAN download times for a 100MB file at various 'k' values (the graphs for 10MB and 1MB files have the same shape, but more variance). The faster blue samples are for 1.7.1, while the slower red samples are current trunk (probably around 8e69b94588c1c0e7). Both graphs are quite linear, but trunk (with the new downloader) is significantly slower than the old downloader in 1.7.1 across the board, probably about 3x.

Higher 'k' slows down the process too, more severely for the new downloader. For 1.7.1, k=60 is about 3x slower than k=15, and for trunk, the difference is about 3.8x .

I'm still suspecting the foolscap/message-handling overhead. I'd also like to find a way to get a speed-limited WAN-like pipe (simulated, for consistency across runs) and compute similar graphs in an environment where the network is the bottleneck. I believe the new-downloader is faster than the old code in the WAN (that's why I wrote it in the first place), but it looks like something about the complexity or small-reads makes the LAN case slower.

[warner]

comparison of 1.7.1 versus current trunk (probably about 8e69b94588c1c0e7) (better graph, more data)

[warner]

FYI, my full report on LAN performance is now on the wiki at Performance/Sep2011.

[warner]

I've opened some new tickets for some of the improvements we should experiment with, in decreasing order of bang-for-the-buck:

• #1545: add readv() to immutable storage API
• #1544: coordinate hash-chain requests between multiple Shares
• #1543: rearrange share format to make downloads more efficient