Page MenuHomePhabricator
Create Task
Maniphest T95426

SiteStatsInit::edits and SiteStatsInit::articles query storm
Closed, ResolvedPublic
Actions

Description

S2 slaves were hit by a storm of these on svwiki:

SELECT /* SiteStatsInit::edits 127.0.0.1 */ COUNT(*) FROM revision LIMIT 1

Then minutes later a very similar storm of these:

SELECT /* SiteStatsInit::articles ... */ COUNT(DISTINCT page_id) FROM page, pagelinks WHERE page_namespace = '0' AND page_is_redirect = '0' AND (pl_from=page_id) LIMIT 1

The queries cam from wikiuser and various client IPs, implying they were not run from any maintenance script or job. Clients did include a lot of msnbot and googlebot, but not exclusively.

Both queries should be run asynchronously and cached somewhere (which based on IRC conversation between hoo/Nemo/aude, is actually the expected behavior).

Details

SubjectRepoBranchLines +/-
Use PoolCounter for SiteStats updatesmediawiki/coremaster+23 -12
Prevent SiteStats::loadAndLazyInit from reloading in $wgMiserModemediawiki/coremaster+3 -1
Customize query in gerrit

Related Objects

Event Timeline

• Springle created this task.Apr 8 2015, 1:25 PM
• Springle raised the priority of this task from to Needs Triage.
• Springle updated the task description. (Show Details)
• Springle added a project: MediaWiki-libs-Rdbms.
• Springle subscribed.
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptApr 8 2015, 1:25 PM
hoo subscribed.Apr 8 2015, 1:26 PM
Aklapper merged a task: T95421: Database error when trying to connect to NL wikipedia.Apr 8 2015, 1:36 PM
Aklapper mentioned this in T95421: Database error when trying to connect to NL wikipedia.
Aklapper added a subscriber: Mbch331.
Aklapper triaged this task as High priority.Apr 8 2015, 1:53 PM
gerritbot subscribed.Apr 8 2015, 1:54 PM

Change 202732 had a related patch set uploaded (by MaxSem):
Use PoolCounter for SiteStats updates

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

gerritbot added a project: Patch-For-Review.Apr 8 2015, 1:54 PM
He7d3r subscribed.Apr 8 2015, 2:01 PM
gerritbot added a comment.Apr 8 2015, 4:35 PM

Change 202766 had a related patch set uploaded (by Aaron Schulz):
Prevent SiteStats::loadAndLazyInit from reloading in $wgMiserMode

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

aaron subscribed.Apr 8 2015, 4:43 PM

Sample backtrace:

