[Bamboo-Users] long latency (>5000ms) for BetterGetPutTest

Thu Nov 1 23:59:38 UTC 2007

Sean,

I tried the bamboo march 2006 code (latest release), started 2 dht nodes @ localhost, one "BetterGetPutTest" client node @localhost too.

I see occasional long latency such as 5004 ms for get (for a real key).

All nodes are up and looks fine. I can reproduce the long latency get within 1 min of the test.

For the same (real) key, most of the gets has short latency, but a few with long latency.

After digging thru logs, I found the long latency happens in Dht.java between:

"local read done" and "got new recur get resp"

The condition is:

if a new "get req" comes in between the above two:

bamboo at haijun-linux:/tmp$ grep 4117322052515304435 experiment-12141-172.22.34.148-3630.log

2007-11-01 12:49:45,072 INFO  bamboo.dht.Gateway: get req client=127.0.0.1:45497
 client_library="bamboo.dht.GatewayClient $Revision: 1.16 $" application="bamboo
.dht.BetterPutGetTest $Revision: 1.4 $" xact_id=0xe3379169 key=0x914f884b maxval
s=1744895999 placemark=(NONE)
2007-11-01 12:49:45,072 DEBUG bamboo.dht.Dht: got (Dht.GetReq key=914f884b maxva
ls=1744895999 all=true placemark=null)
2007-11-01 12:49:45,072 INFO  bamboo.dht.Dht: upcall for get req key=0x914f884b return addr=172.22.34.148:3630 seq=4117322052515304435 reached replica, new recur style, replicas=[172.22.34.148:3633, 172.22.34.148:3630], synced=[172.22.34.148:3633]
...

2007-11-01 12:49:45,074 INFO  bamboo.dht.Dht: local read done for new style recur get req seq=4117322052515304435
2007-11-01 12:49:45,112 INFO  bamboo.dht.Gateway: get req client=127.0.0.1:45497
 client_library="bamboo.dht.GatewayClient $Revision: 1.16 $" application="bamboo
.dht.BetterPutGetTest $Revision: 1.4 $" xact_id=0xe337916a key=0xba12b9bb maxval
s=671154175 placemark=(NONE)
2007-11-01 12:49:45,112 DEBUG bamboo.dht.Dht: got (Dht.GetReq key=ba12b9bb maxva
ls=671154175 all=true placemark=null)
2007-11-01 12:49:45,112 INFO  bamboo.dht.Dht: upcall for get req key=0xba12b9bb
return addr=172.22.34.148:3630 seq=4117322052515304436 reached replica, new recu
r style, replicas=[172.22.34.148:3633, 172.22.34.148:3630], synced=[172.22.34.14
8:3633]

....
....
.... (long latency for seq 4117322052515304435)
....
....

2007-11-01 12:49:50,078 INFO  bamboo.dht.Dht: got new recur get resp key=0x914f884b return addr=172.22.34.148:3630 seq=4117322052515304435 from 172.22.34.148:3630 replicas=[172.22.34.148:3633, 172.22.34.148:3630] synced=[172.22.34.148:3633]
2007-11-01 12:49:50,078 INFO  bamboo.dht.Dht:  iterative get req key=0x914f884b return addr=172.22.34.148:3630 seq=4117322052515304435 done
2007-11-01 12:49:50,078 DEBUG bamboo.dht.Dht: enqueuing (Dht.GetResp values.size
 ()=1 placemark=key=0x00000000 secret_hash=0x00000000 data_hash=0x00000000 time_
usec=0x0 ttl=0 client_id=0.0.0.0)
2007-11-01 12:49:50,078 INFO  bamboo.dht.Gateway: get resp client=127.0.0.1:4549
7 client_library="bamboo.dht.GatewayClient $Revision: 1.16 $" application="bambo
o.dht.BetterPutGetTest $Revision: 1.4 $" xact_id=0xe3379169 key=0x914f884b maxva
ls=2021720063 req placemark=(NONE) values=[(32, SHA 0x00000000, 0x229c5ba0, 6047
93)] resp placemark=(NONE) lat=5005 ms

Is this "long latency" possibly a bug? Can I have some pointer on how to debug this further? 

I've attached cfg files for all nodes (server and client), log files.

Thanks in advance for looking into this.

Haijun
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://bamboo-dht.org/pipermail/bamboo-users/attachments/20071101/6639692a/attachment-0001.htm 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: better-12141.log
Type: application/octet-stream
Size: 252100 bytes
Desc: better-12141.log
Url : http://bamboo-dht.org/pipermail/bamboo-users/attachments/20071101/6639692a/attachment-0006.obj 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: better.cfg
Type: application/octet-stream
Size: 853 bytes
Desc: better.cfg
Url : http://bamboo-dht.org/pipermail/bamboo-users/attachments/20071101/6639692a/attachment-0007.obj 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: experiment-12141-172.22.34.148-3630.log
Type: application/octet-stream
Size: 3088981 bytes
Desc: experiment-12141-172.22.34.148-3630.log
Url : http://bamboo-dht.org/pipermail/bamboo-users/attachments/20071101/6639692a/attachment-0008.obj 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: experiment-12141-172.22.34.148-3630.cfg
Type: application/octet-stream
Size: 2429 bytes
Desc: experiment-12141-172.22.34.148-3630.cfg
Url : http://bamboo-dht.org/pipermail/bamboo-users/attachments/20071101/6639692a/attachment-0009.obj 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: experiment-12141-172.22.34.148-3633.log
Type: application/octet-stream
Size: 587296 bytes
Desc: experiment-12141-172.22.34.148-3633.log
Url : http://bamboo-dht.org/pipermail/bamboo-users/attachments/20071101/6639692a/attachment-0010.obj 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: experiment-12141-172.22.34.148-3633.cfg
Type: application/octet-stream
Size: 2429 bytes
Desc: experiment-12141-172.22.34.148-3633.cfg
Url : http://bamboo-dht.org/pipermail/bamboo-users/attachments/20071101/6639692a/attachment-0011.obj 