Page MenuHomePhabricator
Create Task
Maniphest T167941

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

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.

Related Objects

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
mwjames added a comment.Jun 15 2017, 8:01 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}
mwjames added a subscriber: Krinkle.Jun 15 2017, 8:48 AM

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

Krinkle added a comment.Jun 15 2017, 2:18 PM

@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.

mwjames added a comment.Jun 15 2017, 2:37 PM

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.

Krinkle added a comment.Jun 15 2017, 2:38 PM
In T167941#3351486, @mwjames wrote:

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?

Krinkle closed this task as a duplicate of T154424: TransactionProfiler should not apply to SqlBagOStuff.Jun 15 2017, 2:39 PM
mwjames added a comment.Jun 15 2017, 2:43 PM

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.

mwjames added a comment.Jun 15 2017, 2:48 PM

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
mwjames mentioned this in T154424: TransactionProfiler should not apply to SqlBagOStuff.Jun 15 2017, 2:56 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 · Credits