Page MenuHomePhabricator

Page import can fail with "Lock wait timeout exceeded" in WikiPage::insertOn
Open, NormalPublic

Description

message
WikiPage::insertOn	10.64.48.35	1205	Lock wait timeout exceeded; try restarting transaction (10.64.48.35)	INSERT IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('250','हिंदुई_साहित्य_का_इतिहास.pdf/269','','0','1','0.119844444395','20191008114512','0','0')

I tried to import w:zh:注意力不足過動症的非藥物治療 but to see these outputs:

导入失败:A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? Query: INSERT IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('0','注意力不足過動症的非藥物治療','','0','1','0.715036974696','20190330123638','0','0') Function: WikiPage::insertOn Error: 1205 Lock wait timeout exceeded; try restarting transaction (10.64.32.136)

Details

Request ID
XZx2xgpAME0AABsXnFMAAABF
Request URL
/w/index.php?title=Special:Import&action=submit
Stack Trace
#2 /srv/mediawiki/php-1.34.0-wmf.25/includes/libs/rdbms/database/Database.php(2139): Wikimedia\Rdbms\Database->query('INSERT IGNORE I...', 'WikiPage::inser...')
#3 /srv/mediawiki/php-1.34.0-wmf.25/includes/libs/rdbms/database/DBConnRef.php(68): Wikimedia\Rdbms\Database->insert('`page`', Array, 'WikiPage::inser...', 'IGNORE')
#4 /srv/mediawiki/php-1.34.0-wmf.25/includes/libs/rdbms/database/DBConnRef.php(371): Wikimedia\Rdbms\DBConnRef->__call('insert', Array)
#5 /srv/mediawiki/php-1.34.0-wmf.25/includes/page/WikiPage.php(1355): Wikimedia\Rdbms\DBConnRef->insert('page', Array, 'WikiPage::inser...', Array)
#6 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/ImportableOldRevisionImporter.php(62): WikiPage->insertOn(Object(Wikimedia\Rdbms\DBConnRef))
#7 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/WikiRevision.php(616): ImportableOldRevisionImporter->import(Object(WikiRevision))
#8 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/WikiImporter.php(366): WikiRevision->importOldRevision()
#9 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/WikiImporter.php(501): WikiImporter->importRevision(Object(WikiRevision), Object(WikiImporter))
#10 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/WikiImporter.php(941): WikiImporter->revisionCallback(Object(WikiRevision))
#11 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/WikiImporter.php(860): WikiImporter->processRevision(Array, Array)
#12 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/WikiImporter.php(802): WikiImporter->handleRevision(Array)
#13 /srv/mediawiki/php-1.34.0-wmf.25/includes/import/WikiImporter.php(606): WikiImporter->handlePage()
#14 /srv/mediawiki/php-1.34.0-wmf.25/includes/specials/SpecialImport.php(227): WikiImporter->doImport()
#15 /srv/mediawiki/php-1.34.0-wmf.25/includes/specials/SpecialImport.php(109): SpecialImport->doImport()
#16 /srv/mediawiki/php-1.34.0-wmf.25/includes/specialpage/SpecialPage.php(575): SpecialImport->execute(NULL)
#17 /srv/mediawiki/php-1.34.0-wmf.25/includes/specialpage/SpecialPageFactory.php(611): SpecialPage->run(NULL)
#18 /srv/mediawiki/php-1.34.0-wmf.25/includes/MediaWiki.php(296): MediaWiki\Special\SpecialPageFactory->executePath(Object(Title), Object(RequestContext))
#19 /srv/mediawiki/php-1.34.0-wmf.25/includes/MediaWiki.php(900): MediaWiki->performRequest()
#20 /srv/mediawiki/php-1.34.0-wmf.25/includes/MediaWiki.php(527): MediaWiki->main()
#21 /srv/mediawiki/php-1.34.0-wmf.25/index.php(44): MediaWiki->run()

Event Timeline

Restricted Application added subscribers: Cosine02, Aklapper. · View Herald TranscriptMar 30 2019, 12:39 PM

stack trace from the first error in the series:

