High latency for 'tahoe get' if 'tahoe put' in parallel

[T_X]

The two node setup, connected via a VPN and details of the setup can be found here: ​http://tahoe-lafs.org/pipermail/tahoe-dev/2011-July/006563.html.

Notable was, that if the bandwidth is saturated with another program ('netcat6' in this case), then there was no latency issue for 'tahoe get'. However, with running 'tahoe put' over the same gateway, then the latency went up to about 20 seconds.

I further tried to reproduce the issue within a single host in a KVM instance. One node was set up as a dedicated storage node, the other as a dedicated gateway with no storage. See tahoe.cfg attachments for the detailed node configurations.

The scripted test procedure can be found in the attached test-run.sh.

The results were the following:

Test 0: Download with no parallel upload or limitations: 1.6s average

Test 1: Parallel 'tahoe put', limited to 800kbit/s: 1.8s average

Test 2: Parallel 'tahoe put', tahoe-2 (gateway) limited to 800kbit/s: 87s average

Test 3: Parallel 'tahoe put', tahoe-1 (storage) limited to 800kbit/s: 12s average

For latency of each individual download, see log attachements.

Test 2's individual download times are also very noteworthy in particular. I'm not quite sure whether the 200s and 500s delays are another issue or whether it is an extreme manifestation of the same thing. When I'm repeating the test script, at least one of these highly delayed transfers occures in the beginning of test 2.

For Tests 0 and 1, the 1.6s seem to be a little high for a local transfer of this tiny file, but ok, that latency is just about acceptable.

My actual goal was to be able to run a common httpd and ftpd on top of sshfs using tahoe-lafs. However the results of most tests are too high and influence the usability badly. As there is no feedback for the final user's ftp and http client during the delays, Users might for one thing claim that the service is slow, might abort downloads or applications would abort on their own anyway (with the default settings wget times out after 30s for instance).

During the tests, especially during the downloads that took more than 200s, I didn't notice any cpu usage spikes. I hope that with trickle the limited bandwidth capabilities of the internet uplink as it was the case in the first tests over the VPN could somehow be simulated by that, hopefully with the similar issues in both test setups having the same cause(s).

[T_X]

Log of Test 0: Download with no parallel upload or limitations

[T_X]

Log of Test 1: Parallel 'tahoe put', limited to 800kbit/s

[T_X]

Log of Test 2: Parallel 'tahoe put', tahoe-2 (gateway) limited to 800kbit/s

[T_X]

Log of Test 3: Parallel 'tahoe put', tahoe-1 (storage) limited to 800kbit/s

[zooko]

T_X: thank you for the bug report. It sounds like it might be a serious problem in Tahoe-LAFS. I'm glad you've taken the effort to record detailed measurements and include notes about how you tries to make a minimal, reproducible case. I especially appreciate that you included your test script—very good!

However, I'm still confused and need more help from you to understand what's going on. Could you summarize in one paragraph of English -- like not more than 3 or 4 sentences what is wrong and how you know it is happening?

You're observing dramatically high latency on tahoe get in some cases. In fact, in 10 runs of tahoe get (tahoe-stats-2.log​), it took this many seconds:

1	15.38
2	213.31
3	564.83
4	11.87
5	11.99
6	11.99
7	12.56
8	12.11
9	12.50
10	12.83

The fact that it took 560 seconds to do a tahoe get (after which it completed successfully instead of erroring out?) is definitely an indication of something very wrong. I'm still hoping it turns out to be something wrong in your test rig or scripts rather than in Tahoe-LAFS, but we'll see. :-)

So, that's a question. How do we know that the runs that took an order of magnitude longer completed successfully? As far as I can tell from a quick scan of your script​, it isn't checking the return value or inspecting the resulting downloaded file to be sure it worked.

(Note this would still be a major problem in Tahoe-LAFS if it waited 560 seconds and failed as if it waited 560 seconds and succeeded, but it would help to understand which is happening).

Thanks!

[T_X]

Replying to zooko:

However, I'm still confused and need more help from you to understand what's going on. Could you summarize in one paragraph of English -- like not more than 3 or 4 sentences what is wrong and how you know it is happening?

