"Failed to write, and not due to blocking" on Memcached 1.5.3 #458

blkperl · 2019-03-05T21:54:09Z

I'm trying to debug an issue where connections to memcache timeout after a stream of EAGAIN messages on the recvfrom and sendto system calls.

Temporarily upgrading to the latest version of memcached did not resolve the issue. It can be reproduced on multiple servers across different availability zones and the servers have been replaced and the issue eventually reoccurs on the new servers.

On the client

I have been unable to isolate the issue from Drupal so far as testing with php manually works fine. The initial drush9 command also works after memcached restart but fails on all following occurrences.

timeout 120 strace -s 2048 -Tfe trace=network drush9 php-eval 'true;'
[...]
[pid  1140] sendto(8,   [....] , 8196, MSG_NOSIGNAL|MSG_MORE, NULL, 0) = -1 EAGAIN (Resource temporarily unavailable) <0.000020>

During this time ~13,000 sets and gets are performed from the Drupal bootstrap.

On the with server -vvv flags enabled

Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: <37 GET 674e2bb21b4c41979d663e0d26dd12f9_%3Aconfig%3A-core.base_field_override.node.product_page_block.status
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: > FOUND KEY 674e2bb21b4c41979d663e0d26dd12f9_%3Aconfig%3A-core.base_field_override.node.product_page_block.status
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: >37 Writing bin response:
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: >37   0x81 0x0d 0x00 0x65
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: >37   0x04 0x00 0x00 0x00
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: >37   0x00 0x00 0x04 0x46
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: >37   0x02 0x3e 0x00 0x00
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: >37   0x00 0x00 0x00 0x00
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: >37   0x00 0x00 0x00 0x00
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: 37: going from conn_nread to conn_mwrite
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: Failed to write, and not due to blocking: Connection reset by peer
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: 37: going from conn_mwrite to conn_closing
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: <37 connection closed.
Mar 05 19:59:46 web-12345.redacted.com memcached[32007]: 37: going from conn_closing to conn_closed

Version info

   ["version"]=>
    string(5) "1.5.3"
    ["libevent"]=>
    string(13) "2.0.21-stable"

Client Config

$settings['memcache']['options'][Memcached::OPT_COMPRESSION] = TRUE;
$settings['memcache']['options'][Memcached::OPT_BINARY_PROTOCOL] = TRUE;

The text was updated successfully, but these errors were encountered:

dormando · 2019-03-06T01:38:44Z

