Perf data from mw1234: https://phabricator.wikimedia.org/P7755

What I briefly observed yesterday night during the outage was:

• On ill-behaving HHVMs, threads kept getting in deadlocks and using 100% of a core waiting on said locks
• Given we have a request timeout of 60 seconds, it seemed like servers would recover from the ill condition, but they'd get back to deadlocks as soon as traffic came back to them
• I didn't check the size of the bytecode cache databases to see if that exploded. If that's the case, I might want to purge it today.

So, we tried to redeploy the code on the mwdebug servers today, and I load tested both servers with ab before and after the deployment of the code.

Overall:

• no cpu spikes were noticed apart from normal request-related ones
• no notable performance difference was noticed when parsing a mildly complex page (enwiki's Australia page) at medium (-c 5) and high (-c 10) concurrency (remember the mwdebug servers are 1-vcpu VMs)

This, together with the behaviour from yesterday and the perf data collected seems to suggest that something went wrong on a portion of the hhvm hosts because of a particular state they were in. This is not a satisfactory answer but is frankly the only explanation I have given I can't seem to reproduce the high cpu usage with timeouts.

I don't see this as a blocker to try to redeploy the train on monday.

In T208549#4716470, @Joe wrote:

I don't see this as a blocker to try to redeploy the train on monday.

Current plan is to roll forward the mwdebug servers again at 18:00UTC Monday. If after some prodding those servers do not exhibit the behavior described here, to roll 1.33.0-wmf.2 out to all wikis on all servers shortly thereafter.

A bunch of new messages are getting tidied and going through remex now ( https://gerrit.wikimedia.org/r/#/q/topic:deprecate-wgtidy ) -- although that *shouldn't* cause problems, here are a couple of wild theories:

1. MessageCache is missing somehow ( 4b1db1190bb8f2a115c6a81a5ee487b7d18cd303 ) and tying up CPU (but I'm pretty sure the misses would show in logs). Rolling back would cause misses on the updated messages so "not solve the issue".
2. ParserCache is missing somehow ( 58abac2d1489cdfaaf2ffdf2f9e1214509760b31 ) but I'm pretty sure that would show up in analytics. Same thing, roll back could cause misses of the previous misses.
3. Some system message is triggering some weird infinite-loop bug in Remex. Of course, remex has been used for tidy in all article content for months now, but I'm always ready to be surprised. If there's a specific URL which triggers the CPU hog behavior, that would be a big clue. But wouldn't explain why rolling back didn't help.
4. It's not my fault at all. (I like this one the best, but it doesn't help you fine folks in ops any.) ;)

AFAIK none of the parser/tidy related code has any locking so I'm guessing I'm off the hook for this problem, which seems to be a deadlock. But I figured I'd still offer some wild ideas just in case they are helpful by chance.

In T208549#4716336, @Joe wrote:

• I didn't check the size of the bytecode cache databases to see if that exploded. If that's the case, I might want to purge it today.

Did you end up purging the bytecode cache? If so, was it before you redeployed to mwdebug?

In T208549#4716528, @cscott wrote:

A bunch of new messages are getting tidied and going through remex now ( https://gerrit.wikimedia.org/r/#/q/topic:deprecate-wgtidy ) -- although that *shouldn't* cause problems, here are a couple of wild theories:

1. MessageCache is missing somehow ( 4b1db1190bb8f2a115c6a81a5ee487b7d18cd303 ) and tying up CPU (but I'm pretty sure the misses would show in logs). Rolling back would cause misses on the updated messages so "not solve the issue".

Seems to be there:

thcipriani@mwdebug1001:~$ grep -i -A1 'for the same reason' /srv/mediawiki/php-1.33.0-wmf.2/includes/cache/MessageCache.php                        // For the same reason, tidy the output!
                        $this->mParserOptions->setTidy( true );

2. ParserCache is missing somehow ( 58abac2d1489cdfaaf2ffdf2f9e1214509760b31 ) but I'm pretty sure that would show up in analytics. Same thing, roll back could cause misses of the previous misses.

Also seems like it's there

thcipriani@mwdebug1001:~$ grep -A3 'if any of this changes as' /srv/mediawiki/php-1.33.0-wmf.2/includes/parser/ParserOptions.php                      
                        // *UPDATE* ParserOptions::matches() if any of this changes as needed
                        self::$defaults = [
                                'dateformat' => null,
                                'tidy' => true,

3. Some system message is triggering some weird infinite-loop bug in Remex. Of course, remex has been used for tidy in all article content for months now, but I'm always ready to be surprised. If there's a specific URL which triggers the CPU hog behavior, that would be a big clue. But wouldn't explain why rolling back didn't help.

We haven't been able to find any url to trigger as yet, unfortunately :(

4. It's not my fault at all. (I like this one the best, but it doesn't help you fine folks in ops any.) ;)

AFAIK none of the parser/tidy related code has any locking so I'm guessing I'm off the hook for this problem, which seems to be a deadlock. But I figured I'd still offer some wild ideas just in case they are helpful by chance.