From the stacktrace it's unclear whether it's happening during pre-send shutdown or post-send shutdown. If it's pre-send shutdown, then this would probably fatal the webrequest in question.

General improvement

We should move it to post-shutdown and wrap in a try/catch so that we isolate any future potential for errors as well. (Profiling must never break the web request!)

Specific issue

As for the specific error found in this task, looks like it might have to do with the connection timeout being reached. Which seems fair, given we set it very low at 0.1s. It's quite acceptable to lose a few traces from the sampling profiler. Although it'd be good to confirm that this is indeed just caused by the network and/or redis service being a little slower to respond than usual.

Checking online led me to https://stackoverflow.com/a/18087513/319266 and https://github.com/phpredis/phpredis/issues/70 which further suggest three alternative explanations:

• Redis service might be under load. I was under the impression we're pretty low on load, so if this is the case, it might be worth making sure the underlying system, network and Redis service are configured and setup correctly to handle the required load. Also with future growth in mind. If we're at capacity and dropping a few request per day, that seems worrying. Not because of what we lose today, but because it means we're at capacity.

• The connect timeout might not be working. The thread suggests the timeout parameter is "relatively new" and might not be supported by our version of phpredis, in which case the 0.1s we're passing would be ineffective. We're not actually using phpredis, but HHVM's built-in port of it. So some differences here aren't unexpected. To be confirmed.

• The phpredis client can sometimes persist connections without it being obvious, which could lead to the kind of error we found. We don't want to persist connections here, so to be confirmed that this is indeed not happening.

Given the start date of September 14, I'm assuming this is probably due to the switchover. We're logging to mwlog1001 which is in eqiad, so the distance is greater now and that would explain why connections would take longer to establish on average.

Based on the stacktrace, this isn't coming from $redis->connect(). Instead, it's coming from publish(). Specifically, it's from after the PUBLISH command is sent to the server, when the client is attempting to read the server's response. The profiling code doesn't actually use the response, though.

Right before reading the response from the Redis socket, HHVM's Redis\socketReadLine calls checkConnection() which checks stream_get_meta_data()['timed_out'], and then decides to throw based on that. (hhvm src)

I've thus eliminated possibility 2 (timeout not working) and 3 (persistent connections being used). This leads possibility 1 (Redis under load), and the initial premise if it simply being an actual timeout due to increased physical latency simply not making it possible to send all the data in under 100ms all the time.

Physical latency seems almost certain to be the issue. It's 36ms roundtrip from codfw to eqiad, so the tolerance is quite tight.

I'd suggest just wrapping in a try and ignoring a failure. Not really worth doing anything more than that, given that this has only occurred a couple of dozen times.

Change 464178 had a related patch set uploaded (by Krinkle; owner: Krinkle):
[operations/mediawiki-config@master] profiler: Prevent Xenon flushes from being able to fatal a request

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

Mentioned in SAL (#wikimedia-operations) [2018-10-09T02:41:05Z] <krinkle@deploy1001> Synchronized wmf-config/profiler.php: T176916 / T206092 - Ie86e88 (duration: 00m 56s)

Change 464178 merged by jenkins-bot:
[operations/mediawiki-config@master] profiler: Prevent flush from fataling a request

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

Mentioned in SAL (#wikimedia-operations) [2018-10-10T22:16:14Z] <krinkle@deploy1001> Synchronized wmf-config/arclamp.php: T206092 - If607ad (duration: 00m 48s)