See https://en.wikipedia.org/wiki/Wikipedia:Village_pump_(technical)#CSD_backlog? for details.
Basically, the magic word {{PAGESINCATEGORY}} returns far higher numbers for this category (at the time of writing this: 319) then viewing the category does (at the time of writing this: 10) and no one can figure out why.
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Open | None | T30599 Deadlock tracking bug (tracking) | |||
| Open | None | T221795 Refactor Category::refreshCounts logic to a job and simplify | |||
| Resolved | PRODUCTION ERROR | Anomie | T195397 {{PAGESINCATEGORY}} returns incorrect value on en-wiki Category:Candidates for speedy deletion |
I manually refreshed the count for just this category. Let's see if it gets bad again.
Some data:
All this makes me suspect that the deleteLinks jobs aren't running in a timely manner. @mobrovac or @Pchelolo, can you tell if the enwiki deleteLinks jobs are backlogged in the new EventBus job queue, consistent with these timestamps?
BTW, the discrepancy between 432 extra "count" and 718 broken categorylinks could be explained by the fact that various code paths recount the category whenever the saved "count" is less than 100 and the recount ignores the broken categorylinks. So until the "count" manages to exceed 100 the recounts would keep correcting for the jobs not running, and bad "count" would only pile up once the recounts are no longer triggered.
All this makes me suspect that the deleteLinks jobs aren't running in a timely manner. @mobrovac or @Pchelolo, can you tell if the enwiki deleteLinks jobs are backlogged in the new EventBus job queue, consistent with these timestamps?
Hm... Interesting that the last deleteLinks submitted into kafka I see is from 2018-05-31T15:21:05+00:00 for User:Lothar_Hakelberg/Benutzernavigation on commons.
The graphs for rates of this particular one looks very suspicious as well. I will come back with more data tomorrow EU morning.
I've been looking into this for a while now, but with no luck - the deleteLinks job just doesn't get posted and I couldn't locate any errors in JobQueue or mediawiki logs..
It looks like with HHVM we don't do LinksDeletionUpdates as a job, I was mistaken. Sorry for having you look.
Digging into this deeper, I see an increase in database deadlocks at the end of April, roughly correlating with the deployment of 1.32.0-wmf.1. Specifically, I'm looking at log messages like these:
2018-06-11 07:46:24 [Wx4oxQpAEMIAAL0WdSoAAADD] mw1313 commonswiki 1.32.0-wmf.7 DBQuery ERROR: Category::refreshCounts 10.64.48.23 1213 Deadlock found when trying to get lock; try restarting transaction (10.64.48.23) UPDATE `category` SET
cat_pages = '2',cat_subcats = '0',cat_files = '2' WHERE cat_title = 'Duplicate' {"db_server":"10.64.48.23","db_name":"commonswiki","db_user":"wikiuser","method":"Wikimedia\\Rdbms\\Database::makeQueryException","errno":1213,"error":"Deadlock found when trying to get lock; try restarting transaction (10.64.48.23)","sql1line":"UPDATE `category` SET cat_pages = '2',cat_subcats = '0',cat_files = '2' WHERE cat_title = 'Duplicate'","fname":"Category::refreshCounts"}2018-06-11 14:13:40 [Wx6DjQpAAE4AAC30QoIAAABQ] mw1283 commonswiki 1.32.0-wmf.7 DBQuery ERROR: LinksDeletionUpdate::batchDeleteByPK 10.64.48.23 1213 Deadlock found when trying to get lock; try restarting transaction (10.64.48.23) DELETE FROM `categorylinks` WHERE (cl_from = '65163833' AND cl_to = '1966_coins') OR (cl_from = '65163833' AND cl_to = 'CC-BY-SA-4.0') OR (cl_from = '65163833' AND cl_to = 'Commemorative_10_Mark_coins_of_East_Germany') OR (cl_from = '65163833' AND cl_to = 'Deletion_requests_June_2018') OR (cl_from = '65163833' AND cl_to = 'Karl_Friedrich_Schinkel') OR (cl_from = '65163833' AND cl_to = 'Self-published_work') {"db_server":"10.64.48.23","db_name":"commonswiki","db_user":"wikiuser","method":"Wikimedia\\Rdbms\\Database::makeQueryException","errno":1213,"error":"Deadlock found when trying to get lock; try restarting transaction (10.64.48.23)","sql1line":"DELETE FROM `categorylinks` WHERE (cl_from = '65163833' AND cl_to = '1966_coins') OR (cl_from = '65163833' AND cl_to = 'CC-BY-SA-4.0') OR (cl_from = '65163833' AND cl_to = 'Commemorative_10_Mark_coins_of_East_Germany') OR (cl_from = '65163833' AND cl_to = 'Deletion_requests_June_2018') OR (cl_from = '65163833' AND cl_to = 'Karl_Friedrich_Schinkel') OR (cl_from = '65163833' AND cl_to = 'Self-published_work')","fname":"LinksDeletionUpdate::batchDeleteByPK"}The second is what would be causing this bug: when the error occurs in LinksDeletionUpdate, the whole transaction has to be rolled back and the update doesn't get retried.
| Date | in LinksDeletionUpdate | in refreshCounts |
|---|---|---|
| 04-20 | 0 | 0 |
| 04-21 | 0 | 0 |
| 04-22 | 0 | 0 |
| 04-23 | 0 | 2 |
| 04-24 | 0 | 2 |
| 04-25 | 0 | 24 |
| 04-26 | 4 | 22 |
| 04-27 | 46 | 196 |
| 04-28 | 180 | 240 |
| 04-29 | 380 | 160 |
| 04-30 | 260 | 272 |
Breaking log messages since June 1 down by wiki,
| Wiki | in LinksDeletionUpdate | in refreshCounts |
|---|---|---|
| enwiki | 3162 | 1782 |
| commonswiki | 1002 | 1822 |
| zhwiki | 0 | 162 |
| kowiki | 8 | 98 |
| ruwiki | 14 | 0 |
| ptwiki | 0 | 8 |
| dewiki | 0 | 6 |
| viwiki | 0 | 2 |
| thwiki | 2 | 0 |
| plwiki | 0 | 2 |
| idwiki | 0 | 2 |
| huwiki | 0 | 2 |
| arwiki | 0 | 2 |
I see two changes in 1.32.0-wmf.1 that seem like they might be relevant:
The first looks more suspicious to me. It causes Category::refreshCounts() to be called much more often, and for categories that probably aren't empty. On a wiki with heavy deletion activity in a particular category (such as enwiki's Category:Candidates for speedy deletion, which exists specifically to hold pages to be deleted), this seems like it could easily wind up with the refresh's transaction deadlocking with transactions that are trying to delete rows in the category being refreshed.
The second being the cause would require that there be some difference in locking behavior between these two SQL queries, with the second somehow locking more rows to cause the deadlocks:
SELECT COUNT(*) AS `rowcount` FROM (SELECT 1 FROM `categorylinks`,`page` WHERE cl_to = 'Foobar' AND (page_id = cl_from) LOCK IN SHARE MODE) `tmp_count`
SELECT COUNT(*) AS `pages`,COUNT( (CASE WHEN page_namespace = '14' THEN 1 ELSE NULL END) ) AS `subcats`,COUNT( (CASE WHEN page_namespace = '6' THEN 1 ELSE NULL END) ) AS `files` FROM `categorylinks`,`page` WHERE cl_to = 'Foobar' AND (page_id = cl_from) LIMIT 1 LOCK IN SHARE MODE
I don't have any explanation for why the orphaned categorylinks rows on enwiki are only showing up since 2018-06-01.
Change 439809 had a related patch set uploaded (by Aaron Schulz; owner: Aaron Schulz):
[mediawiki/core@master] Reduce frequency of refreshCounts() calls in LinksDeletionUpdate
Change 439946 had a related patch set uploaded (by Anomie; owner: Anomie):
[mediawiki/core@master] Category: Lock the category row before the categorylinks rows
Change 439946 merged by jenkins-bot:
[mediawiki/core@master] Category: Lock the category row before the categorylinks rows
Change 440053 had a related patch set uploaded (by Aaron Schulz; owner: Anomie):
[mediawiki/core@wmf/1.32.0-wmf.8] Category: Lock the category row before the categorylinks rows
Change 440053 merged by jenkins-bot:
[mediawiki/core@wmf/1.32.0-wmf.8] Category: Lock the category row before the categorylinks rows
Mentioned in SAL (#wikimedia-operations) [2018-06-13T14:15:56Z] <anomie@deploy1001> Synchronized php-1.32.0-wmf.8/includes/Category.php: Backporting fix for T195397 ([[gerrit:440053]]) (duration: 01m 00s)
This was known to me. This points me I should be more vocal about Wikimedia-production-error I find in the future. Related: T165675
This looks likely to be resolved now: the change was backported to wmf.8, and no deadlocks related to this task have been logged since that went out.
I also went through and recounted most categories that were logged as having these deadlocks. I skipped some that have more than 10000 rows, as categories with too many rows take too long to recount. Note that "10000" is an arbitrary limit, I picked a round number that seemed large enough that count inaccuracy wouldn't make that much difference and small enough that the queries completed quickly.
The categories not recounted were:
Please don't run count(*) + LOCK IN SHARE MODE on the masters or you will create contention. This run was conflicting with HTMLCacheUpdates and created a bunch of fatals: https://grafana.wikimedia.org/dashboard/db/mediawiki-graphite-alerts?orgId=1&panelId=2&fullscreen&from=1529061367667&to=1529069430000
It looks like that locking was added in 2008 in rMW80a5874828c2: This is a schema change. It's only a table creation, but the table must be… so the counts wouldn't be inaccurate due to concurrent deletions. Normally the method is only called when the category is expected to have very few rows in the first place.
I see most issues arose from updates to things like 'CC-BY-SA-4.0', and 'Self-published_work', which may have dozens of millions of members.
Change 439809 merged by jenkins-bot:
[mediawiki/core@master] Reduce frequency of refreshCounts() calls in LinksDeletionUpdate