I'll also note that the behavior is generally quite rare compared to the number of PUTs from jobrunners, e.g. I haven't been able to reproduce using the swift python client. +1 to re-image a stretch jobrunner

In T275752#6864889, @fgiunchedi wrote:

Looking back a few days, e.g. Feb 4-5th, the list of hosts that take > 80s is still eqiad jobrunners, and suspiciously all have been running buster by that date:

AFAICS, T245757 says we're almost fully on buster, so it isn't a surprise that all of them are running buster. mwdebug1003 is stretch, as well as mw1402 (api server) and mw1403 (app server), all of them are special-cases exactly for the purpose of ruling-out/confirming a distro upgrade breaking something.

If it's possible to try it at a given mw server, maybe you can try with those? Or do we need some traffic there (at which point we'd need to reimage a random jobrunner back to stretch)?

In T275752#6869341, @Urbanecm wrote:

In T275752#6864889, @fgiunchedi wrote:

Looking back a few days, e.g. Feb 4-5th, the list of hosts that take > 80s is still eqiad jobrunners, and suspiciously all have been running buster by that date:

AFAICS, T245757 says we're almost fully on buster, so it isn't a surprise that all of them are running buster. mwdebug1003 is stretch, as well as mw1402 (api server) and mw1403 (app server), all of them are special-cases exactly for the purpose of ruling-out/confirming a distro upgrade breaking something.

If it's possible to try it at a given mw server, maybe you can try with those? Or do we need some traffic there (at which point we'd need to reimage a random jobrunner back to stretch)?

From my findings in the swift logs the slow uploads happen occasionally only on buster jobrunners, not other mw hosts. It does indeed look like a jobrunner with traffic is needed.

Change 667631 had a related patch set uploaded (by Legoktm; owner: Legoktm):
[operations/puppet@production] install_server: Swtich mw1307 (jobrunner) back to stretch

https://gerrit.wikimedia.org/r/667631

Change 667631 merged by Dzahn:
[operations/puppet@production] install_server: Swtich mw1307 (jobrunner) back to stretch

https://gerrit.wikimedia.org/r/667631

Script wmf-auto-reimage was launched by dzahn on cumin1001.eqiad.wmnet for hosts:

mw1307.eqiad.wmnet

The log can be found in /var/log/wmf-auto-reimage/202103011718_dzahn_13229_mw1307_eqiad_wmnet.log.

Completed auto-reimage of hosts:

['mw1307.eqiad.wmnet']

and were ALL successful.

In T275752#6869162, @Joe wrote:

My suggestion is we re-image one jobrunner to stretch and we check if that changes things dramatically. @Legoktm / @Dzahn can you take care of this?

done! mw1307.eqiad.wmnet is back on stretch and a jobrunner.

@fgiunchedi could you re-run your analysis to see if mw1307 (10.64.0.169) is still exhibiting the issue?

In T275752#6935663, @Legoktm wrote:

@fgiunchedi could you re-run your analysis to see if mw1307 (10.64.0.169) is still exhibiting the issue?