Expectation (writeQueryTime <= 1) by MediaWiki::main not met (actual: 15.677501916885):
query-m: INSERT IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('X') [TRX#6b6fbf]
#0 /srv/mediawiki/php-1.33.0-wmf.23/includes/libs/rdbms/TransactionProfiler.php(252): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writeQueryTime', 'query-m: INSERT...', 15.677501916885)
#1 /srv/mediawiki/php-1.33.0-wmf.23/includes/libs/rdbms/database/Database.php(1317): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: INSERT...', 1553949398.4402, true, -1)
#2 /srv/mediawiki/php-1.33.0-wmf.23/includes/libs/rdbms/database/Database.php(1198): Wikimedia\Rdbms\Database->attemptQuery('INSERT IGNORE I...', 'INSERT /* WikiP...', true, 'WikiPage::inser...')
#3 /srv/mediawiki/php-1.33.0-wmf.23/includes/libs/rdbms/database/Database.php(2123): Wikimedia\Rdbms\Database->query('INSERT IGNORE I...', 'WikiPage::inser...')
#4 /srv/mediawiki/php-1.33.0-wmf.23/includes/libs/rdbms/database/DBConnRef.php(49): Wikimedia\Rdbms\Database->insert('`page`', Array, 'WikiPage::inser...', 'IGNORE')
#5 /srv/mediawiki/php-1.33.0-wmf.23/includes/libs/rdbms/database/DBConnRef.php(329): Wikimedia\Rdbms\DBConnRef->__call('insert', Array)
#6 /srv/mediawiki/php-1.33.0-wmf.23/includes/page/WikiPage.php(1345): Wikimedia\Rdbms\DBConnRef->insert('page', Array, 'WikiPage::inser...', 'IGNORE')
#7 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/ImportableOldRevisionImporter.php(62): WikiPage->insertOn(Object(Wikimedia\Rdbms\DBConnRef))
#8 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/WikiRevision.php(595): ImportableOldRevisionImporter->import(Object(WikiRevision))
#9 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/WikiImporter.php(367): WikiRevision->importOldRevision()
#10 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/WikiImporter.php(504): WikiImporter->importRevision(Object(WikiRevision), Object(WikiImporter))
#11 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/WikiImporter.php(941): WikiImporter->revisionCallback(Object(WikiRevision))
#12 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/WikiImporter.php(860): WikiImporter->processRevision(Array, Array)
#13 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/WikiImporter.php(802): WikiImporter->handleRevision(Array)
#14 /srv/mediawiki/php-1.33.0-wmf.23/includes/import/WikiImporter.php(609): WikiImporter->handlePage()
...

Immediately afterwards we see 'Lock wait timeout exceeded; try restarting transaction'. See https://logstash.wikimedia.org/goto/3c0fca8b693751a2a1579df6ea3ce610

Tendril shows a couple more of those inserts around that time that are slow: https://tendril.wikimedia.org/report/slow_queries_checksum?checksum=e75aa74cb532e53483222e47ba181943&host=db1078&user=&schema=&hours=48

@Wang_Qiliang Did you retry the import, and if so, with what results? Sometimes these are one-time glitches.

Leaderboard triaged this task as Unbreak Now! priority.Apr 3 2019, 10:10 AM
Leaderboard added a subscriber: Leaderboard.

I'm getting the same error on en.wikibooks:

Import failed: A database query error has occurred. Did you forget to run your application's database schema updater after upgrading? Query: INSERT IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('108','List_of_Australian_AM_radio_stations','','0','1','0.896837776405','20190403100623','0','0') Function: WikiPage::insertOn Error: 1205 Lock wait timeout exceeded; try restarting transaction (10.64.32.136)
Restricted Application added subscribers: Liuxinyu970226, TerraCodes. · View Herald TranscriptApr 3 2019, 10:10 AM
Leaderboard renamed this task from A database query error has occurred when importing pages from zhwp to zhwikiversity to Database query errors occurring when importing.Apr 3 2019, 10:11 AM

Is this an UBN? Does it happen all the time?

It's happened twice for me in the last hour when trying to import just the latest revision (when trying to import everything, it times out as usual).

Let me add Core Platform Team to see if the can help out here or know who would be responsible for looking into this.
It is basically something holding that lock for long and the transaction dies after waiting.

Leaderboard lowered the priority of this task from Unbreak Now! to Normal.Apr 4 2019, 8:52 PM

The issue no longer occurs to me. Waiting for a response from original poster (@Wang_Qiliang) before closing.

I found one thing, there was an import started at 10:05:12,thread id 459590083, first entry

INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('108','List_of_Australian_AM_radio_stations','','0','1','0.524657413337','20190403100512','0','0')

and this set of inserts and so on finished at 10:08:25 (the COMMIT at the end of all of the statements). That overlaps with the second transaction at 10:06:23 that you mention above in T219702#5081099 and that timed out waiting for the lock presumably held by the first transaction.

These imports all start with a first statement of an INSERT into the page table via WikiPage::insertOn, where the timestamp of the page looks like it reflects the time the transaction started, so that would confirm the overlap for me.

@Marostegui Does that seem right to you?

Looking at the logs I see:

BEGIN
/*!*/;
# at 440371356
#190403 10:05:12 server id 171974792  end_log_pos 440371384     Intvar
SET INSERT_ID=406249/*!*/;
# at 440371384
#190403 10:05:12 server id 171974792  end_log_pos 440371733     Query   thread_id=459590083     exec_time=0     error_code=0
use `enwikibooks`/*!*/;
SET TIMESTAMP=1554285912/*!*/;
INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('108','List_of_Australian_AM_radio_stations','','0','1','0.524657413337','20190403100512','0','0')
/*!*/;
# at 440371733
#190403 10:05:12 server id 171974792  end_log_pos 440371761     Intvar

Lots of other operations
and then:

COMMIT/*!*/;
# at 441080534
#190403 10:08:25 server

So it is possible that that query caused the lock indeed

I don't find any other import for the first reporter's title (mysqlbinlog -d zhwikiversity db1078-bin.000375 | grep WikiPage::insertOn | grep 力 gives an empty list) so that may have a different cause, but we don't know if that was a repeated issue or a one-time event.

This was one of a string of several imports. Here are the beginnings of the successful import transactions from around that time period:

INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('0','北海道道1131号美呗停车场线','','0','1','0.949136402090','20190330122313','0','0')
INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('0','北海道道1121号月形幌向线','','0','1','0.652885195497','20190330122320','0','0')
INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('0','北海道道1065號夕張厚真線','','0','1','0.552713291421','20190330122327','0','0')
INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('0','北海道道1056号江别长沼线','','0','1','0.950335385292','20190330122333','0','0')
INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('0','北海道道920号幌内汤内线','','0','1','0.755278554463','20190330122340','0','0')
INSERT /* WikiPage::insertOn  */ IGNORE INTO `page` (page_namespace,page_title,page_restrictions,page_is_redirect,page_is_new,page_random,page_touched,page_latest,page_len) VALUES ('0','北海道道875号多度志一已线','','0','1','0.468333029950','20190330122348','0','0')

Not sure we will find much based on that.

kchapman added a subscriber: kchapman.

I'm not seeing a specific thing for Core Platform to do at the moment, but if the issue still exists we are happy to take a look.

I'm not seeing a specific thing for Core Platform to do at the moment, but if the issue still exists we are happy to take a look.

I tagged it mostly to see if the team can help figuring out where this could be coming from.
There is nothing specific for the team to fix, but was kinda a shout for help :-)

