Page MenuHomePhabricator

TransactionProfiler throws a "Expectation ..." on SqlBagOStuff::setMulti
Closed, DuplicatePublic

Description

MediaWiki	1.30.0-alpha (1ba29a5)
PHP	7.1.1 (apache2handler)
PostgreSQL	9.3.12
ICU	57.1
query-m: DELETE FROM 'X' WHERE ( keyname='X' ) [TRX#d5e6c9]
#0 ...\includes\libs\rdbms\TransactionProfiler.php(218): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writes', 'query-m: DELETE...')
#1 ...\includes\libs\rdbms\database\Database.php(1032): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: DELETE...', 1497512677.6, true, 0)
#2 ...\includes\libs\rdbms\database\Database.php(933): Wikimedia\Rdbms\Database->doProfiledQuery('DELETE FROM "ob...', 'DELETE /* SqlBa...', true, 'SqlBagOStuff::s...')
#3 ...\includes\libs\rdbms\database\Database.php(2208): Wikimedia\Rdbms\Database->query('DELETE FROM "ob...', 'SqlBagOStuff::s...')
#4 ...\includes\objectcache\SqlBagOStuff.php(373): Wikimedia\Rdbms\Database->replace('objectcache', Array, Array, 'SqlBagOStuff::s...')
#5 ...\includes\objectcache\SqlBagOStuff.php(388): SqlBagOStuff->setMulti(Array, 30)
#6 ...\includes\libs\objectcache\BagOStuff.php(545): SqlBagOStuff->set('mwmasterpg:mess...', 1, 30)
#7 ...\includes\libs\objectcache\BagOStuff.php(418): BagOStuff->add('mwmasterpg:mess...', 1, 30)
#8 [internal function]: BagOStuff->{closure}()
#9 ...\vendor\wikimedia\wait-condition-loop\src\WaitConditionLoop.php(92): call_user_func(Object(Closure))
#10 ...\includes\libs\objectcache\BagOStuff.php(429): Wikimedia\WaitConditionLoop->invoke()
#11 ...\includes\libs\objectcache\BagOStuff.php(472): BagOStuff->lock('mwmasterpg:mess...', 0, 30, 'MessageCache::g...')
#12 ...\includes\cache\MessageCache.php(762): BagOStuff->getScopedLock('mwmasterpg:mess...', 0, 30, 'MessageCache::g...')
#13 ...\includes\cache\MessageCache.php(420): MessageCache->getReentrantScopedLock('mwmasterpg:mess...', 0)
#14 ...\includes\cache\MessageCache.php(350): MessageCache->loadFromDBWithLock('en', Array, NULL)
#15 ...\includes\cache\MessageCache.php(991): MessageCache->load('en')
#16 ...\includes\cache\MessageCache.php(919): MessageCache->getMsgFromNamespace('Pagetitle', 'en')
#17 ...\includes\cache\MessageCache.php(888): MessageCache->getMessageForLang(Object(Language), 'pagetitle', true, Array)
#18 ...\includes\cache\MessageCache.php(828): MessageCache->getMessageFromFallbackChain(Object(Language), 'pagetitle', true)
#19 ...\includes\Message.php(1257): MessageCache->get('pagetitle', true, Object(Language))
#20 ...\includes\Message.php(842): Message->fetchMessage()
#21 ...\includes\Message.php(934): Message->toString('text')
#22 ...\includes\OutputPage.php(936): Message->text()
#23 ...\includes\OutputPage.php(983): OutputPage->setHTMLTitle(Object(Message))
#24 ...\includes\page\Article.php(464): OutputPage->setPageTitle('Main Page')
#25 ...\includes\actions\ViewAction.php(68): Article->view()
#26 ...\includes\MediaWiki.php(499): ViewAction->show()
#27 ...\includes\MediaWiki.php(293): MediaWiki->performAction(Object(Article), Object(Title))
#28 ...\includes\MediaWiki.php(862): MediaWiki->performRequest()
#29 ...\includes\MediaWiki.php(523): MediaWiki->main()
#30 ...\index.php(43): MediaWiki->run()
#31 {main}

Most likely relates to T154424.

Event Timeline

mwjames created this task.Jun 15 2017, 7:52 AM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJun 15 2017, 7:52 AM

Another exception:

query-m: INSERT INTO 'X' (keyname,value,exptime) VALUES ('X') [TRX#081e29]
#0 ...\includes\libs\rdbms\TransactionProfiler.php(225): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writeQueryTime', 'query-m: INSERT...', ' (actual: 30.80...')
#1 ...\includes\libs\rdbms\database\Database.php(1032): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: INSERT...', 1497513549.4375, true, 1)
#2 ...\includes\libs\rdbms\database\Database.php(933): Wikimedia\Rdbms\Database->doProfiledQuery('INSERT INTO "ob...', 'INSERT /* SqlBa...', true, 'SqlBagOStuff::s...')
#3 ...\includes\libs\rdbms\database\DatabasePostgres.php(643): Wikimedia\Rdbms\Database->query('INSERT INTO "ob...', 'SqlBagOStuff::s...', NULL)
#4 ...\includes\libs\rdbms\database\Database.php(2212): Wikimedia\Rdbms\DatabasePostgres->insert('"objectcache"', Array, 'SqlBagOStuff::s...')
#5 ...\includes\objectcache\SqlBagOStuff.php(373): Wikimedia\Rdbms\Database->replace('objectcache', Array, Array, 'SqlBagOStuff::s...')
#6 ...\includes\objectcache\SqlBagOStuff.php(388): SqlBagOStuff->setMulti(Array, 30)
#7 ...\includes\libs\objectcache\BagOStuff.php(545): SqlBagOStuff->set('mwmasterpg:mess...', 1, 30)
#8 ...\includes\libs\objectcache\BagOStuff.php(418): BagOStuff->add('mwmasterpg:mess...', 1, 30)
#9 [internal function]: BagOStuff->{closure}()
#10 ...\vendor\wikimedia\wait-condition-loop\src\WaitConditionLoop.php(92): call_user_func(Object(Closure))
#11 ...\includes\libs\objectcache\BagOStuff.php(429): Wikimedia\WaitConditionLoop->invoke()
#12 ...\includes\libs\objectcache\BagOStuff.php(472): BagOStuff->lock('mwmasterpg:mess...', 0, 30, 'MessageCache::g...')
#13 ...\includes\cache\MessageCache.php(762): BagOStuff->getScopedLock('mwmasterpg:mess...', 0, 30, 'MessageCache::g...')
#14 ...\includes\cache\MessageCache.php(420): MessageCache->getReentrantScopedLock('mwmasterpg:mess...', 0)
#15 ...\includes\cache\MessageCache.php(350): MessageCache->loadFromDBWithLock('en', Array, NULL)
#16 ...\includes\cache\MessageCache.php(991): MessageCache->load('en')
#17 ...\includes\cache\MessageCache.php(919): MessageCache->getMsgFromNamespace('Timezone-cest', 'en')
#18 ...\includes\cache\MessageCache.php(888): MessageCache->getMessageForLang(Object(Language), 'timezone-cest', true, Array)
#19 ...\includes\cache\MessageCache.php(828): MessageCache->getMessageFromFallbackChain(Object(Language), 'timezone-cest', true)
#20 ...\includes\Message.php(1257): MessageCache->get('timezone-cest', true, Object(Language))
#21 ...\includes\Message.php(982): Message->fetchMessage()
#22 ...\includes\MWTimestamp.php(190): Message->exists()
#23 ...\includes\parser\Parser.php(4510): MWTimestamp->getTimezoneMessage()
#24 ...\includes\parser\Parser.php(4482): Parser->pstPass2('[[Test::test]]\n...', Object(User))
#25 ...\includes\StubObject.php(113): Parser->preSaveTransform('[[Test::test]]\n...', Object(Title), Object(User), Object(ParserOptions))
#26 ...\includes\StubObject.php(139): StubObject->_call('preSaveTransfor...', Array)
#27 ...\includes\content\WikitextContent.php(140): StubObject->__call('preSaveTransfor...', Array)
#28 ...\includes\page\WikiPage.php(2038): WikitextContent->preSaveTransform(Object(Title), Object(User), Object(ParserOptions))
#29 ...\includes\api\ApiStashEdit.php(200): WikiPage->prepareContentForEdit(Object(WikitextContent), NULL, Object(User), 'text/x-wiki', false)
#30 ...\includes\api\ApiStashEdit.php(148): ApiStashEdit::parseAndStash(Object(WikiPage), Object(WikitextContent), Object(User), '')
#31 ...\includes\api\ApiMain.php(1578): ApiStashEdit->execute()
#32 ...\includes\api\ApiMain.php(545): ApiMain->executeAction()
#33 ...\includes\api\ApiMain.php(516): ApiMain->executeActionWithErrorHandling()
#34 ...\api.php(83): ApiMain->execute()
#35 {main}

@Krinkle As for the last stack trace, it happens on each edit and causes a significant lag during a save action.

@mwjames It seems you omitted the main warning message. The one that says "Expectation .. by .. not met ..".

Also nothing is thrown here, there is no PHP "exception". Rather it's a debug log message (severity=INFO) that is hidden by default and (for easier debugging) includes a manually created stack trace.

I'm inclined to merge this with T154424, since this violation itself is likely working as expected (assuming it is true that the write took as long as it claims). The bug, per T154424, is merely that transaction/query performance profiling should not apply to SqlBagOStuff.

Also nothing is thrown here, there is no PHP "exception". Rather it's a debug log message (severity=INFO) that is hidden by default and (for easier debugging) includes a manually created stack trace.

That might be true in the actual sense of an exception but unfortunately this has a significant cost and it appears on each save action and therefore no longer is something to ignore as it impacts editing practice (surely not WMF related) by a constant and unnecessary log output.

The bug, per T154424, is merely that transaction/query performance profiling should not apply to SqlBagOStuff.

I'm fine with that but just merging tasks into each other doesn't actually help on the root cause and there have been plenty of reports on this topic so just deferring it to another task doesn't make it go away.

Also nothing is thrown here, there is no PHP "exception". Rather it's a debug log message (severity=INFO) that is hidden by default and (for easier debugging) includes a manually created stack trace.

That might be true in the actual sense of an exception but unfortunately this has a significant cost and it appears on each save action and therefore no longer is something to ignore as it impacts editing practice (surely not WMF related) by a constant and unnecessary log output.

Are you referring to warnings end-users see, or the cost of writing to a file on the server-side?

or the cost of writing to a file on the server-side?

While testing Postgres the edit/save process took significantly longer before the GET request would return with the output after a save event and the debug log was written.

Normally, I would use redis but this time around for testing I just used the vanilla setup that comes with SqlBagOStuff out of the box hence the increased log output.

[caches] cluster: EmptyBagOStuff, WAN: mediawiki-main-default, stash: db-replicated, message: SqlBagOStuff, parser: SqlBagOStuff, session: SqlBagOStuff