The issue is that when doing a 'tahoe put' in the background (which is not limited in throughput itself) that a parallel 'tahoe get' seems to be delayed unreasonably long (and I'm considering the 20s delay in the VPN setup as well as the 10s in the VM setup as unreasonable, badly influencing the end user experience). It seems like a tahoe gateway is prefering the 'tahoe put' to the 'tahoe get' - or at least not serving the 'tahoe get' as timely as it should - the 'tahoe get' should always get a response at about the same time as it gets without the parallel 'tahoe put'. I know that this is happening due to the long time the 'tahoe get' needs as seen in test 2 and test 3 as well as in the the vpn setup stated on the mailing list and even when 'tahoe put' saturates the available capacity, it shouldn't take that long for the 19 Bytes to finish downloading.

Replying to zooko:

The fact that it took 560 seconds to do a tahoe get (after which it completed successfully instead of erroring out?) is definitely an indication of something very wrong. I'm still hoping it turns out to be something wrong in your test rig or scripts rather than in Tahoe-LAFS, but we'll see. :-)

Actually, the >500s delay I'm having in test 2 was something I didn't expect when setting up this VM configuration as I didn't see that in the VPN test before. I don't know if this issue is related or having a different cause than the 10 or 20s delays. However this delay is very reproducible and always happens during the beginning of test 2, so I think it is an issue within tahoe-lafs.

Replying to zooko:

As far as I can tell from a quick scan of your script Download, it isn't checking the return value or inspecting the resulting downloaded file to be sure it worked.

Hmm, true, but at least 'tahoe get' didn't complain and gave me ten times "tahoe:tahoe-file2download retrieved and written to /tmp/tahoe-file2download" (still have the log in gnu screen session here and just checked). Otherwise it'd be another issue with tahoe not giving an error message - but, sure, I can add a 'rm' and then a check after the 'tahoe get' and run the tests again.

[edited to correct ms -> s]

[zooko]

Can you capture more information from one of those runs that takes a long time, like > 500s? Here are ways to extract more information:

1. Get the "download timings" results from the "Recent Uploads and Downlaods" page. (I know you said on IRC you had a problem doing this, but hopefully it will work this time. Also: open a bug report!)
2. Run wireshark and capture network-level information.
3. Turn on logging, as described in source:docs/logging.rst​ .

Thanks!

[T_X]

Okay, now with having figured out the cause of #1462, I tried test 2 and had a look at the status page again. And the "download timings" are actually fine, I think:

    Started: 17:49:57 07-Aug-2011 (1312735797.17)
    Storage Index: 3pysvkzdgfswxkpkfyunwzblim
    Helper?: No
    Total Size: 95
    Progress: 100.0%
    Status: idle
    timeline

DYHB Requests:
serverid	sent	received	shnums	RTT
sbw63iqt	+0.001030s	+0.090083s	0,1,2,3,4,5,6,7,8,9	89ms

Read Events:
range	start	finish	got	time	decrypttime	pausedtime	speed
[0:+95]	+0.000000s	+0.149550s	95	150ms	11us	0us	635Bps

Segment Events:
segnum	start	active	finish	range	decodetime	segtime	speed
seg0	+0.000396s	+0.000461s	+0.148877s	[0:+95]	32us	148ms	640Bps

Requests:
serverid	shnum	range	txtime	rxtime	received	RTT
sbw63iqt	0	[0:+2445]	+0.120100s	+0.124593s	1473	4.5ms

And actually all other timings on this web status page seem fine too, nothing that is remotely as high as the 500s+.

Instead I noticed that the first mapupdate takes a very, very long time:

• 'tahoe get' started at Sun Aug 7 17:36:55 BST 2011