Sounds like the client killed the connection for some reason :( Server tries to write but gets peer'ed.

Looks like php-memcached, libmemcached based client. What client version? + What distro/where did the server and client builds come from?

blkperl · 2019-03-06T02:17:31Z

Client is from Ubuntu repositories. Server is compiled and packaged manually.

php-memcached 3.1.3
libmemcached11 1.0.18-4.1
Ubuntu Xenial with memcached compiled from source (1.5.3)
PHP 7.2 and PHP 7.1

I also opened php-memcached-dev/php-memcached#429

dormando · 2019-03-06T03:18:24Z

Well the error is likely on the client, unless the server is returning a malformed response. Hopefully you'll have more luck with the php-memcached project? At some point somewhere the client should be emitting an error code.

blkperl · 2019-03-06T15:48:14Z

Alright, thanks for narrowing it down. I'll wait for them to respond on php-memcached-dev/php-memcached#429

glennpratt · 2019-03-08T23:00:56Z

@dormando what does this mean, do you mean the client closed an end of the connection or something else? I'm not seeing close in strace.

Server tries to write but gets peer'ed.

dormando · 2019-03-08T23:15:08Z

@glennpratt If the server is getting "connection reset by peer" when writing, it means it received a TCP RST (connection was reset). That could happen for a number of reasons (firewalls? client crash? fd recycle?), so I can't really tell you why offhand.

glennpratt · 2019-03-13T22:46:43Z

Thanks for the feedback, greatly appreciated. I can't say I see any of those things from strace or tcpdump.

Here's a Wireshark summary from both sides:

https://gist.github.com/glennpratt/1973c7e5f423dfe7365c72d89c34ab21

dormando · 2019-03-13T22:55:08Z

Got some "acked unseen segments" toward the end of the capture. packet loss/rate issues?

glennpratt · 2019-03-13T23:08:46Z

Memcached Server

ssh server 'netstat -s | grep -i retrans'
    169742 segments retransmited
    TCPLostRetransmit: 1129
    28874 fast retransmits
    1985 forward retransmits
    1254 retransmits in slow start
    156 SACK retransmits failed
    TCPSynRetrans: 5320

Bad Client machine

ssh bad-client 'netstat -s | grep -i retrans'
    1497604 segments retransmited
    TCPLostRetransmit: 16
    3963 fast retransmits
    353 forward retransmits
    286 retransmits in slow start
    23 SACK retransmits failed
    TCPSynRetrans: 5077

Good Client machine

ssh good-client 'netstat -s | grep -i retrans'
    318614 segments retransmited
    TCPLostRetransmit: 2
    2547 fast retransmits
    600 forward retransmits
    293 retransmits in slow start
    75 SACK retransmits failed
    TCPRetransFail: 1
    TCPSynRetrans: 25842

glennpratt · 2019-03-13T23:11:17Z

Also, here's the wireshark summaries from a good session:

https://gist.github.com/glennpratt/9e29e54504806acdc2fc8feca35558f8

dormando · 2019-03-13T23:15:46Z

confused; what's a good client machine vs bad client machine? only certain clients get disconnected from even the same servers?

glennpratt · 2019-03-13T23:21:36Z

The behavior only seems to happen from one particular server (out of three in a cluster) at a time. The behavior reliably returns on new clusters, after replacing servers, etc. The errors will stop for 1 or 2 request cycles after restarting memcached.

It seems possible that the issue may be triggered by the actual content of the cache traffic.

dormando · 2019-03-13T23:29:28Z

That's certainly possible, which is why I was asking about getting client errors at first. It should be raising some kind of exception internally.

also when I said your wireshark is missing data, I don't mean the machine was retransmitting, I mean your tcpdump wasn't capturing everything so it wasn't fully correlating. It could've missed the RST in there.

glennpratt · 2019-03-13T23:38:11Z

I am not seeing the "Connection reset by peer" log message except when the client program actually exits, in which case it is likely expected. I'm not seeing that log on the server while the client seems to be hung in a loop around EAGAIN.

The client code is not receiving an Exception in PHP land as far as I can tell. When I inspect the PHP process with gdb while it is in this loop, it is in libmemcached code.

I'll make some new captures and include something from strace and gdb if I can.

dormando · 2019-03-13T23:47:25Z

Any chance you could re-summarize the problem from the start? The more detail the better since I don't know drupal/php/etc.

As originally written it sounds like the client EAGAIN's for some amount of time, then the server gets peer'ed trying to write. From what you say now it sounds like the client gets into EAGAIN infinite loops sometimes, and the client will eventually timeout and get killed?

dormando · 2019-04-04T21:40:42Z

Hey,

how goes? I'd like to get this figured out or close out the issue. thanks!

glennpratt · 2019-04-10T21:36:38Z

Hi @dormando,

Thanks for checking in!

To summarize from the start:

Drupal application operating on 3 webnodes with a single memcached daemon.

We have isolated the problem to one configuration setting for the PHP memcached extension: Memcached::OPT_BINARY_PROTOCOL.

The problem is this, during application bootstrap there are a number of gets and sets. On one or two of the three nodes, the application bootstrap becomes extremely slow. Looking at gdb, the process is looping inside libmemcached. Looking at Wireshark we see the "TCP Window Full" message at the same time that the process goes into a very slow loop inside libmemcached.

None of this happens with Memcached::OPT_BINARY_PROTOCOL is not set.

As far as I can tell, the connection resets only happened at a timeout killing the process, as you suggest. In other words, not an issue.

dormando · 2019-04-27T08:23:42Z

Sorry! I know I pinged but just getting back to looking through issues.

Sounds like you figured it out? Something killing your process? Okay if we close the issue then? :)

blkperl · 2019-04-27T17:57:06Z

@dormando, No we are stuck now. We need Memcached::OPT_BINARY_PROTOCOL for SASL but don't how to further debug the slow loop inside libmemcached which eventually causes the process to die at connection reset timeout

The problem is this, during application bootstrap there are a number of gets and sets. On one or two of the three nodes, the application bootstrap becomes extremely slow. Looking at gdb, the process is looping inside libmemcached. Looking at Wireshark we see the "TCP Window Full" message at the same time that the process goes into a very slow loop inside libmemcached.

dormando · 2019-04-27T18:28:17Z

Got it. I misread that part sorry.

From your latest update it might be possible you're just filling the tcp window? uhhh I thought libmemcached had a pressure release though. it's been a while since I've thought about it.

basically: if you issue large gets and sets but aren't reading the gets off the socket fast enough the receive buffer fills on the client side. Then on memcached's side its send buffer fills.. so then it goes into a loop waiting to send more data before going back into read mode. Think that's something that might be happening here?

If that's not it I'd have to dig in really closely or we'd need a reproducable test independent of your app that I can examine.

dormando · 2019-04-27T23:10:22Z

