Maniphest T219702

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

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()

Related Objects

Mentioned In: T236595: Error importing module to outreach wiki
T225340: A database query error occurred when transwiki importing a page from zhwikipedia to zhwikiversity
Blog Post: Production Excellence #10: April 2019
Mentioned Here: T225340: A database query error occurred when transwiki importing a page from zhwikipedia to zhwikiversity

Event Timeline

Wang_Qiliang created this task.Mar 30 2019, 12:39 PM

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

MarcoAurelio added a project: Wikimedia-production-error.Mar 30 2019, 1:14 PM

Reedy added a project: MediaWiki-Core-Snapshots.Mar 30 2019, 9:36 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

• Marostegui subscribed.Apr 1 2019, 8:47 AM

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

• Marostegui added a project: MediaWiki-libs-Rdbms.Apr 3 2019, 10:09 AM

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 Platform Engineering 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.

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.

Krinkle moved this task from Untriaged to Mar 2019 / 1.33wmf20-23 on the Wikimedia-production-error board.Apr 5 2019, 11:09 PM

• kchapman edited projects, added Platform Team Legacy; removed Platform Engineering.Apr 8 2019, 8:01 PM

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.

In T219702#5095296, @kchapman wrote:

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 :-)

In T219702#5095296, @kchapman wrote:

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.

Krinkle mentioned this in Blog Post: Production Excellence #10: April 2019.May 31 2019, 7:21 PM

ArielGlenn moved this task from Backlog to Snapshot import on the MediaWiki-Core-Snapshots board.Jun 13 2019, 6:52 AM

Looks like we had another case reported at T225340: A database query error occurred when transwiki importing a page from zhwikipedia to zhwikiversity

ArielGlenn merged a task: T225340: A database query error occurred when transwiki importing a page from zhwikipedia to zhwikiversity.Jun 14 2019, 5:35 PM

ArielGlenn added a subscriber: 94rain.

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.

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.

Krinkle moved this task from Untriaged to Meta on the MediaWiki-Core-Revision-backend board.Aug 1 2019, 7:56 PM

• mmodell changed the subtype of this task from "Bug Report" to "Production Error".Aug 28 2019, 11:07 PM

Krinkle added a project: Wikimedia-database-issue.Oct 8 2019, 8:38 PM

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

Krinkle edited projects, added Platform Engineering; removed Platform Team Legacy (Watching / External).Oct 11 2019, 11:41 PM

Anomie moved this task from Inbox to Triage Meeting Inbox on the Platform Engineering board.Oct 15 2019, 3:15 PM

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

Aklapper mentioned this in T236595: Error importing module to outreach wiki.Oct 26 2019, 5:14 PM

WDoranWMF moved this task from Inbox to Backlog on the Platform Team Workboards (Clinic Duty Team) board.Oct 31 2019, 8:54 PM

• AMooney added a project: Platform Engineering (Icebox).Mar 13 2020, 1:24 PM

CCicalese_WMF removed a project: Platform Team Workboards (Clinic Duty Team).Mar 13 2020, 1:32 PM

Krinkle moved this task from Mar 2019 / 1.33wmf20-23 to Older on the Wikimedia-production-error board.Apr 8 2020, 10:28 PM

TerraCodes unsubscribed.Apr 8 2020, 11:47 PM

Shizhao moved this task from Backlog to MediaWiki core on the Chinese-Sites board.Jul 6 2020, 1:13 AM

Krinkle merged a task: T270487: Import error: Lock wait timeout exceeded.Apr 9 2022, 8:45 PM

Krinkle added subscribers: MF-Warburg, jhsoby, Urbanecm.

Krinkle removed a project: Platform Engineering (Icebox).Aug 17 2023, 3:56 PM

Krinkle added a project: Unstewarded-production-error.

Page import can fail with "Lock wait timeout exceeded" in WikiPage::insertOnOpen, MediumPublicPRODUCTION ERRORActions

Description

Details

Related Objects

Event Timeline

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