Follow-up for T262391 and it's non-public counterpart T262240.
In T262391#6449590 et seq, @Bawolff proposed to limit concurrency of DPL queries by two ways: a query cache (which makes DPL to not do the same work XY times) and a pool counter that makes DPL to not work at more than X things at once.
Both should make DPL somehow safer (but not faster), which is always a bonus.
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Open | None | T263220 Limit concurrency of DPL queries | |||
| Resolved | Security | Urbanecm | T266775 Stalls on db1075 (s3) replica db |
Change 626268 had a related patch set uploaded (by Urbanecm; owner: Brian Wolff):
[mediawiki/extensions/intersection@master] Attempt to add a query cache to DPL
More specificly its meant to prevent query pileups. The common case of a query pileup in DPL being a template with a dpl on it being used on tens of thousands of pages, all being refreshed at once, which the short cache will eliminate. The pool counter solution as a fall back should eliminate any other situation of DPL query pileup.
I have closed the non public task that tracked the initial impact of DPL on ruwikinews (T262240).
As far as I know the patches that @Bawolff put together are still pending to be merged (https://gerrit.wikimedia.org/r/c/mediawiki/extensions/intersection/+/626268/ https://gerrit.wikimedia.org/r/c/mediawiki/extensions/intersection/+/626796/)
Can we get someone to review and merge them? I guess that'd be Platform Engineering or Performance-Team?
Maybe we can double check if reviewing, merging and deploying https://gerrit.wikimedia.org/r/626796 is realistically possible before the weekend? And maybe also https://gerrit.wikimedia.org/r/c/mediawiki/extensions/intersection/+/626268/ which I guess is more complex?
Platform Engineering can you bump this on your list of reviews priorities if possible?
Note. The former one depends on the latter one, so we would need to review 626268 first anyway :/.
To help with reviewing 626268, I enabled memcached caching as MainCacheType and set wgDLPQueryCacheTime to 30. Then, I created Category:A with handful of pages via for i in {0..45}; do echo -e "Testing page $i\n\n[[Category:A]]" | php /home/urbanecm/unsynced/gerrit/mediawiki/core/maintenance/edit.php --wiki=bwiki Test_page_$i --user Martin_Urbanec; done. Then, I set $wgDebugLogFile = "/var/www/wikis/logs/debug-{$wgDBname}.log"; to see all possible MediaWiki logs.
Then, I opened tail -f /var/www/wikis/logs/debug-bwiki.log | grep -i DBQuery | grep -i DynamicPageListHooks in my terminal, and opened Template:DPL_query for editing in my browser. Then, I pasted the following to the template:
<DynamicPageList> category = A count = 5 order = descending addfirstcategorydate = true </DynamicPageList>
Then, I previewed it once, and confirmed that [DBQuery] DynamicPageListHooks::processQuery - Template:DPL_query [0s] localhost: SELECT page_namespace,page_title,c1.cl_timestamp FROM page` INNER JOIN categorylinks c1 ON ((page_id = c1.cl_from) AND (c1.cl_to='A')) WHERE page_is_redirect = 0 ORDER BY c1.cl_timestamp DESC LIMIT 5` appears only once in the logs I opened previously in my terminal. Then, I previewed it several times, and it didn't generate any more queries. Then, I waited 30 seconds (wgDLPQueryCacheTime on my machine), and it did query the DB again.
Marked with V+1 on Gerrit, as it seems to do what it is advertised to :).
Change 637499 had a related patch set uploaded (by Urbanecm; owner: Urbanecm):
[operations/mediawiki-config@master] Set wgDLPQueryCacheTime to 120 at all wikis
Change 626268 merged by jenkins-bot:
[mediawiki/extensions/intersection@master] Attempt to add a query cache to DPL
Change 637059 had a related patch set uploaded (by Urbanecm; owner: Brian Wolff):
[mediawiki/extensions/intersection@wmf/1.36.0-wmf.14] Attempt to add a query cache to DPL
Change 637499 merged by jenkins-bot:
[operations/mediawiki-config@master] Set wgDLPQueryCacheTime to 120 at all wikis
Mentioned in SAL (#wikimedia-operations) [2020-10-29T15:15:02Z] <urbanecm@deploy1001> Synchronized wmf-config/InitialiseSettings.php: 19c5aff02c20812c56b8abdcc0ed530393010193: Set wgDLPQueryCacheTime to 120 at all wikis (T263220) (duration: 00m 59s)
Change 637059 merged by jenkins-bot:
[mediawiki/extensions/intersection@wmf/1.36.0-wmf.14] Attempt to add a query cache to DPL
Mentioned in SAL (#wikimedia-operations) [2020-10-29T15:22:42Z] <urbanecm@deploy1001> Synchronized php-1.36.0-wmf.14/extensions/intersection/: 483c3bceb926ac6a2cfc40112fb9b4f0671fef72: Attempt to add a query cache to DPL (T263220) (duration: 00m 58s)
This is no longer UBN, please feel free to consider it resolved/declined based on my comments on the subtask.
I think we should still review and merge https://gerrit.wikimedia.org/r/c/mediawiki/extensions/intersection/+/626796, so this should stay open IMO.
Change 626796 merged by jenkins-bot:
[mediawiki/extensions/intersection@master] Add an option to limit DPL concurrency with pool counter
Good point. Do you mind uploading a patch please? I can deploy in the nearest window :).
Change 645994 had a related patch set uploaded (by Brian Wolff; owner: Brian Wolff):
[operations/mediawiki-config@master] Add PoolCounter settings for DPL
Config patch for review & deployment, bumping to clinic duty.
Note that @Bawolff used to be staff - that doesn't make him immune to mistakes, but it's safe to assume that he generally knows what he's doing in the config :)
Change 645994 merged by jenkins-bot:
[operations/mediawiki-config@master] Add PoolCounter settings for DPL
Mentioned in SAL (#wikimedia-operations) [2020-12-10T19:15:22Z] <catrope@deploy1001> Synchronized wmf-config/PoolCounterSettings.php: Add PoolCounter settings for DPL (T263220) (duration: 01m 05s)
Change 647637 had a related patch set uploaded (by Catrope; owner: Catrope):
[operations/mediawiki-config@master] Revert "Add PoolCounter settings for DPL"
Change 647637 merged by jenkins-bot:
[operations/mediawiki-config@master] Revert "Add PoolCounter settings for DPL"
Mentioned in SAL (#wikimedia-operations) [2020-12-10T19:24:43Z] <catrope@deploy1001> Synchronized wmf-config/PoolCounterSettings.php: Revert PoolCounter settings for DPL (T263220) (duration: 01m 03s)
@Urbanecm noticed errors in the logs that looked like Pool key 'nowait:dpl-query:enwikinews' (DPL): Error reading from pool counter server 10.64.0.151., and asked me to revert
I've tried to get this live with Catrope in today Morning B&C window. However, this triggered about 1300 of error messages that looked like Pool key 'nowait:dpl-query:enwikinews' (DPL): Error reading from pool counter server 10.64.0.151. I asked Catrope to revert, as I didn't see a similar error message in the logs:
[urbanecm@mwlog1001 /srv/mw-log]$ grep 'reading from pool' poolcounter.log | head -n 3 2020-12-10 19:10:35 [X9JyqwpAAC4AACHyDIkAAABJ] mwdebug1002 ruwikinews 1.36.0-wmf.21 poolcounter INFO: Pool key 'nowait:dpl-query:ruwikinews' (DPL): Error reading from pool counter server 10.64.0.151. 2020-12-10 19:11:02 [X9JyxgpAAC4AAHW57dMAAABF] mwdebug1002 ruwikinews 1.36.0-wmf.21 poolcounter INFO: Pool key 'nowait:dpl-query:ruwikinews' (DPL): Error reading from pool counter server 10.64.0.151. 2020-12-10 19:11:09 [X9JyzQpAAC4AAHW57fUAAABI] mwdebug1002 ruwikinews 1.36.0-wmf.21 poolcounter INFO: Pool key 'nowait:dpl-query:ruwikinews' (DPL): Error reading from pool counter server 10.64.0.151. [urbanecm@mwlog1001 /srv/mw-log]$ grep 'reading from pool' poolcounter.log | wc -l 1056 [urbanecm@mwlog1001 /srv/mw-log]$ grep 'reading from pool' poolcounter.log | grep -v dpl | head [urbanecm@mwlog1001 /srv/mw-log]$
@Bawolff Could you have a look and advice, please?
Huh. That's not the error i was expecting if the limit was too low. That sounds like something was wrong with poolcounter generally.
I can't even see where that error is reported. Searching for "Error reading" doesn't bring up anything useful, nor can I find anything in the relevant code path calling info() on a logger.
@daniel Grep for poolcounter-read-error, you'll find https://gerrit.wikimedia.org/g/mediawiki/extensions/PoolCounter/+/4f4851e5f5c9ecf497848f50a89d16ee1f0b18f0/includes/PoolCounter_Client.php#73. It is possible that PoolCounter client somehow logs the status's exit code, if fatal. I can't find where that gets called, but that's where I found that error message.
Oh right, in the extension. I was looking in core.
But anyway... that's an odd failure mode. This basically means that the service killed the connection, right? Or could it be a read timeout?
It's odd indeed, odd enough to rollback it and pause to debate about "why this happens".
https://www.php.net/manual/en/function.fgets.php says " If an error occurs, false is returned.", so I think it can be any kind of an error, which obviously makes it harder to debug.
Do we have logs of what is happening on the other side? I'm not familiar with the code of the poolcounter daemon. Time to ping @tstarling I guess...
The problem happened again - see T287362. Could this task be reviewed in terms of priority?
Given that the underlying problem that this change might help with has already caused multiple full outages (all wikis affected) in the past year alone and the extension is deployed on quite a few wiki, I'd like to ask this to be looked into again for the near-term. Raising priority to 'high'. Would this be in scope for PET's Clinic Duty? How can SRE help?
Thanks for the comment here, @mark. The last part pending _should_ be a re-deployment of https://gerrit.wikimedia.org/r/c/operations/mediawiki-config/+/645994.
I tried to deploy that patch some time ago with @Catrope, and we rollbacked it, because errors like T263220#6683178 started to appear. I'm not a poolcounter expert, so I!m unable to help more with figuring out why it happened -- hopefully the information in my comment above are enough for someone to follow-up (maybe SREs have a poolcounter expert in the team?).
Alternatively, I can try to re-deploy it, and see if same errors happen -- maybe it was a temporary failure only.
Hope this helps.
Change 708051 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[operations/mediawiki-config@master] Revert \"Revert \"Add PoolCounter settings for DPL\"\"
@Urbanecm I'm on clinic duty this week and just so happen to have PoolCounter experience so let's find a time to pair on this.
@Bawolff I think you wrote the comment at https://gerrit.wikimedia.org/r/c/operations/mediawiki-config/+/645994/2/wmf-config/PoolCounterSettings.php#87 I think that suggests to reduce/tune if errors the values of 'workers'/'maxqueue' (not the timeout) in sync, but the comment is not 100% clear to me. Could you confirm that is the intention?
I will send an amend or a followup patch with clearer wording if you confirm that is the case, we don't have to think a lot if eventually we end up under the stress of an outage. E.g.:
// Note, this uses nowait:., so 'timeout' must always be 0. // 'worker' and 'maxqueue' can be tuned, but they should be equal to each other. // E.g. In the event DPL is causing DB problems, decrease both 'worker' AND 'maxqueue' to 2.
Change 708051 merged by jenkins-bot:
[operations/mediawiki-config@master] Revert \"Revert \"Add PoolCounter settings for DPL\"\"
Change 708148 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[operations/mediawiki-config@master] DPL PoolCounter setting: Fix class name
Change 708148 merged by jenkins-bot:
[operations/mediawiki-config@master] DPL PoolCounter setting: Fix class name
Yes. Timeout must always be 0 (since its inside the general parser lock and those are the poolcounter rules)
Change 708154 had a related patch set uploaded (by Urbanecm; author: Urbanecm):
[operations/mediawiki-config@master] Revert DPL poolcounter setting
Change 708154 merged by jenkins-bot:
[operations/mediawiki-config@master] Revert DPL poolcounter setting
@Urbanecm and I (plus lurker @majavah :)) spent an hour today trying to roll this out with mediocre success, but not enough confidence for a full rollout. We enabled the poolcounter config and disabled the query cache on mwdebug2001 and tested against https://en.wikinews.org/wiki/Chili_Finger_Incident with purges and page previews.
As with before, there were some mwdebug2001 enwikinews 1.37.0-wmf.15 poolcounter INFO: Pool key 'nowait:dpl-query:enwikinews' (DPL): Error reading from pool counter server 10.192.0.132. errors occasionally. It was inconsistent though and I don't think either of us had a sense of how bad the impact would be in real traffic.
This error corresponds to the fgets() call returning false: https://gerrit.wikimedia.org/g/mediawiki/extensions/PoolCounter/+/1c596b7b84c0f39fe8f7a5740d8e8c7975a379c4/includes/Client.php#76 https://www.php.net/manual/en/function.fgets.php says "If there is no more data to read in the file pointer, then false is returned. If an error occurs, false is returned." AFAICT, there's no way to get the actual error.
The other suspicious thing that was a decent amount of:
ACQ4ME nowait:dpl-query:enwikinews 25 25 0 which got a LOCKED reply, but then there was never a follow-up RELEASE. The page did load, so it's not like the query just timed out either...
And then weird stuff like
2021-07-26 18:49:41 [e385ffa1-a838-4b8b-bd2e-21dfdf0c61c6] mwdebug2001 enwikinews 1.37.0-wmf.15 wfDebug DEBUG: Sending pool counter command: ACQ4ME nowait:dpl-query:enwikinews 25 25 0 2021-07-26 18:49:41 [e385ffa1-a838-4b8b-bd2e-21dfdf0c61c6] mwdebug2001 enwikinews 1.37.0-wmf.15 wfDebug DEBUG: Got pool counter response: LOCKED 2021-07-26 18:49:41 [e385ffa1-a838-4b8b-bd2e-21dfdf0c61c6] mwdebug2001 enwikinews 1.37.0-wmf.15 wfDebug DEBUG: Sending pool counter command: RELEASE
which is missing the RELEASED response.
And of course, there were some requests that looked just fine, going through the full ACQ4ME nowait:dpl-query:enwikinews 25 25 0 -> LOCKED & RELEASE -> RELEASED flow.
I also tried sending the commands manually with nc and it all worked as expected.
It's unclear to me whether this is a poolcounter bug (worth working on and investigating further) or whether it's an issue in DPL (probably not worth working on).
bawolff and I discussed this a bit more yesterday and think that something is probably going wrong with nowait: / nested locks. In theory poolcounterd lets you hold up to 4 locks at once, but MediaWiki enforces that all locks after the first are "nowait" and have a timeout of 0. It's unclear if this requirement is actually a good thing since it causes problems elsewhere, like if you're parsing a page that transcludes Special:Contributions, which has its own PoolCounter lock.
Change 710138 had a related patch set uploaded (by Legoktm; author: Legoktm):
[mediawiki/core@master] poolcounter: Allow holding multiple timeout locks
Half a year later, does someone plan to pick up https://gerrit.wikimedia.org/r/c/710138 , or what is left to do in this open high prio ticket? Thanks.