After fixing T102229: MessageGroupStats::clear performs the same deletion on all mediawiki servers, locking itself, there are still occasional spikes about "Lock wait timeout exceeded; try restarting transaction". It would be a good thing to isolate the remaining causes and fix them completely.
Description
Description
Details
Details
Customize query in gerrit
| Status | Subtype | Assigned | Task | ||
|---|---|---|---|---|---|
| Resolved | None | T195760 Language Annual Plan 2018-2019 | |||
| Resolved | Nikerabbit | T204818 Language tools maintenance intervention: Improve the quality of translations for Translate extension | |||
| Invalid | None | T30499 [DO NOT USE] 1205: Lock wait timeout exceeded; try restarting transaction (tracking) | |||
| Resolved | PRODUCTION ERROR | Nikerabbit | T134252 Avoid "Lock wait timeout exceeded" from MessageGroupStats::clear |
Event Timeline
Comment Actions
That's the thing that should be investigated. Logstash does not tell what is holding the lock. I see entries for both MessageGroupStats::clear and MessageGroupStats::queueUpdates and some slow query logs from hhvm (which might be slow because they were waiting for the lock?). What is clear is that they usually come in bursts.
Comment Actions
Is it possible to paste the full details of some errors as on T102229? Knowing the url, sql1line and timestamp would be of great help.
Comment Actions
Curiously enough, for the past week there is only one message. Maybe this has been solved after all?
2016-05-09T16:56:00.000Z
SlowTimer [11614ms] at runtime/ext_mysql: slow query: DELETE /* MessageGroupStats::clear <username> */ FROM translate_groupstats WHERE tgs_group = 'page-Wikidata:List of properties/Geographical feature' AND tgs_lang = 'hu'
Going further back in time, here are the contents for one group messages happening at the same time.
2016-05-01T13:17:38.615Z
{"mobileview":{"normalizedtitle":"Wikimedia Highlights, May 2014/pl","lastmodified":"2016-02-18T18:55:08Z","revision":15360487,"languagecount":0,"displaytitle":"Aktualności Wikimedia - Maj 2014","id":5004653,"image":{"file":"ZoomProof Wikisource tool concept.ogv","width":1112,"height":672},"thumb":{"url":"//upload.wikimedia.org/wikipedia/commons/thumb/8/83/ZoomProof_Wikisource_tool_concept.ogv/1024px--ZoomProof_Wikisource_tool_concept.ogv.jpg","width":1024,"height":619},"sections":[],"protection":[],"editable":true}}<!DOCTYPE html><html><head><title>Internal Server Error</title></head><body><h1>Internal Server Error</h1><p>A database query error has occurred.<br />
Function: MessageGroupStats::queueUpdates<br />
Error: 1205 Lock wait timeout exceeded; try restarting transaction (10.64.16.30)<br />
[snip more html]
MessageGroupStats::queueUpdates 10.64.16.30 1205 Lock wait timeout exceeded; try restarting transaction (10.64.16.30) INSERT IGNORE INTO translate_groupstats (tgs_group,tgs_lang,tgs_total,tgs_translated,tgs_fuzzy,tgs_proofread) VALUES ('page-Wikimedia Highlights, May 2014','ar','54','10','0','8')
{"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/Database.php","line":901,"function":"reportQueryError","class":"DatabaseBase","type":"->","args":["string","integer","string","string","boolean"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/Database.php","line":1464,"function":"query","class":"DatabaseBase","type":"->","args":["string","string"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/extensions/Translate/utils/MessageGroupStats.php","line":477,"function":"insert","class":"DatabaseBase","type":"->","args":["string","array","string","string"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/extensions/Translate/utils/MessageGroupStats.php","line":492,"function":"Closure$MessageGroupStats::queueUpdates","args":["DatabaseMysqli","string"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/Database.php","line":2482,"function":"Closure$MessageGroupStats::runWithLock","args":[]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/Database.php","line":2693,"function":"runOnTransactionIdleCallbacks","class":"DatabaseBase","type":"->","args":[]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/loadbalancer/LoadBalancer.php","line":1055,"function":"commit","class":"DatabaseBase","type":"->","args":["string","string"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/loadbalancer/LBFactory.php","line":206,"function":"commitMasterChanges","class":"LoadBalancer","type":"->","args":["string"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/loadbalancer/LBFactoryMulti.php","line":411,"function":"Closure$LBFactory::forEachLBCallMethod","args":["LoadBalancer","string","array"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/loadbalancer/LBFactory.php","line":209,"function":"forEachLB","class":"LBFactoryMulti","type":"->","args":["Closure$LBFactory::forEachLBCallMethod;1204592053","array"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/db/loadbalancer/LBFactory.php","line":250,"function":"forEachLBCallMethod","class":"LBFactory","type":"->","args":["string","array"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/MediaWiki.php","line":561,"function":"commitMasterChanges","class":"LBFactory","type":"->","args":["string","array"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/api/ApiMain.php","line":478,"function":"preOutputCommit","class":"MediaWiki","type":"::","args":["DerivativeContext"]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/includes/api/ApiMain.php","line":434,"function":"executeActionWithErrorHandling","class":"ApiMain","type":"->","args":[]}, {"file":"/srv/mediawiki/php-1.27.0-wmf.22/api.php","line":83,"function":"execute","class":"ApiMain","type":"->","args":[]}, {"file":"/srv/mediawiki/w/api.php","line":3,"function":"include","args":["string"]}
SlowTimer [15888ms] at runtime/ext_mysql: slow query: INSERT /* MessageGroupStats::queueUpdates 10.64.0.16 */ IGNORE INTO translate_groupstats (tgs_group,tgs_lang,tgs_total,tgs_translated,tgs_fuzzy,tgs_proofread) VALUES ('page-Wikimedia Highlights, May 2014','ar','54','10','0','8')
Comment Actions
There is group of 6 messages just 8 seconds before this one:
MessageGroupStats::clear 10.64.16.30 1205 Lock wait timeout exceeded; try restarting transaction (10.64.16.30) DELETE FROM translate_groupstats WHERE tgs_group = 'page-Wikimedia Highlights, May 2014' AND tgs_lang = 'ar'
This one is also via api.php but has a referer. Looks like someone was translating at the same time.
Comment Actions
WMF Logstash reported this fatal error 48 times in the last 30 days, including on versions 1.32.0-wmf.19 and 1.32.0-wmf.22, and on multiple wikis (wikidata.org, mediawiki.org, meta.wikimedia.org).
Recent sample:
A database query error has occurred. ### Query: DELETE FROM `translate_groupstats` WHERE tgs_group = 'page-###||###' AND tgs_lang = 'hi' Function: MessageGroupStats::clear Error: 1205 Lock wait timeout exceeded; try restarting transaction (10.192.32.103)
trace
#3 /srv/mediawiki/php-1.32.0-wmf.22/extensions/Translate/utils/MessageGroupStats.php(168): Wikimedia\Rdbms\Database->delete(string, string, string) #4 /srv/mediawiki/php-1.32.0-wmf.22/extensions/Translate/TranslateEditAddons.php(230): MessageGroupStats::clear(MessageHandle) #5 /srv/mediawiki/php-1.32.0-wmf.22/includes/Hooks.php(174): TranslateEditAddons::onSave(WikiPage, User, WikitextContent, string, integer, NULL, NULL, integer, Revision, Status, boolean, integer) #6 /srv/mediawiki/php-1.32.0-wmf.22/includes/Hooks.php(202): Hooks::callHook(string, array, array, NULL) #7 /srv/mediawiki/php-1.32.0-wmf.22/includes/Storage/PageUpdater.php(1209): Hooks::run(string, array) #8 /srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/Database.php(3746): Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate(Wikimedia\Rdbms\DatabaseMysqli, string) #9 /srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/DBConnRef.php(49): Wikimedia\Rdbms\Database->doAtomicSection(string, Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate;3070) #10 /srv/mediawiki/php-1.32.0-wmf.22/includes/libs/rdbms/database/DBConnRef.php(529): Wikimedia\Rdbms\DBConnRef->__call(string, array) #11 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/AtomicSectionUpdate.php(35): Wikimedia\Rdbms\DBConnRef->doAtomicSection(string, Closure$MediaWiki\Storage\PageUpdater::getAtomicSectionUpdate;3070) #12 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/DeferredUpdates.php(268): AtomicSectionUpdate->doUpdate() #13 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/DeferredUpdates.php(214): DeferredUpdates::runUpdate(AtomicSectionUpdate, Wikimedia\Rdbms\LBFactoryMulti, string, integer) #14 /srv/mediawiki/php-1.32.0-wmf.22/includes/deferred/DeferredUpdates.php(130): DeferredUpdates::execute(array, string, integer) #15 /srv/mediawiki/php-1.32.0-wmf.22/includes/MediaWiki.php(607): DeferredUpdates::doUpdates(string, integer) #16 /srv/mediawiki/php-1.32.0-wmf.22/includes/api/ApiMain.php(548): MediaWiki::preOutputCommit(DerivativeContext) #17 /srv/mediawiki/php-1.32.0-wmf.22/includes/api/ApiMain.php(502): ApiMain->executeActionWithErrorHandling() #18 /srv/mediawiki/php-1.32.0-wmf.22/api.php(87): ApiMain->execute()
Comment Actions
The eventual fix should take care of both translate_messagegroupstats and translate_reviews (See T195293: 503 error attempting to open multiple projects (Wikipedia and meta wiki are loading very slowly) ).
Currently leading proposal is to use Pool Counter to avoid stampedes. There should also be another look at the code to see if there are any possible changes to avoid deadlocks or unnecessary work.
Comment Actions
Change 468319 had a related patch set uploaded (by Nikerabbit; owner: Nikerabbit):
[mediawiki/extensions/Translate@master] Reduce contention on translate_messagegroupstats
Comment Actions
Change 468319 merged by jenkins-bot:
[mediawiki/extensions/Translate@master] Reduce contention on translate_messagegroupstats
Comment Actions
Change 470618 had a related patch set uploaded (by Nikerabbit; owner: Nikerabbit):
[mediawiki/extensions/Translate@master] Fix message group stats not upating
Comment Actions
This is quite nasty issue to slip into an MLEB release... I'm wondering whether we should do a follow-up.
Comment Actions
Change 470618 merged by jenkins-bot:
[mediawiki/extensions/Translate@master] Fix message group stats not updating
Comment Actions
Change 474659 had a related patch set uploaded (by Nikerabbit; owner: Nikerabbit):
[mediawiki/extensions/Translate@master] Special:PageTranslation: Fix bunch of warnings with encourage&discourage
Comment Actions
Logstash no longer shows results with "Lock wait timeout exceeded" AND MessageGroupStats so the original problem at least seems to be resolved.
Comment Actions
Change 474659 merged by jenkins-bot:
[mediawiki/extensions/Translate@master] Special:PageTranslation: Fix bunch of warnings with encourage&discourage
Comment Actions
@Nikerabbit I see numerous WARNINGS in logstash - https://logstash.wikimedia.org/app/kibana#/discover?_g=h@44136fa&_a=h@59a810c:
Expectation (masterConns <= 0) by MediaWiki::restInPeace not met (actual: 1):
[connect to 10.64.0.205 (mediawikiwiki)]
#0 /srv/mediawiki/php-1.33.0-wmf.6/includes/libs/rdbms/TransactionProfiler.php(165): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.33.0-wmf.6/includes/libs/rdbms/loadbalancer/LoadBalancer.php(761): Wikimedia\Rdbms\TransactionProfiler->recordConnection()
#2 /srv/mediawiki/php-1.33.0-wmf.6/includes/libs/rdbms/database/DBConnRef.php(46): Wikimedia\Rdbms\LoadBalancer->getConnection()
#3 /srv/mediawiki/php-1.33.0-wmf.6/includes/libs/rdbms/database/DBConnRef.php(604): Wikimedia\Rdbms\DBConnRef->__call()
#4 /srv/mediawiki/php-1.33.0-wmf.6/extensions/Translate/utils/MessageGroupStats.php(553): Wikimedia\Rdbms\DBConnRef->lock()
#5 /srv/mediawiki/php-1.33.0-wmf.6/includes/deferred/MWCallableUpdate.php(34): Closure$MessageGroupStats::withLock()
#6 /srv/mediawiki/php-1.33.0-wmf.6/includes/deferred/DeferredUpdates.php(270): MWCallableUpdate->doUpdate()
#7 /srv/mediawiki/php-1.33.0-wmf.6/includes/deferred/DeferredUpdates.php(216): DeferredUpdates::runUpdate()
#8 /srv/mediawiki/php-1.33.0-wmf.6/includes/deferred/DeferredUpdates.php(140): DeferredUpdates::execute()
#9 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(905): DeferredUpdates::doUpdates()
#10 /srv/mediawiki/php-1.33.0-wmf.6/includes/MediaWiki.php(728): MediaWiki->restInPeace()
#11 (): Closure$MediaWiki::doPostOutputShutdown()
#12 {main}Any concerns about such warnings? Are they related to the patches in this task?