For sure! Just did on centrallog1001 (bar_chart.py is part of https://github.com/bitly/data_hacks and lives in my home). See below, doesn't look like mw1307 is in the list at 80s threshold

centrallog1001:/srv/syslog$ zcat ms-fe2*/swift.log-20210325.gz  | awk '/proxy-server:.*PUT/ && $21 > 80 {print $6}' | ~/bar_chart.py 
# each ∎ represents a count of 1. total 54
 10.64.0.170 [     1] ∎
 10.64.0.171 [     2] ∎∎
 10.64.0.172 [     2] ∎∎
 10.64.0.173 [     5] ∎∎∎∎∎
10.64.16.105 [     5] ∎∎∎∎∎
10.64.16.106 [     3] ∎∎∎
10.64.16.199 [     2] ∎∎
 10.64.16.58 [     3] ∎∎∎
 10.64.16.59 [     2] ∎∎
 10.64.16.60 [     1] ∎
 10.64.16.61 [     1] ∎
 10.64.16.63 [     4] ∎∎∎∎
 10.64.16.65 [     3] ∎∎∎
 10.64.16.66 [     2] ∎∎
 10.64.16.67 [     3] ∎∎∎
 10.64.16.68 [     2] ∎∎
 10.64.16.69 [     2] ∎∎
 10.64.32.36 [     1] ∎
 10.64.32.37 [     3] ∎∎∎
 10.64.32.38 [     3] ∎∎∎
 10.64.32.39 [     2] ∎∎
 10.64.32.53 [     1] ∎
10.64.48.222 [     1] ∎

In T275752#6948295, @fgiunchedi wrote:

In T275752#6935663, @Legoktm wrote:

@fgiunchedi could you re-run your analysis to see if mw1307 (10.64.0.169) is still exhibiting the issue?

For sure! Just did on centrallog1001 (bar_chart.py is part of https://github.com/bitly/data_hacks and lives in my home). See below, doesn't look like mw1307 is in the list at 80s threshold

Thanks, I re-ran it just now and can confirm the same. I note that the overall occurrence of this has shot up a lot, 496 on 2021-04-03, 194 on 2021-04-04, and 168 on 2021-04-05. But I think that could easily be explained by the increased usage of video2commons, which normally results in large uploads.

Another data point, as expected post-switchover the high latency uploads from jobrunners moved from codfw to eqiad since codfw is now active.

Also to avoid confusion I'd like to clarify that on the swift side I can't find anything obviously wrong though I don't have the bandwidth to investigate further on the mw/jobrunner/buster side

One thing I think most of us missed is that MediaWiki AFAICT isn't actually uploading any data, it's just sending a X-Copy-From to Swift.

Looking at https://commons.wikimedia.org/wiki/File:A_bibliography_of_North_Carolina,_1589-1956_-_1958.djvu (51MB)

eqiad -> eqiad took 0.6s

2021-10-27 14:58:50 [5b424ea4-cc9e-48d4-be23-f30497ad135f] mw1308 commonswiki 1.38.0-wmf.5 FileOperation DEBUG: HTTP start: PUT https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu {"method":"PUT","url":"https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu"} 
2021-10-27 14:58:51 [5b424ea4-cc9e-48d4-be23-f30497ad135f] mw1308 commonswiki 1.38.0-wmf.5 FileOperation DEBUG: HTTP complete: PUT https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu code=201 size=0 total=0.600838 connect=3.9E-5 {"method":"PUT","url":"https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu","response_code":201,"size":0.0,"total_time":"0.600838","connect_time":"3.9E-5"}

eqiad -> codfw took 25s

2021-10-27 14:58:52 [5b424ea4-cc9e-48d4-be23-f30497ad135f] mw1308 commonswiki 1.38.0-wmf.5 FileOperation DEBUG: HTTP start: PUT https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu {"method":"PUT","url":"https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu"} 
2021-10-27 14:59:17 [5b424ea4-cc9e-48d4-be23-f30497ad135f] mw1308 commonswiki 1.38.0-wmf.5 FileOperation DEBUG: HTTP complete: PUT https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu code=201 size=0 total=25.100911 connect=4.0E-5 {"method":"PUT","url":"https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-commons-local-public.ef/e/ef/A_bibliography_of_North_Carolina%2C_1589-1956_-_1958.djvu","response_code":201,"size":0.0,"total_time":"25.100911","connect_time":"4.0E-5"}

(note: we should probably log headers here)

Scratch that, the requests that are slow are not using X-Copy-From:

2021-10-28 20:45:41 [fc3a0714-35c2-4cbc-8999-ad4c24bc17b4] mw1439 testwiki 1.38.0-wmf.6 FileOperation DEBUG: HTTP start: PUT https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu {"method":"PUT","url":"https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu","headers":{"x-content-dimensions":"","content-type":"image/vnd.djvu","content-length":53798301,"etag":"069fc83e88bc112f309f2548c386853c","x-object-meta-sha1base36":"56e0liu04c2u9avcrvlz7m5k4nh6gxf"}} 
2021-10-28 20:45:42 [fc3a0714-35c2-4cbc-8999-ad4c24bc17b4] mw1439 testwiki 1.38.0-wmf.6 FileOperation DEBUG: HTTP complete: PUT https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu code=201 size=0 total=0.613292 connect=6.7E-5 {"method":"PUT","url":"https://ms-fe.svc.eqiad.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu","response_code":201,"size":0.0,"total_time":"0.613292","connect_time":"6.7E-5"} 
...
2021-10-28 20:45:42 [fc3a0714-35c2-4cbc-8999-ad4c24bc17b4] mw1439 testwiki 1.38.0-wmf.6 FileOperation DEBUG: HTTP start: PUT https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu {"method":"PUT","url":"https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu","headers":{"x-content-dimensions":"","content-type":"image/vnd.djvu","content-length":53798301,"etag":"069fc83e88bc112f309f2548c386853c","x-object-meta-sha1base36":"56e0liu04c2u9avcrvlz7m5k4nh6gxf"}} 
2021-10-28 20:46:10 [fc3a0714-35c2-4cbc-8999-ad4c24bc17b4] mw1439 testwiki 1.38.0-wmf.6 FileOperation DEBUG: HTTP complete: PUT https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu code=201 size=0 total=27.750302 connect=4.0E-5 {"method":"PUT","url":"https://ms-fe.svc.codfw.wmnet/v1/AUTH_mw/wikipedia-test-local-public/3/36/Legoktm_test_1.djvu","response_code":201,"size":0.0,"total_time":"27.750302","connect_time":"4.0E-5"}

I think I narrowed it down. If I upload using plain CLI curl, it finishes instantaneously:

Now when I use a stripped down version of SwiftFileBackend/MultiHttpClient, I get:

note that it's doing fread's with a chunk size of 65536 or 65kb...which again points to syscalls just overall being slower on buster. strace shows CLI curl using like five read() syscalls to read the whole file while PHP took so many it scrolled off my terminal.

If I use PHP's stream wrappers, literally:

$opts = [ 'http' => [
	'method' => 'PUT',
	'header' => $realHeaders,
	'content' => $contents,
] ];

$ctx = stream_context_create($opts);
$fh = fopen( $url, "r", false, $ctx );
$result = stream_get_meta_data( $fh );

Where $contents is the file read into memory, then the same exact upload to codfw takes ~1s.

Also note that during the buster upgrade we did move from curl 7.52.1 to 7.64.0, so it could also be a regression from that. I haven't looked at the libcurl changelog yet.

I tried a few different variations on the PHP curl script, none of which made a difference:

• Using curl_setopt( $ch, CURLOPT_POSTFIELDS, $contents ); instead of CURLOPT_INFILE/CURLOPT_READFUNCTION
• Writing the file to php://memory which is supposed to be a in-memory stream

The stream_context_create solution only works for files that fit under the memory limit, which is currently ~600MB.

In T275752#7467352, @Legoktm wrote:

The stream_context_create solution only works for files that fit under the memory limit, which is currently ~600MB.

@Inductiveload mentioned to me that the practical limit to not hit a timeout is ~90-100MB, so this still would be a decent improvement. We could also have a temporary higher memory limit for job runners like we already do for Parsoid.

Just to clarify from a previous comment from @Legoktm, the "fread" reported in his output is produced by curl when it sends the data to the client. So I'm not sure at all it has to do with too many syscalls.

So, we can go deeper in what's wrong here, but for now I just tested switching the URL we call in @Legoktm's test.php to funnel the request via envoy, and that reduced the upload time to ~ 1 second, which is what we were seeing with the curl cli tool as well. We need to do a few more tests - like try to change the swift url on mwdebug and see if that's enough to fix the issue without breaking the world, but it seems indeed the problem is with the transfer chunk size and the amount of back and forth chatter needed as a consequence.

While I think this route should be only followed with care (we know that introducing a proxy between systems often causes failures of its own) it is still a way out and confirmed my basic suspect.

So, what I think we know at this point is:

• The problem is completely within php / curl; curl from the command line or pretty much any other client behaves correctly.
• PHP's curl usage will write/read responses in 65k chunks, so there seems to be a back-forth of request/response partial data across the wire
• for the test file, I see 820 such req/resp partial stages (the fread in lego's paste)
• If we multiply 820 by 31.5 ms (the rtt between mw1305 and ms-fe.svc.codfw.wmnet) we get 25.8 seconds... which is more or less the overhead we're seeing

Now I would just need to get a full dump of the tcp communications between client and server to confirm what exactly is happening - I suppose it's waiting for "100-contiunue" messages from the server.

So @Legoktm hypothesis seems overall correct - but it's not the syscalls that cause the slowness, it's the 820 round trips between datacenters because we're sending such small chunks.

Adding a statistical analysis of packet lengths in wireshark from 2 captures. Upper one, with 3323 packets in total is standard curl call, lower one, with 13326 packets is test.php.

I don't think curl sends Expect: 100-continue for chunked transfers to begin with, and I don't think chunks need to be ack'ed before sending the next in HTTP/1.1.

But then, as Lego's output above shows, cmdline curl is using HTTP/1.0 and libcurl from PHP is using HTTP/2. And in HTTP/2 chunked transfer encoding isn't supported, replaced with some new streaming and multiplexing stuff that I've never looked into but which sounds suspiciously like reimplementing TCP on top of HTTP. In particular, I wouldn't be at all surprised to find that HTTP/2 has what amounts to a TCP ACK but without SACK.

Can we force cmdline curl to HTTP/2, or PHP libcurl to HTTP/1.1, to test that?

In any case, with ~15ms latency any synchronous ack is going to kill performance with small chunks (http level "packets"), and upping the size of the chunks massively the best bet for improving throughput.

Can we force cmdline curl to HTTP/2, or PHP libcurl to HTTP/1.1, to test that?

Right on target! Thanks for noticing that, that's the issue. HTTP2 shouldn't really be used in internal scenarios, it was never meant for that.

setting curl_setopt( $ch, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1); in the code fixes it and conversely passing --http2 to the curl call reproduces it.

Yes, thanks for noticing @Xover; a posteriori, it's pretty obvious what is going on and it's interesting how much more inefficient using http2 is in this case (not surprising, once you think about it, but still unexpected, at least for me).

#2709 landed in libcurl 7.62.0 and enabled HTTP/2 multiplexing by default when available, so Buster would indeed have changed the behaviour here as Lego suggested in T275752#7467345.

In T275752#7467725, @akosiaris wrote:

setting curl_setopt( $ch, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1); in the code fixes it

Hmm. Is HTTP/2 actually used for anything in core? Just setting the above in the global settings in MultiHttpClient.php:getCurlHandle() might be all that's needed.

In T275752#7467817, @Xover wrote:

In T275752#7467725, @akosiaris wrote:

setting curl_setopt( $ch, CURLOPT_HTTP_VERSION, CURL_HTTP_VERSION_1_1); in the code fixes it

Hmm. Is HTTP/2 actually used for anything in core? Just setting the above in the global settings in MultiHttpClient.php:getCurlHandle() might be all that's needed.

I would rather add an option to the constructor of MultiHttpClient conditionally or - let me put my SRE hat on - get the ability to define domains for which we do not want to use http/2 so that we can effectively ban the use of http/2 internally.