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

[James Robinson]

On Aug 30, 2005, at 5:37 PM, Alex Stapleton wrote:

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


Started up memcached again, then ran the following script to test  
timing stores of ever increasing payload sizes:

---
import memcache
import time

c = memcache.Client(['127.0.0.1:11211'])

for i in range(0,38000, 20):
     if i % 50 == 0:
         print 'did %d' % (i,)
     val = 's' * i
     t1 = time.time()
     c.set(i,val)
     t2= time.time()
     if t2 - t1 > 1:
         print "%d store took %d seconds" % (i, t2  - t1)

---


Here's the result. From payload size 0 to 32640 was under a second  
each store + recv response, but ...

... [ boring part from 0 to 32300 snipped ]
did 32400
did 32500
did 32600
32660 store took 4 seconds
32680 store took 4 seconds
did 32700
32700 store took 4 seconds
32720 store took 4 seconds
32740 store took 4 seconds
32760 store took 4 seconds
32780 store took 4 seconds
did 32800
32800 store took 4 seconds
32820 store took 4 seconds

So, every store after some payload size very near 32660 tickles  
something odd.

The MTU on the loopback device is 16384.

I restarted memcached and worked backwards, from payload size 32740  
down to 32000, and once it got below 32660 again it got brisk again:
---
import memcache
import time

c = memcache.Client(['127.0.0.1:11211'])

for i in range(32740,32000, -20):
     if i % 50 == 0:
         print 'did %d' % (i,)
     val = 's' * i
     t1 = time.time()
     c.set(i,val)
     t2= time.time()
     if t2 - t1 > 1:
         print "%d store took %d seconds" % (i, t2  - t1)
---
32740 store took 4 seconds
32720 store took 4 seconds
did 32700
32700 store took 4 seconds
32680 store took 5 seconds
32660 store took 5 seconds
did 32600
did 32500
did 32400
did 32300
did 32200
did 32100
---

So it doesn't seem to be immediately related to being the first data  
being sent over the wire. Stepping down from 32660 by increments of  
one byte shows the pivot point at 32641 -- this size or higher things  
go slowly.

I have since slightly altered memcached.c, going through all 4  
permuntations of twiddling TCP_NODELAY and TCP_NOPUSH on and off on  
the server socket in function server_socket(), but these have no  
effect upon this symptom. Neither did doing the same thing on newly  
accepted client sockets (just in case OS X didn't copy the server  
socket options over to the accepted connection sockets).

Bumping both the TCP_SNDBUF and TCP_RCVBUF from default 32K to 64K on  
the newly accepted socket connection had no discernible effect.  
Neither did twiddling the TCP_NOWAIT, SO_SNDBUF and SO_RCVBUF values  
on the client end. Turning TCP_NOPUSH off at the client end  
definitely made things worse -- making payload sizes greater than the  
MTU but 16K take 4 or more seconds for the total round trip, but  
sparing those less than MTU size:

----
import memcache
import time
import socket

c = memcache.Client(['127.0.0.1:11211'])
c.get(0)     # Force connection establishment.
method = c.servers[0].socket.setsockopt
for level, opt, val in (
     (socket.SOL_SOCKET, socket.SO_SNDBUF, 32767*2),
     (socket.SOL_SOCKET, socket.SO_RCVBUF, 32767*2),
     (socket.IPPROTO_TCP, socket.TCP_NODELAY, 1),
     (socket.IPPROTO_TCP, 4, 1)    # TCP_NOPUSH value gleamed from / 
usr/include/netinet/tcp.h -- YMMV
     ):
     method(level, opt, val)

for i in (32641, 32639, 16000, 14000, 18000, 32641, 32644,55000,  
32641 * 2):
     val = 's' * i
     t1 = time.time()
     c.set(i,val)
     t2= time.time()
     print "%d store took %d seconds" % (i, t2  - t1)
---
Yeilds:

32641 store took 4 seconds
32639 store took 5 seconds
16000 store took 0 seconds
14000 store took 0 seconds
18000 store took 10 seconds
32641 store took 5 seconds
32644 store took 9 seconds
55000 store took 5 seconds
65282 store took 9 seconds


----

So, the only effect I've had on things at all is enabling TCP_NOPUSH  
on the client end, which makes things worse.

----
James Robinson
Socialserve.com