Performance degradation for non-existing keys when using BINARY_PROTOCOL

[SjonHortensius]

I'm experiencing horrible performance using Memcached::OPT_BINARY_PROTOCOL, I have created a testcase that shows a ~400x slowdown, not sure why.

memcached 1.5.8
php 7.2.7
libmemcached 1.0.18
php-memcached 3.0.4

<?php

$mc = new Memcached;
$mc->addServer('localhost', 11211);
$k = uniqid();

$s = microtime(true);var_dump($mc->get($k.'1'), microtime(true)-$s); # 0.007
$s = microtime(true);var_dump($mc->get($k.'2'), microtime(true)-$s); # 0.0007
$s = microtime(true);var_dump($mc->get($k.'3'), microtime(true)-$s); # 0.0002

$mc->setOption(Memcached::OPT_BINARY_PROTOCOL, true);

$s = microtime(true);var_dump($mc->get($k.'4'), microtime(true)-$s); # 0.0004
$s = microtime(true);var_dump($mc->get($k.'5'), microtime(true)-$s); # 0.04
$s = microtime(true);var_dump($mc->get($k.'6'), microtime(true)-$s); # 0.04

strace with relative timestamps:

0.000035 socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_TCP) = 3
0.000034 connect(3, {sa_family=AF_INET6, sin6_port=htons(11211), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
0.000112 poll([{fd=3, events=POLLOUT}], 1, 4000) = 1 ([{fd=3, revents=POLLOUT}])
0.000039 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
0.000044 sendto(3, "get 5b3b6434d04711\r\n", 20, MSG_NOSIGNAL, NULL, 0) = 20
0.000064 recvfrom(3, 0x55fbdfe20bb8, 8196, MSG_NOSIGNAL, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
0.000034 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
0.000037 recvfrom(3, "END\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 5
0.000061 write(1, "bool(false)\n", 12bool(false)) = 12
0.000046 write(1, "float(0.0070631504058838)\n", 26float(0.0070631504058838)) = 26
0.000042 sendto(3, "get 5b3b6434d04712\r\n", 20, MSG_NOSIGNAL, NULL, 0) = 20
0.000060 recvfrom(3, 0x55fbdfe20bb8, 8196, MSG_NOSIGNAL, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
0.000034 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
0.000260 recvfrom(3, "END\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 5
0.000446 write(1, "bool(false)\n", 12bool(false)) = 12
0.000232 write(1, "float(0.00074386596679688)\n", 27float(0.00074386596679688)) = 27
0.000170 sendto(3, "get 5b3b6434d04713\r\n", 20, MSG_NOSIGNAL, NULL, 0) = 20
0.000085 recvfrom(3, 0x55fbdfe20bb8, 8196, MSG_NOSIGNAL, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
0.000038 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
0.000053 recvfrom(3, "END\r\n", 8196, MSG_NOSIGNAL, NULL, NULL) = 5
0.000052 write(1, "bool(false)\n", 12bool(false)) = 12
0.000045 write(1, "float(0.00024914741516113)\n", 27float(0.00024914741516113)) = 27
0.000042 sendto(3, "quit\r\n", 6, MSG_NOSIGNAL, NULL, 0) = 6
0.000062 shutdown(3, SHUT_WR)      = 0
0.000041 shutdown(3, SHUT_RD)      = 0
0.000030 close(3)                  = 0
0.000051 socket(AF_INET6, SOCK_STREAM|SOCK_CLOEXEC|SOCK_NONBLOCK, IPPROTO_TCP) = 3
0.000038 connect(3, {sa_family=AF_INET6, sin6_port=htons(11211), inet_pton(AF_INET6, "::1", &sin6_addr), sin6_flowinfo=htonl(0), sin6_scope_id=0}, 28) = -1 EINPROGRESS (Operation now in progress)
0.000101 poll([{fd=3, events=POLLIN|POLLOUT}], 1, 4000) = 1 ([{fd=3, revents=POLLOUT}])
0.000039 getsockopt(3, SOL_SOCKET, SO_ERROR, [0], [4]) = 0
0.000040 sendto(3, "\200\r\0\16\0\0\0\0\0\0\0\16\0\1\0\0\0\0\0\0\0\0\0\0005b3b6434d04714", 38, MSG_NOSIGNAL, NULL, 0) = 38
0.000062 sendto(3, "\200\n\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0", 24, MSG_NOSIGNAL, NULL, 0) = 24
0.000055 recvfrom(3, "\201\n\0\0\0\0\0\0\0\0\0\0\0\2\0\0\0\0\0\0\0\0\0\0", 8196, MSG_NOSIGNAL, NULL, NULL) = 24
0.000087 write(1, "bool(false)\n", 12bool(false)) = 12
0.000047 write(1, "float(0.0004279613494873)\n", 26float(0.0004279613494873)) = 26
0.000045 sendto(3, "\200\r\0\16\0\0\0\0\0\0\0\16\0\3\0\0\0\0\0\0\0\0\0\0005b3b6434d04715", 38, MSG_NOSIGNAL, NULL, 0) = 38
0.000062 sendto(3, "\200\n\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0\0\0\0", 24, MSG_NOSIGNAL, NULL, 0) = 24
0.000049 recvfrom(3, 0x55fbdfe20bb8, 8196, MSG_NOSIGNAL, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
0.000037 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
0.043318 recvfrom(3, "\201\n\0\0\0\0\0\0\0\0\0\0\0\4\0\0\0\0\0\0\0\0\0\0", 8196, MSG_NOSIGNAL, NULL, NULL) = 24
0.000184 write(1, "bool(false)\n", 12bool(false)) = 12
0.000072 write(1, "float(0.043596982955933)\n", 25float(0.043596982955933)) = 25
0.000058 sendto(3, "\200\r\0\16\0\0\0\0\0\0\0\16\0\5\0\0\0\0\0\0\0\0\0\0005b3b6434d04716", 38, MSG_NOSIGNAL, NULL, 0) = 38
0.000072 sendto(3, "\200\n\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\0\0\0\0\0\0\0", 24, MSG_NOSIGNAL, NULL, 0) = 24
0.000049 recvfrom(3, 0x55fbdfe20bb8, 8196, MSG_NOSIGNAL, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
0.000041 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
0.042675 recvfrom(3, "\201\n\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\0\0\0\0\0\0\0", 8196, MSG_NOSIGNAL, NULL, NULL) = 24
0.000060 write(1, "bool(false)\n", 12bool(false)) = 12
0.000043 write(1, "float(0.042906045913696)\n", 25float(0.042906045913696)) = 25
0.000049 sendto(3, "\200\7\0\0\0\0\0\0\0\0\0\0\0\7\0\0\0\0\0\0\0\0\0\0", 24, MSG_NOSIGNAL, NULL, 0) = 24
0.000063 shutdown(3, SHUT_WR)      = 0

I have tested 2 other clients (one in PHP and one in golang) but they don't have this problem

Here's another strace showing the difference in timings:

client:

16:27:20.661865 sendto(3, "\200\r\0\16\0\0\0\0\0\0\0\16\0\5\0\0\0\0\0\0\0\0\0\0005b3b87c8"..., 38, MSG_NOSIGNAL, NULL, 0) = 38
16:27:20.662018 sendto(3, "\200\n\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\0\0\0\0\0\0\0", 24, MSG_NOSIGNAL, NULL, 0) = 24
16:27:20.662102 recvfrom(3, 0x564bfeef2318, 8196, MSG_NOSIGNAL, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
16:27:20.662155 poll([{fd=3, events=POLLIN}], 1, 5000) = 1 ([{fd=3, revents=POLLIN}])
16:27:20.705002 recvfrom(3, "\201\n\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\0\0\0\0\0\0\0", 8196, MSG_NOSIGNAL, NULL, NULL) = 24

server:

16:27:20.661969 read(12, "\200\r\0\16\0\0\0\0\0\0\0\16\0\5\0\0\0\0\0\0\0\0\0\0005b3b87c8"..., 2048) = 38
16:27:20.662032 epoll_wait(8,  <unfinished ...>
16:27:20.670720 <... nanosleep resumed> NULL) = 0
16:27:20.670777 nanosleep({tv_sec=0, tv_nsec=177574000},  <unfinished ...>
16:27:20.676708 <... nanosleep resumed> NULL) = 0
16:27:20.676795 nanosleep({tv_sec=0, tv_nsec=177574000},  <unfinished ...>
16:27:20.704331 <... epoll_wait resumed> [{EPOLLIN, {u32=12, u64=12}}], 32, -1) = 1
16:27:20.704476 read(12, "\200\n\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\0\0\0\0\0\0\0", 2048) = 24
16:27:20.704706 sendmsg(12, {msg_name=NULL, msg_namelen=0, msg_iov=[{iov_base="\201\n\0\0\0\0\0\0\0\0\0\0\0\6\0\0\0\0\0\0\0\0\0\0", iov_len=24}], msg_iovlen=1, msg_controllen=0, msg_flags=0}, 0) = 24

This is on localhost so no network latency. Who's to blame?

[stdex]

Try enabling Memcached::OPT_TCP_NODELAY:
#24

[SjonHortensius]

@stdex Wow, great find. That does indeed fix this. Seems to me NODELAY should be enabled by this extension by default when BINARY gets activated. Thanks!

[Krinkle]

See #421, which proposes exactly that.

[jrots]

Any updates on this? Maybe a fix within the PECL library itself?

I'm seeing this performance degradation too .. 4 node memcache cluster,
when using sasl + binary protocol:
avg 50ms per get (==> unusable in production env..)

without :
avg 0.2ms per get

setting Memcached::OPT_TCP_NODELAY => TRUE; has no impact at all.

using :
Version | 3.1.4
libmemcached version | 1.0.18