#0 /srv/mediawiki/php-1.25wmf23/includes/db/Database.php(1189): DatabaseBase->reportQueryError()
#1 /srv/mediawiki/php-1.25wmf23/includes/db/Database.php(1729): DatabaseBase->query()
#2 /srv/mediawiki/php-1.25wmf23/includes/db/Database.php(1397): DatabaseBase->select()
#3 /srv/mediawiki/php-1.25wmf23/includes/SiteStats.php(330): DatabaseBase->selectField()
#4 /srv/mediawiki/php-1.25wmf23/includes/SiteStats.php(378): SiteStatsInit->articles()
#5 /srv/mediawiki/php-1.25wmf23/includes/SiteStats.php(87): SiteStatsInit::doAllAndCommit()
#6 /srv/mediawiki/php-1.25wmf23/includes/SiteStats.php(54): SiteStats::loadAndLazyInit()
#7 /srv/mediawiki/php-1.25wmf23/includes/SiteStats.php(147): SiteStats::load()
#8 /srv/mediawiki/php-1.25wmf23/extensions/Scribunto/engines/LuaCommon/SiteLibrary.php(77): SiteStats::pages()
#9 /srv/mediawiki/php-1.25wmf23/extensions/Scribunto/engines/LuaCommon/LuaCommon.php(450): Scribunto_LuaSiteLibrary->register()
#10 /srv/mediawiki/php-1.25wmf23/extensions/Scribunto/engines/LuaCommon/LuaCommon.php(124): Scribunto_LuaEngine->instantiatePHPLibrary()
#11 /srv/mediawiki/php-1.25wmf23/extensions/Scribunto/engines/LuaCommon/LuaCommon.php(197): Scribunto_LuaEngine->load()
#12 /srv/mediawiki/php-1.25wmf23/extensions/Scribunto/engines/LuaCommon/LuaCommon.php(847): Scribunto_LuaEngine->getInterpreter()
#13 /srv/mediawiki/php-1.25wmf23/extensions/Scribunto/engines/LuaCommon/LuaCommon.php(864): Scribunto_LuaModule->getInitChunk()
#14 /srv/mediawiki/php-1.25wmf23/extensions/Scribunto/common/Hooks.php(113): Scribunto_LuaModule->invoke()
#15 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3768): ScribuntoHooks::invokeHook()
#16 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3502): Parser->callParserFunction()
#17 /srv/mediawiki/php-1.25wmf23/includes/parser/Preprocessor_Hash.php(1094): Parser->braceSubstitution()
#18 /srv/mediawiki/php-1.25wmf23/extensions/ParserFunctions/ParserFunctions_body.php(106): PPFrame_Hash->expand()
#19 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3768): ExtParserFunctions::ifObj()
#20 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3502): Parser->callParserFunction()
#21 /srv/mediawiki/php-1.25wmf23/includes/parser/Preprocessor_Hash.php(1094): Parser->braceSubstitution()
#22 /srv/mediawiki/php-1.25wmf23/extensions/ParserFunctions/ParserFunctions_body.php(104): PPFrame_Hash->expand()
#23 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3768): ExtParserFunctions::ifObj()
#24 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3502): Parser->callParserFunction()
#25 /srv/mediawiki/php-1.25wmf23/includes/parser/Preprocessor_Hash.php(1094): Parser->braceSubstitution()
#26 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3644): PPFrame_Hash->expand()
#27 /srv/mediawiki/php-1.25wmf23/includes/parser/Preprocessor_Hash.php(1094): Parser->braceSubstitution()
#28 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(3319): PPFrame_Hash->expand()
#29 /srv/mediawiki/php-1.25wmf23/includes/parser/Parser.php(634): Parser->replaceVariables()
#30 /srv/mediawiki/php-1.25wmf23/includes/api/ApiExpandTemplates.php(110): Parser->preprocess()
#31 /srv/mediawiki/php-1.25wmf23/includes/api/ApiMain.php(1037): ApiExpandTemplates->execute()
#32 /srv/mediawiki/php-1.25wmf23/includes/api/ApiMain.php(394): ApiMain->executeAction()
#33 /srv/mediawiki/php-1.25wmf23/includes/api/ApiMain.php(367): ApiMain->executeActionWithErrorHandling()
#34 /srv/mediawiki/php-1.25wmf23/api.php(88): ApiMain->execute()
#35 /srv/mediawiki/w/api.php(3): include()
#36 {main}

gerritbot added a comment.Apr 8 2015, 5:17 PM

Change 202766 merged by jenkins-bot:
Prevent SiteStats::loadAndLazyInit from reloading in $wgMiserMode

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

aaron mentioned this in rMWff88ba3c5ff6: Prevent SiteStats::loadAndLazyInit from reloading in $wgMiserMode.Apr 8 2015, 5:17 PM
Krinkle subscribed.Apr 8 2015, 5:28 PM
Liuxinyu970226 subscribed.Apr 9 2015, 2:34 AM
• Springle added a comment.Apr 9 2015, 4:36 AM

From IRC:

14:12 #wikimedia-operations: < MaxSem> springle, re that outage: is there a way to find out the contents of site_stats before that storm? i.e. was it empty or was there some bogus value?

S2 24h delayed replication on dbstore1001 is currently paused a few hours before the outage with binlogs (relay logs) up to an including the event. Do we still need to investigate this aspect, or does @aaron's stack trace and gerrit set above indicate we have the problem nailed?

matej_suchanek added projects: User-notice, Notice.Apr 10 2015, 12:29 PM
matej_suchanek set Security to None.
matej_suchanek moved this task from To Triage to In current Tech/News draft on the User-notice board.
matej_suchanek moved this task from Backlog to Triaged on the Notice board.
aaron added a comment.Apr 10 2015, 3:34 PM
In T95426#1193049, @Springle wrote:

From IRC:

14:12 #wikimedia-operations: < MaxSem> springle, re that outage: is there a way to find out the contents of site_stats before that storm? i.e. was it empty or was there some bogus value?