• Output of web page:

  Recent Operations:
  Started 	Type 	Storage Index 	Helper? 	Total Size 	Progress 	Status
  17:50:15 07-Aug-2011 	publish 	zb24cwlnpwynz7dtqszava76cm 	No 	790B 	100.0% 	Finished
  17:50:15 07-Aug-2011 	retrieve 	zb24cwlnpwynz7dtqszava76cm 	No 	790B 	100.0% 	Finished
  17:50:15 07-Aug-2011 	mapupdate MODE_WRITE 	zb24cwlnpwynz7dtqszava76cm 	No 	-NA- 	100.0% 	Finished
  17:49:57 07-Aug-2011 	download 	3pysvkzdgfswxkpkfyunwzblim 	No 	95B 	100.0% 	idle
  17:49:57 07-Aug-2011 	retrieve 	zb24cwlnpwynz7dtqszava76cm 	No 	790B 	100.0% 	Finished
  17:49:56 07-Aug-2011 	mapupdate MODE_READ 	zb24cwlnpwynz7dtqszava76cm 	No 	-NA- 	100.0% 	Finished
  17:49:56 07-Aug-2011 	retrieve 	zb24cwlnpwynz7dtqszava76cm 	No 	790B 	100.0% 	Finished
  17:49:56 07-Aug-2011 	mapupdate MODE_READ 	zb24cwlnpwynz7dtqszava76cm 	No 	-NA- 	100.0% 	Finished
  

• 'tahoe get' finished 782.01s after the start time.

I'll make a tcpdump in a minute.

[T_X]

​Here's a 100MB tcpdump capture. It includes the 'prepare' and the 'test2' part of the test script, as well as some communication with the web interface on port 3457. Interestingly, it seems that the web interface is also totally unresponsive during 'test2'.

• The 'tahoe get' started at 18:49:58.

• The web interface output is:

  Recent Operations:
  Started 	Type 	Storage Index 	Helper? 	Total Size 	Progress 	Status
  19:03:29 07-Aug-2011 	publish 	zb24cwlnpwynz7dtqszava76cm 	No 	791B 	100.0% 	Finished
  19:03:29 07-Aug-2011 	retrieve 	zb24cwlnpwynz7dtqszava76cm 	No 	791B 	100.0% 	Finished
  19:03:29 07-Aug-2011 	mapupdate MODE_WRITE 	zb24cwlnpwynz7dtqszava76cm 	No 	-NA- 	100.0% 	Finished
  19:03:13 07-Aug-2011 	download 	3pysvkzdgfswxkpkfyunwzblim 	No 	95B 	100.0% 	idle
  19:03:13 07-Aug-2011 	retrieve 	zb24cwlnpwynz7dtqszava76cm 	No 	791B 	100.0% 	Finished
  19:03:12 07-Aug-2011 	mapupdate MODE_READ 	zb24cwlnpwynz7dtqszava76cm 	No 	-NA- 	100.0% 	Finished
  19:03:12 07-Aug-2011 	retrieve 	zb24cwlnpwynz7dtqszava76cm 	No 	791B 	100.0% 	Finished
  19:03:12 07-Aug-2011 	mapupdate MODE_READ 	zb24cwlnpwynz7dtqszava76cm 	No 	-NA- 	100.0% 	Finished
  

• 'tahoe get' finished 795.44 after the start time.

[T_X]

updated version of the test script

[T_X]

updating introducer port (to match the tcpdump, port 38940)

[T_X]

updating introducer port (to match the tcpdump, port 38940)

[T_X]

updating introducer port (to match the tcpdump, port 38940)

[zooko]

T_X: what versions of tahoe did you use? If you could try comparing v1.8.2 with today's trunk, that might be informative. My guess is the two shouldn't differ in this behavior, but if they do differ then that might be a good clue.

You can get trunk with:

darcs get --lazy http://tahoe-lafs.org/source/darcs/tahoe-lafs/trunk

[T_X]

For test 2 I'm having the following results at the moment.

Current trunk (37cd111009d0b30e):

792.81
3.90
3.89
3.88
3.77
3.81
3.79
3.80
3.83
3.80

1.8.2:

794.95
4.03
4.10
4.05
4.06
4.05
3.97
4.03
4.03
4.01

So the very long delay in the beginning seems to be present in both versions. The common latency seems to be slightly lower though.

But looks interesting, that it usually seems to be in the range of 790 and 795 seconds, as if some specific thing needed to time out first.

[T_X]

Don't know if that helps in anyway, but it's with some 'print's I could narrow it down to c.getresponse in common_http.py's do_http, called by tahoe_get's get. The getresponse takes these 700+ seconds to return.

[warner]

