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

New issue

Open

opened 2011-07-31 00:45:21 +00:00 by T_X · 25 comments

T_X commented

2011-07-31 00:45:21 +00:00

Owner

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).

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).

tahoe-lafs added the

labels 2011-07-31 00:45:21 +00:00

tahoe-lafs added this to the undecided milestone 2011-07-31 00:45:21 +00:00

T_X commented

2011-07-31 00:48:58 +00:00

Author

Owner

Attachment tahoe-stats-0.log (50 bytes) added

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

**Attachment** tahoe-stats-0.log (50 bytes) added Log of Test 0: Download with no parallel upload or limitations

tahoe-stats-0.log

50 B

T_X commented

2011-07-31 00:49:53 +00:00

Author

Owner

Attachment tahoe-stats-1.log (50 bytes) added

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

**Attachment** tahoe-stats-1.log (50 bytes) added Log of Test 1: Parallel 'tahoe put', limited to 800kbit/s

tahoe-stats-1.log

50 B

T_X commented

2011-07-31 00:51:51 +00:00

Author

Owner

Attachment tahoe-stats-2.log (62 bytes) added

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

**Attachment** tahoe-stats-2.log (62 bytes) added Log of Test 2: Parallel 'tahoe put', tahoe-2 (gateway) limited to 800kbit/s

tahoe-stats-2.log

62 B

T_X commented

2011-07-31 00:52:41 +00:00

Author

Owner

Attachment tahoe-stats-3.log (59 bytes) added

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

**Attachment** tahoe-stats-3.log (59 bytes) added Log of Test 3: Parallel 'tahoe put', tahoe-1 (storage) limited to 800kbit/s

tahoe-stats-3.log

59 B

zooko commented

2011-07-31 19:33:32 +00:00

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 (attachment:tahoe-stats-2.log), it took this many seconds:

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]attachment:test-run.sh#L16, 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: 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` ([attachment:tahoe-stats-2.log](/tahoe-lafs/trac/attachments/000078ac-3cd9-6989-6e49-ce671e08bc27)), 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]attachment:test-run.sh#L16, 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!

zooko added

p/critical

and removed

p/major

labels 2011-07-31 19:33:32 +00:00

T_X commented

2011-07-31 20:38:11 +00:00

Author

Owner

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.

[to correct ms -> s]edited

Replying to [zooko](/tahoe-lafs/trac/issues/1456#issuecomment-385767): > 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](/tahoe-lafs/trac/issues/1456#issuecomment-385767): > 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](/tahoe-lafs/trac/issues/1456#issuecomment-385767): > 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. [to correct ms -> s]edited

zooko commented

2011-08-02 19:50:33 +00:00

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

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!)
Run wireshark and capture network-level information.
Turn on logging, as described in source:docs/logging.rst .

Thanks!

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 commented

2011-08-07 17:34:53 +00:00

Author

Owner

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.

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 commented

2011-08-07 19:04:56 +00:00

Author

Owner

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.

[Here](http://krtek.asta.uni-luebeck.de/~tux/tahoe-lafs/tahoe-prepare-test-2-dump.cap)'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 commented

2011-08-07 19:06:28 +00:00

Author

Owner

Attachment test-run.sh (3533 bytes) added

updated version of the test script

**Attachment** test-run.sh (3533 bytes) added updated version of the test script

test-run.sh

3.5 KiB

T_X commented

2011-08-07 19:10:26 +00:00

Author

Owner

Attachment tahoe-1.2.cfg (1140 bytes) added

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

**Attachment** tahoe-1.2.cfg (1140 bytes) added updating introducer port (to match the tcpdump, port 38940)

tahoe-1.2.cfg

1.1 KiB

T_X commented

2011-08-07 19:10:45 +00:00

Author

Owner

Attachment tahoe-1.cfg (1140 bytes) added

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

**Attachment** tahoe-1.cfg (1140 bytes) added updating introducer port (to match the tcpdump, port 38940)

tahoe-1.cfg

1.1 KiB

T_X commented

2011-08-07 19:11:03 +00:00

Author

Owner

Attachment tahoe-2.cfg (1139 bytes) added

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

**Attachment** tahoe-2.cfg (1139 bytes) added updating introducer port (to match the tcpdump, port 38940)

tahoe-2.cfg

1.1 KiB

zooko commented

2011-08-11 18:08:37 +00:00

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: 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 commented

2011-08-13 01:20:20 +00:00

Author

Owner

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

Current trunk (changeset:37cd111009d0b30e):

1.8.2:

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.

For test 2 I'm having the following results at the moment. Current trunk (changeset: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 commented

2011-08-17 07:25:40 +00:00

Author

Owner

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 commented

2011-08-17 16:35:18 +00:00

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.

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 commented

2011-08-18 06:32:59 +00:00

Author

Owner

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.

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](wiki/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 commented

2011-08-18 13:10:16 +00:00

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()]source:trunk/src/allmydata/util/time_format.py?annotate=blame&rev=4005#L11

See also the builtin facility to run the tahoe lafs node [under a profiler]source:trunk/src/allmydata/scripts/startstop_node.py?annotate=blame&rev=5074#L9.

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()]source:trunk/src/allmydata/util/time_format.py?annotate=blame&rev=4005#L11 See also the builtin facility to run the tahoe lafs node [under a profiler]source:trunk/src/allmydata/scripts/startstop_node.py?annotate=blame&rev=5074#L9.

T_X commented

2011-08-20 00:39:07 +00:00

Author

Owner

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.

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.

daira commented

2011-08-20 04:47:24 +00:00

Attachment tahoe-run-profile-option.darcs.patch (38675 bytes) added

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

**Attachment** tahoe-run-profile-option.darcs.patch (38675 bytes) added Add --profile option to 'tahoe run'. refs #1456

tahoe-run-profile-option.darcs.patch

38 KiB

daira commented

2011-08-20 04:50:18 +00:00

Replying to T_X:

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

attachment: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.

Replying to [T_X](/tahoe-lafs/trac/issues/1456#issuecomment-385780): > But for 'tahoe run' this profiler does not seem to be available. [attachment:tahoe-run-profile-option.darcs.patch](/tahoe-lafs/trac/attachments/000078ac-3cd9-6989-6e49-db26590a285d) 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 commented

2011-08-23 01:03:15 +00:00

Author

Owner

Attachment profiling_results.prof (98167 bytes) added

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

**Attachment** profiling_results.prof (98167 bytes) added Profiling results of node #2 (gateway/client, non-storage node)

profiling_results.prof

96 KiB

T_X commented

2011-08-23 01:08:00 +00:00

Author

Owner

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

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.

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](/tahoe-lafs/trac/attachments/000078ac-3cd9-6989-6e49-8fb96d9508fe) 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 commented

2011-08-23 03:26:23 +00:00

Author

Owner

$ 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 [3.7.3]sqlite,
setuptools: 0.6c16dev3

``` $ 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 [3.7.3]sqlite, setuptools: 0.6c16dev3 ```

zooko added

p/major

and removed

p/critical

labels 2012-03-29 16:11:45 +00:00