Ah I meant to more clearly say this can happen on streams of gets: "get foo\r\n" x 100k without reading the socket and you'll deadlock.

blkperl · 2019-05-16T21:21:45Z

For others who might stumble upon this. The fix was to set send and recv size.

Memcached::OPT_SOCKET_SEND_SIZE = 1024 * 1024;
Memcached::OPT_SOCKET_RECV_SIZE = 1024 * 1024;

fgm · 2020-05-04T07:42:58Z

FWIW, I just got this today on macOS and Drupal 8.8.5:

PHP PHP 7.3.17 (cli) (built: Apr 16 2020 12:52:37) ( NTS )
- Zend Engine v3.3.17, Copyright (c) 1998-2018 Zend Technologies
- with Xdebug v2.9.4, Copyright (c) 2002-2020, by Derick Rethans
- with Zend OPcache v7.3.17, Copyright (c) 1999-2018, by Zend Technologies
php-memcached 3.1.5
libmemcached 1.0.18
Memcached daemon 1.6.5

It happens with the default options, so I checked the combinations of all 4 options suggested in this issue separately:

Setting OPT_SOCKET_(SEND|RECV)_SIZE did not fix the problem
Setting OPT_COMPRESSION to true did not fix it either
Setting OPT_BINARY_PROTOCOL to true is what fixed it for me for most cases (all Drush cases) both with or without the other ones. However, on some pages, even enabling the three other options did not get it to entirely disappear.

dormando · 2020-05-04T07:49:52Z

The fix is to not write a million keys to the socket without reading anything back.

fgm · 2020-05-04T08:04:16Z

Thanks for the answer, I opened an issue on the Drupal memcache module to suggest this.

blkperl changed the title ~~Failed to write, and not due to blocking on Memcached 1.5.3~~ "Failed to write, and not due to blocking" on Memcached 1.5.3 Mar 5, 2019

blkperl mentioned this issue Mar 5, 2019

"Failed to write, and not due to blocking" php-memcached-dev/php-memcached#429

Open

dormando closed this as completed May 16, 2019

solracsf mentioned this issue Dec 11, 2020

Memcached Failed to write, and not due to blocking: Connection reset by peer #749

Closed

petergoldstein mentioned this issue Nov 16, 2021

send_multiget write call hangs if keys total bytesize > ~1,700,000 bytes petergoldstein/dalli#776

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

"Failed to write, and not due to blocking" on Memcached 1.5.3 #458

"Failed to write, and not due to blocking" on Memcached 1.5.3 #458

blkperl commented Mar 5, 2019 •

edited

dormando commented Mar 6, 2019

blkperl commented Mar 6, 2019 •

edited

dormando commented Mar 6, 2019

blkperl commented Mar 6, 2019

glennpratt commented Mar 8, 2019 •

edited

dormando commented Mar 8, 2019

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

glennpratt commented Mar 13, 2019

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

dormando commented Apr 4, 2019

glennpratt commented Apr 10, 2019

dormando commented Apr 27, 2019

blkperl commented Apr 27, 2019

dormando commented Apr 27, 2019

dormando commented Apr 27, 2019

blkperl commented May 16, 2019

fgm commented May 4, 2020 •

edited

dormando commented May 4, 2020

fgm commented May 4, 2020 •

edited

"Failed to write, and not due to blocking" on Memcached 1.5.3 #458

"Failed to write, and not due to blocking" on Memcached 1.5.3 #458

Comments

blkperl commented Mar 5, 2019 • edited

On the client

On the with server -vvv flags enabled

Version info

Client Config

dormando commented Mar 6, 2019

blkperl commented Mar 6, 2019 • edited

dormando commented Mar 6, 2019

blkperl commented Mar 6, 2019

glennpratt commented Mar 8, 2019 • edited

dormando commented Mar 8, 2019

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

glennpratt commented Mar 13, 2019

Memcached Server

Bad Client machine

Good Client machine

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

glennpratt commented Mar 13, 2019

dormando commented Mar 13, 2019

dormando commented Apr 4, 2019

glennpratt commented Apr 10, 2019

dormando commented Apr 27, 2019

blkperl commented Apr 27, 2019

dormando commented Apr 27, 2019

dormando commented Apr 27, 2019

blkperl commented May 16, 2019

fgm commented May 4, 2020 • edited

dormando commented May 4, 2020

fgm commented May 4, 2020 • edited

blkperl commented Mar 5, 2019 •

edited

blkperl commented Mar 6, 2019 •

edited

glennpratt commented Mar 8, 2019 •

edited

fgm commented May 4, 2020 •

edited

fgm commented May 4, 2020 •

edited