Krinkle added a subscriber: Krinkle.

I'm not seeing a specific thing for Core Platform to do at the moment, but if the issue still exists we are happy to take a look.

The error comes from the revision backend that CPT mainly looks after. Specifically the WikiPage::insert method which deals with creation of new articles.

This specific report started with a user creating an article by using Special:Import. However, the fact that WikiPage::insert can timeout fatally might not be specific to Special:Import and may suggest a general issue with lock contention in WikiPage::insert, which if unaddressed may lead to wider issues of users being unable to create articles.

I took a look through Logstash for database errors that involve `Function: WikiPage::insertOn, and found they have already affected users who are creating articles by other means as well.

Including regular page creations via the edit page (on dewiki), semi-automatic page creation for translations (metawiki), page creations via the API (commonswiki), creating a page with VisualEditor (azwiki), and more.

As mentioned in T225340#5259447 , should I retry the import to find out whether more old revisions will show up?

Yes, I think that's a fine idea. Just one retry in an hour, let's say, no more than that.

94rain added a comment.EditedJun 20 2019, 9:42 AM

With more than ten attempts, I've successfully imported all the revisions of 邪典電影列表, but somehow the log only showed the last attempt (imported 11 revisions).
(https://zh.wikiversity.org/wiki/Special:日志?type=import&user=&page=邪典電影列表)
You may further investigate into this.

OK, this means there's nothing in the specific revisions themselves, and it's probably MediaWiki deadlocking itself.

mmodell changed the subtype of this task from "Bug Report" to "Production Error".Aug 28 2019, 11:07 PM
Krinkle renamed this task from Database query errors occurring when importing to Page import can fail with "Lock wait timeout exceeded" in WikiPage::insertOn.Tue, Oct 8, 8:41 PM
Krinkle set Request URL to /w/index.php?title=Special:Import&action=submit.
Krinkle set Request ID to XZx2xgpAME0AABsXnFMAAABF.
Krinkle updated the task description. (Show Details)
Krinkle edited Stack Trace. (Show Details)
Krinkle edited Stack Trace. (Show Details)

Added stack trace from recent sample. Still seen in Logstash.

daniel added a subscriber: daniel.

Going by the comments, this sounds like imports causing lock retention on the page table. Needs further investigation.