memcached(8) loosing fd events...

Sean Chittenden sean at gigave.com
Fri Aug 19 04:10:40 PDT 2005


I'm not sure if this is an event(3) problem, a memcached(8) issue, or
even a FreeBSD kqueue(2) problem, but, I'm feeling rather vindicated
at the moment.

http://people.FreeBSD.org/~seanc/libmemcache/libmemcache-1.4.0.b2.tar.bz2

In prep for 1.4, I've been putting together some additional regression
tests and have been hunting down various protocol state
synchronization issues, etc.  After a few weeks of love with gdb(1)
and many bug fixes, in the end I very well could be chasing a wild
goose.  After reaching the ultimate state of desperation and
frustration with gdb(1), I decided to attach ktrace(1) to the process
and sure enough:

 85827 lt-benchmark RET   read 8
 85827 lt-benchmark CALL  write(0x3,0x8050000,0x22)
 85827 lt-benchmark GIO   fd 3 wrote 34 bytes
       "set bench_key 0 0 10\r
        EEEEEEEEEE\r
       "
 85827 lt-benchmark RET   write 34/0x22
 85827 lt-benchmark CALL  read(0x3,0x804f000,0x1000)
 85827 lt-benchmark RET   read -1 errno 35 Resource temporarily unavailable
 85827 lt-benchmark CALL  read(0x3,0x804f000,0x1000)
 85827 lt-benchmark RET   read -1 errno 35 Resource temporarily unavailable
 85827 lt-benchmark CALL  read(0x3,0x804f000,0x1000)
 85827 lt-benchmark RET   read -1 errno 35 Resource temporarily unavailable
 85827 lt-benchmark CALL  read(0x3,0x804f000,0x1000)
 85827 lt-benchmark RET   read -1 errno 4 Interrupted system call
 85827 lt-benchmark PSIG  SIGINT SIG_DFL

The client fires off the command, and the server never responds.  I
haven't been able to reproduce this when memcached(8) is being
ktrace(1)'ed, otherwise I'd present a complementary version from the
server side.  So, my theories are this so far:

*) event(3) fails to execute the callback when an event is triggered.

*) there's a code path in memcached(8) that causes a fd event to not
   be re-registered or for the client's fd state to not be set to
   conn_write.  I've been able to reproduce this with all of the major
   commands (get, set, and add) with a high degree of regularity.
   This is my favorite hypothesis since this would explain why the
   server ceases to have this problem when I renice it to +20.

*) if I renice memcached(8) to +20, the problem goes away.  Maybe this
   is a kqueue(2) race condition.  Possible, but *highly* unlikely
   given kqueue(2)'s workload in other daemons.

If I slam the server with thousands of ops per second (ie, 50+% CPU),
occasionally I've been able to see the server refuse to handle
connections from other fd's.  It just doesn't read(2) in any data from
the client.  I'm guessing that if an fd has an op, but it isn't
serviced by memcached(8) fast enough because memcached(8) is busy,
memcached(8) doesn't re-register the fd and any events on the fd are
lost.

Reniced:

Value size:     10
Num tests:      100000
Test    Ops per second  Total Time      Time per Request
set     9905.273885     10.095632       0.000101
get     10083.104951    9.917580        0.000099
add     9645.432921     10.367601       0.000104
delete  11536.565548    8.668091        0.000087

Without, I can't even complete the set iterations.  I haven't dug into
this yet, but, if someone has a bright idea or a suspicion, I'm all
ears.  I'm also running into an interesting bit where my long_val test
is causing the connection to reset:

 88933 lt-long_val CALL  write(0x3,0x804d000,0xefe)
 88933 lt-long_val GIO   fd 3 wrote 3838 bytes
       "set key-1-3811 0 0 3811\r
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\
        EEEEEEEEEEEEEEEEEEEEEEEEEEEEEEE\r
       "
 88933 lt-long_val RET   write 3838/0xefe
 88933 lt-long_val CALL  read(0x3,0x804c000,0x1000)
 88933 lt-long_val GIO   fd 3 read 8 bytes
       "STORED\r
       "
 88933 lt-long_val RET   read 8
 88933 lt-long_val CALL  write(0x3,0x804d000,0x10)
[end of ktrace(1) output, client returns connection reset when I try to read(2) from the fd]

Under nominal or busy load conditions, I don't know that anyone
would've noticed this since a network/scheduler will slow things down
to the point that the server isn't vulnerable to these problems, but
over localhost on an idle box... all bets are off.



-- 
Sean Chittenden


More information about the memcached mailing list