S2 24h delayed replication on dbstore1001 is currently paused a few hours before the outage with binlogs (relay logs) up to an including the event. Do we still need to investigate this aspect, or does @aaron's stack trace and gerrit set above indicate we have the problem nailed?

It might be worth seeing the last INSERT to the table to see if any thing particularly odd happened.

gpaumier moved this task from In current Tech/News draft to Recently announced in Tech/News on the User-notice board.Apr 10 2015, 10:23 PM
• MZMcBride subscribed.Apr 10 2015, 11:14 PM
• Springle added a comment.Apr 13 2015, 7:33 PM

dbstore1001 stopped ~18 hours before the outage:

wmf dbstore1001 3306 root svwiki> select from_unixtime(1428431995);
+---------------------------+
| from_unixtime(1428431995) |
+---------------------------+
| 2015-04-07 18:39:55       |
+---------------------------+
1 row in set (0.25 sec)
wmf dbstore1001 3306 root svwiki> select * from site_stats;
+-----------+----------------+----------------+------------------+----------------+----------+-----------+-----------------+
| ss_row_id | ss_total_views | ss_total_edits | ss_good_articles | ss_total_pages | ss_users | ss_images | ss_active_users |
+-----------+----------------+----------------+------------------+----------------+----------+-----------+-----------------+
|         1 |        1052264 |       29691046 |          1961398 |        4573696 |   431103 |         0 |            3094 |
+-----------+----------------+----------------+------------------+----------------+----------+-----------+-----------------+

Lots of UPDATEs during the next 18h:

UPDATE /* SiteStatsUpdate::tryDBUpdateInternal ... */  `site_stats` SET ss_total_edits=ss_total_edits+1

The next INSERT was at 2015-04-08 12:36:57, after the outage began, when several dozen of these ran nigh simultaneously:

INSERT /* SiteStatsInit::refresh ... */ INTO `site_stats` (ss_row_id,ss_total_edits,ss_good_articles,ss
_total_pages,ss_users,ss_images) VALUES ('1','29682848','1961414','4573781','431159','0') ON DUPLICATE KEY UPDATE
 ss_row_id = '1',ss_total_edits = '29682848',ss_good_articles = '1961414',ss_total_pages = '4573781',ss_users = '
431159',ss_images = '0';

We can use the S2 master binlog to find the last insert before the outage, but whatever it was resulted in the above site_stats state (which looks right?).

aaron added a comment.Apr 13 2015, 7:44 PM

I wonder if the pending stats delta key in memcached for one type (articles) fell out of cache or was re-hashed elsewhere but not another one (pages). The sanity check code might see them being mismatched and would trigger a rebuild. In any case, that will not happen now, and the crons will fix it eventually afaik.

gpaumier moved this task from Triaged to Archive on the Notice board.Apr 16 2015, 5:17 PM
gpaumier moved this task from Recently announced in Tech/News to Already announced/Archive on the User-notice board.Apr 17 2015, 3:23 PM
Aklapper added a comment.Jun 16 2015, 2:10 PM
In T95426#1204355, @aaron wrote:

the crons will fix it eventually afaik

So should this task be closed? Or is there anything left to sort out (with lower priority than currently)?

aaron closed this task as Resolved.Jun 16 2015, 2:28 PM
aaron claimed this task.
gerritbot added a comment.Jun 19 2015, 11:41 PM

Change 202732 abandoned by MaxSem:
Use PoolCounter for SiteStats updates

Reason:
Superseded by other stuff.

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

Liuxinyu970226 unsubscribed.Jun 20 2015, 7:36 AM
Krinkle mentioned this in T36156: SiteStatsInit::refresh() triggered inappropriately, caused downtime.Jun 27 2019, 10:13 PM
Ladsgroup edited projects, added User-notice-archive; removed User-notice.Aug 13 2022, 1:53 PM
Restricted Application added a project: Performance-Team. · View Herald TranscriptAug 13 2022, 1:53 PM
Content licensed under Creative Commons Attribution-ShareAlike (CC BY-SA) 4.0 unless otherwise noted; code licensed under GNU General Public License (GPL) 2.0 or later and other open source licenses. By using this site, you agree to the Terms of Use, Privacy Policy, and Code of Conduct. · Wikimedia Foundation · Privacy Policy · Code of Conduct · Terms of Use · Disclaimer · CC-BY-SA · GPL