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

[Alex Stapleton]

This sounds suspiciously like a problem I reported a while ago. Do  
you get different behaviour depending on whether or not you have just  
restarted memcached before running the test? e.g. if you create the  
keys with smaller data first for example?

On 30 Aug 2005, at 22:11, James Robinson wrote:


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