OS X 10.4.2, storing objects roughly over 32K ...

[James Robinson]

I'm seeing a strange issue under OS X 10.4.2, client connecting from  
localhost, when caching documents right around 32K or bigger. There  
seems to be a  ~4 second delay between when memcached writes out  
"STORED\r\n" as the response and when the client reads it. Really  
bizarre.

Here's a tcpdump when setting a 32600 byte value:

jlrobins:/tmp/memcached-1.1.12 root# tcpdump -i lo0 port 11211
tcpdump: verbose output suppressed, use -v or -vv for full protocol  
decode
listening on lo0, link-type NULL (BSD loopback), capture size 96 bytes
17:04:29.261825 IP localhost.50153 > localhost.11211: S  
183680513:183680513(0) win 65535 <mss 16344,nop,wscale  
0,nop,nop,timestamp 185539278 0>
17:04:29.261903 IP localhost.11211 > localhost.50153: S  
2469690051:2469690051(0) ack 183680514 win 65535 <mss  
16344,nop,wscale 0,nop,nop,timestamp 185539278 185539278>
17:04:29.261918 IP localhost.50153 > localhost.11211: . ack 1 win  
65535 <nop,nop,timestamp 185539278 185539278>
17:04:29.262434 IP localhost.50153 > localhost.11211: . 1:16333 
(16332) ack 1 win 65535 <nop,nop,timestamp 185539278 185539278>
17:04:29.262447 IP localhost.50153 > localhost.11211: P 16333:32620 
(16287) ack 1 win 65535 <nop,nop,timestamp 185539278 185539278>
17:04:29.436047 IP localhost.11211 > localhost.50153: P 1:9(8) ack  
32620 win 65535 <nop,nop,timestamp 185539279 185539278>
17:04:29.636112 IP localhost.50153 > localhost.11211: . ack 9 win  
65535 <nop,nop,timestamp 185539279 185539279>

(the next to last line is memcached sending the 'STORED\r\n'. Nice  
and spiffy.)

Now 32700 bytes store ...
jlrobins:/tmp/memcached-1.1.12 root# tcpdump -i lo0 port 11211
tcpdump: verbose output suppressed, use -v or -vv for full protocol  
decode
listening on lo0, link-type NULL (BSD loopback), capture size 96 bytes
17:05:50.262118 IP localhost.50155 > localhost.11211: S  
575405321:575405321(0) win 65535 <mss 16344,nop,wscale  
0,nop,nop,timestamp 185539440 0>
17:05:50.262196 IP localhost.11211 > localhost.50155: S  
1446792907:1446792907(0) ack 575405322 win 65535 <mss  
16344,nop,wscale 0,nop,nop,timestamp 185539440 185539440>
17:05:50.262211 IP localhost.50155 > localhost.11211: . ack 1 win  
65535 <nop,nop,timestamp 185539440 185539440>
17:05:50.262943 IP localhost.50155 > localhost.11211: . 1:16333 
(16332) ack 1 win 65535 <nop,nop,timestamp 185539440 185539440>
17:05:50.262953 IP localhost.50155 > localhost.11211: . 16333:32665 
(16332) ack 1 win 65535 <nop,nop,timestamp 185539440 185539440>
17:05:50.262957 IP localhost.50155 > localhost.11211: P 32665:32720 
(55) ack 1 win 65535 <nop,nop,timestamp 185539440 185539440>
17:05:50.263988 IP localhost.11211 > localhost.50155: . ack 32720 win  
65535 <nop,nop,timestamp 185539440 185539440>
17:05:54.947407 IP localhost.11211 > localhost.50155: P 1:9(8) ack  
32720 win 65535 <nop,nop,timestamp 185539449 185539440>
17:05:55.047441 IP localhost.50155 > localhost.11211: . ack 9 win  
65535 <nop,nop,timestamp 185539450 185539449>

4 second delay in getting that response line out to the client. This  
seems to happen for any store size greater than that figure  
suspiciously close to 32K. Actually fetching the cached data is fast  
-- just storing the 'large' item. And it seems to be something TCP  
related -- running memcached with '-vv' shows it writing 'STORED' out  
to the client socket nearly immediately.

Can anyone under OS X duplicate this behaviour?

Here's a python script to test with:

---
import memcache
c = memcache.Client(['127.0.0.1:11211'])
c.set(1, 's' * 32600)    # Works great

c.set(2, 's' * 32700) # Takes ~ 4 seconds
---


Thanks in advance,
James

----
James Robinson
Socialserve.com