Are the GET and the PUT referencing the same tahoe-side directory? I wonder if the basic locking we do around the directory's mutable-file objects (to prevent e.g. two simultaneous writes from the same gateway) is causing a PUT to block a GET.

There are a couple of convenience methods on dirnodes: things like "add a new child", or "get a child by a specific name". The add-child method is really a wrapper around two operations: upload-file, then attach-child, and only the latter really needs the lock.

My hypothesis is that PUT is using a convenience method which locks the dirnode during the upload-file phase (which takes a long time), and then the GET tries to do a list-children operation (to find out the immutable file that should be downloaded), which blocks until the add-child method has finished.

If we observed the CHK download to not start until after the PUT's directory-modification completed (using the "recent uploads and downloads" page, or maybe flogtool tail), that'd be supporting evidence.

Some code notes:

• src/allmydata/web/filenode.py (ReplaceMeMixin.replace_me_with_a_child) calls self.parentnode.add_file
• src/allmydata/dirnode.py (DirectoryNode.add_file) calls upload(), then self._create_and_validate_node, then self.set_node

Hrm, maybe not: the locks are all in the mutable-file object, not the dirnode, so the lock shouldn't be claimed until after the upload is completely finished. Anyways, maybe there's some other bug in this direction.. worth considering.

[T_X]

Short update: The cause of the delay has to be even before twisted/web/http.py's HTTPChannel's lineReceived. First added a 'print' at the beginning of tahoe-lafs's web/filenode.py's FileNodeHandler?'s render_GET, but both the 'print' in tahoe-lafs and in twisted still suffer from the long delay. The cause has to be somewhere even earlier.

Reducing pipeline_size in immutable/layout.py to 1 did not help either.

[zooko]

Hm, the line that you printed could itself be buffered and therefore not appear until sometime after the "print" statement was executed. Maybe throw in a timestamp to be sure about that.

time_format.iso_utc()​

See also the builtin facility to run the tahoe lafs node under a profiler.

[T_X]

I'm already using statements like

print "lineReceived %s" % (time.asctime( time.localtime(time.time()) ),)

and this printed timestamp is usually already too late, that's why I guess the issue has to be before the lineReceived call.

Hmm, I'm usually running 'tahoe run' instead of 'tahoe start' for the 2nd node, the gateway node doing the put and get, because trickle does not seem to work for 'tahoe start'. But for 'tahoe run' this profiler does not seem to be available.

Therefore I started to do my own, manual profiling... Basically I had a look at a call trace of lineReceived and tried surrounding various function calls in there with print's and timestamps. However, I couldn't find a function consuming this awful lot of time yet. twisted's tcp.py's Connection's doRead never needs more than a second.

[davidsarah]

Add --profile option to 'tahoe run'. refs #1456

[davidsarah]

Replying to T_X:

But for 'tahoe run' this profiler does not seem to be available.

tahoe-run-profile-option.darcs.patch​ should add a --profile option to tahoe run. If the command fails with no output, look at NODEDIR/logs/tahoesvc.log. If it works, the output will be in NODEDIR/profiling_results.prof. You may have to sudo apt-get install python-profiler.

[T_X]

Profiling results of node #2 (gateway/client, non-storage node)

[T_X]

Results of test 2, using tahoe-lafs trunk r5166:

381.87
14.72
12.54
13.80
12.17
12.21
13.35
11.99
12.89
13.57

See attachment​ for the profiling results of the gateway node. (you don't need any profiling results of node 1, the dedicated storage node, do you?)

EDIT: This run was done with a bandwidth limited to 200KB/s up+down instead of 100, which reduces the delay proportionally.

[T_X]

$ bin/tahoe --version
allmydata-tahoe: 1.8.2-r5151,
foolscap: 0.6.1,
pycryptopp: 0.5.25-r761,
zfec: 1.4.10,
Twisted: 10.2.0,
Nevow: 0.10.0,
zope.interface: unknown,
python: 2.6.6,
platform: Linux-debian_6.0.2-i686-32bit_ELF,
pyOpenSSL: 0.12,
simplejson: 2.1.6,
pycrypto: 2.3,
pyasn1: unknown,
mock: 0.8.0beta3,
sqlite3: 2.4.1 [sqlite 3.7.3],
setuptools: 0.6c16dev3