Page MenuHomePhabricator

TransactionProfiler should not apply to SqlBagOStuff
Closed, ResolvedPublic

Description

MediaWiki 1.29.0-alpha (54381ead)
PHP	5.6.8 (apache2handler)
MySQL	5.6.24
ICU	54.1

Issue

[DBConnection] Connected to database 0 at 'localhost'.
[DBPerformance] Expectation (masterConns <= 0) by MediaWiki::main not met:
[connect to localhost (mw-master)]
#0 ...\includes\libs\rdbms\TransactionProfiler.php(160): TransactionProfiler->reportExpectationViolated('masterConns', '[connect to loc...')
#1 ...\includes\libs\rdbms\loadbalancer\LoadBalancer.php(590): TransactionProfiler->recordConnection('localhost', 'mw-master', true)
#2 ...\includes\objectcache\SqlBagOStuff.php(191): LoadBalancer->getConnection(-2)
#3 ...\includes\objectcache\SqlBagOStuff.php(272): SqlBagOStuff->getDB(0)
#4 ...\includes\objectcache\SqlBagOStuff.php(250): SqlBagOStuff->getMulti(Array)
#5 ...\includes\objectcache\SqlBagOStuff.php(246): SqlBagOStuff->getWithToken('mw-master:smw:s...', NULL, 0)
#6 ...\includes\libs\objectcache\BagOStuff.php(185): SqlBagOStuff->doGet('mw-master:smw:s...', 0)
#7 ...\vendor\onoi\cache\src\MediaWikiCache.php(87): BagOStuff->get('mw-master:smw:s...')
#8 ...\vendor\onoi\cache\src\CompositeCache.php(85): Onoi\Cache\MediaWikiCache->contains('mw-master:smw:s...')
#9 ...\vendor\onoi\blob-store\src\BlobStore.php(150): Onoi\Cache\CompositeCache->contains('mw-master:smw:s...')
#10 ...\extensions\SemanticMediaWiki\src\TransientStatsdCollector.php(102): Onoi\BlobStore\BlobStore->read('608db4223df9921...')
#11 ...\extensions\SemanticMediaWiki\src\CachedQueryResultPrefetcher.php(152): SMW\TransientStatsdCollector->getStats()
#12 ...\extensions\SemanticMediaWiki\src\MediaWiki\Specials\Admin\SupplementaryLinksActionHandler.php(143): SMW\CachedQueryResultPrefetcher->getStats()
#13 ...\extensions\SemanticMediaWiki\src\MediaWiki\Specials\Admin\SupplementaryLinksActionHandler.php(63): SMW\MediaWiki\Specials\Admin\SupplementaryLinksActionHandler->outputQueryCacheStatistics()
#14 ...\extensions\SemanticMediaWiki\src\MediaWiki\Specials\SpecialAdmin.php(92): SMW\MediaWiki\Specials\Admin\SupplementaryLinksActionHandler->doOutputStatistics()
#15 ...\includes\specialpage\SpecialPage.php(522): SMW\MediaWiki\Specials\SpecialAdmin->execute(NULL)
#16 ...\includes\specialpage\SpecialPageFactory.php(576): SpecialPage->run(NULL)
#17 ...\includes\MediaWiki.php(283): SpecialPageFactory::executePath(Object(Title), Object(RequestContext))
#18 ...\includes\MediaWiki.php(851): MediaWiki->performRequest()
#19 ...\includes\MediaWiki.php(512): MediaWiki->main()
#20 ...\index.php(43): MediaWiki->run()

SMW\MediaWiki\Specials\SpecialAdmin contains a doesWrites, yet SqlBagOStuff->doGet is reported with a "Expectation (masterConns <= 0) by MediaWiki::main".

/**
 * {@inheritDoc}
 */
public function doesWrites() {
	return true;
}

One should expect to read from SqlBagOStuff without a "Expectation (masterConns <= 0) by MediaWiki::main" being thrown.

Questions

  • Why does a simple SqlBagOStuff::doGet throws a violation?
  • Why does a SpecialPage activity in general throws a TransactionProfiler violation since one can expect to read from the DB?
  • How to resolve this issue under the premise that one has to read some data from either the DB or the Cache?

Event Timeline

mwjames created this task.Jan 2 2017, 2:19 PM
Restricted Application added a subscriber: Aklapper. · View Herald TranscriptJan 2 2017, 2:19 PM
mwjames updated the task description. (Show Details)Jan 2 2017, 2:21 PM
Legoktm added a subscriber: Legoktm.

Why does a simple SqlBagOStuff::doGet throws a violation?

It shouldn't. In SqlBagOStuff:getDB there's:

				// Use a blank trx profiler to ignore expections as this is a cache
				$info['trxProfiler'] = new TransactionProfiler();
				$db = Database::factory( $type, $info );

but that only applies if you manually specify servers, so we need to extend that logic to the default too.

Given the following message [0], are we going to address (which implicitly means solve) this with 1.29?

[0] https://lists.wikimedia.org/pipermail/wikitech-l/2017-April/088019.html

If you or anyone else plan to provide a patch in Gerrit (see Developer access and the Gerrit tutorial) for review, there is a good chance.

I spent about half an hour digging into this, and the Database object construction chain, afais there's no way to inject a different TransactionProfiler, we have to use Database::factory() directly. That's problematic since we'd need to read all the globals and what not to know what to pass to it.

I think the method of injecting TransactionProfilers needs refactoring to make this more flexible, and given that this warning is mainly intended for developers I don't think it should be a release blocker (since it's not trivial to fix).

demon triaged this task as Unbreak Now! priority.May 31 2017, 6:40 PM
Restricted Application added subscribers: Jay8g, TerraCodes. · View Herald TranscriptMay 31 2017, 6:40 PM
Krinkle renamed this task from SpecialPage / TransactionProfiler throws a "Expectation (masterConns <= 0) by MediaWiki::main" on SqlBagOStuff::doGet to TransactionProfiler throws a "Expectation (masterConns <= 0)" on SqlBagOStuff::doGet.Jun 9 2017, 10:57 PM
Krinkle lowered the priority of this task from Unbreak Now! to High.
demon added a subscriber: demon.

given that this warning is mainly intended for developers I don't think it should be a release blocker (since it's not trivial to fix).

Krinkle renamed this task from TransactionProfiler throws a "Expectation (masterConns <= 0)" on SqlBagOStuff::doGet to TransactionProfiler should not apply to SqlBagOStuff.Jun 15 2017, 2:18 PM
mwjames added a comment.EditedJun 15 2017, 2:56 PM

I think the method of injecting TransactionProfilers needs refactoring to make this more flexible, and given that this warning is mainly intended for developers I don't think it should be a release blocker (since it's not trivial to fix).

The TransactionProfiler is surely not helpful as seen by (T166855, T166856, T167941) and since it doesn't bring any benefit to the end-user or developer by highlighting constant false positives maybe just disable it for any standard deployment and allow user to enable if it necessary. The constant noise on the debug channel is everything but helpful.

Krinkle lowered the priority of this task from High to Medium.Jul 6 2017, 8:34 PM

I think the method of injecting TransactionProfilers needs refactoring to make this more flexible, [..]

How to inject TransactionProfiler isn't the problem. The default is already to not enable TransactionProfiler when creating a LoadBalancer or Database object. We only specifically opt-in to that for the main wiki connection.

The problem is that SqlBagOStuff (CACHE_DB) for PostgresSQL doesn't create its own connection, because (last we checked, many years ago) this isn't supported by the PostgreSQL driver for PHP. As such, you can disable it for the main one, or not. Either way, on PG, your main connection is all your connections.

If you want to disable it, just configure wgDebugLogGroups to silence the DBPerformance channel.

Krinkle renamed this task from TransactionProfiler should not apply to SqlBagOStuff to TransactionProfiler should not apply to SqlBagOStuff (PostgreSQL).Jul 6 2017, 8:34 PM

This isn't just PostgreSQL, it applies to MySQL too.

Legoktm renamed this task from TransactionProfiler should not apply to SqlBagOStuff (PostgreSQL) to TransactionProfiler should not apply to SqlBagOStuff.Jul 6 2017, 8:36 PM

Change 363727 had a related patch set uploaded (by Krinkle; owner: Aaron Schulz):
[mediawiki/core@master] objectcache: Use a separate postgres connection in SqlBagOStuff

https://gerrit.wikimedia.org/r/363727

mwjames added a comment.EditedJul 6 2017, 11:14 PM

This isn't just PostgreSQL, it applies to MySQL too.

Exactly.

https://gerrit.wikimedia.org/r/363727

I checkout master for testing a different patch and it seems TransactionProfiler now spills more messages than before (like an athlete on steroids) not necessarily restricted to SqlBagOStuff, making the debug log fairly useless.

On a vanilla instance (skipped most of the stack trace because it goes on and on without any valuable information and is more or less the same repeating itself like a broken record):

[caches] cluster: EmptyBagOStuff, WAN: mediawiki-main-default, stash: db-replicated, message: SqlBagOStuff, session: SqlBagOStuff
[caches] LocalisationCache: using store LCStoreDB

... 

[DBPerformance] Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 7):
query-m: INSERT INTO 'X' (s_id,o_blob,o_hash) VALUES ('X') [TRX#fb06a1]

...

[DBPerformance] Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 10):
query-m: INSERT INTO 'X' (job_cmd,job_namespace,job_title,job_params,job_id,job_timestamp,job_sha1,job_random) VALUES ('X') [TRX#ff8c57]

...

[DBPerformance] Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 12):
query-m: UPDATE 'X' SET page_touched = 'X') [TRX#a20a67]

...

[runJobs] refreshLinksPrioritized Lorem_ipsum rootJobTimestamp=20170706221008 useRecursiveLinksUpdate=1 triggeringUser={"userId":0,"userName":"127.0.0.1"} triggeringRevisionId=7420 requestId=30a0d674fae21b88f1ce50a2 (id=4606,timestamp=2017-07-06 22:10:43+00) t=1177 good
[DBPerformance] Expectation (writes <= 0) by MediaWiki::restInPeace not met (actual: 16):
query-m: DELETE FROM 'X' WHERE job_cmd = 'X' [TRX#2d274d]
#0 ...\includes\libs\rdbms\TransactionProfiler.php(219): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writes', 'query-m: DELETE...', 16)
#1 ...\includes\libs\rdbms\database\Database.php(1032): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: DELETE...', 1499379055.2159, true, 1)
#2 ...\includes\libs\rdbms\database\Database.php(933): Wikimedia\Rdbms\Database->doProfiledQuery('DELETE FROM "jo...', 'DELETE /* JobQu...', true, 'JobQueueDB::doA...')
#3 ...\includes\libs\rdbms\database\Database.php(2365): Wikimedia\Rdbms\Database->query('DELETE FROM "jo...', 'JobQueueDB::doA...')
#4 [internal function]: Wikimedia\Rdbms\Database->delete('"job"', 'job_cmd = 'refr...', 'JobQueueDB::doA...')
#5 ...\includes\libs\rdbms\database\DBConnRef.php(48): call_user_func_array(Array, Array)
#6 ...\includes\libs\rdbms\database\DBConnRef.php(409): Wikimedia\Rdbms\DBConnRef->__call('delete', Array)
#7 ...\includes\jobqueue\JobQueueDB.php(474): Wikimedia\Rdbms\DBConnRef->delete('job', Array, 'JobQueueDB::doA...')
#8 ...\includes\jobqueue\JobQueue.php(413): JobQueueDB->doAck(Object(RefreshLinksJob))
#9 ...\includes\jobqueue\JobQueueGroup.php(260): JobQueue->ack(Object(RefreshLinksJob))
#10 ...\includes\jobqueue\JobRunner.php(195): JobQueueGroup->ack(Object(RefreshLinksJob))
#11 ...\includes\MediaWiki.php(977): JobRunner->run(Array)
#12 ...\includes\MediaWiki.php(963): MediaWiki->triggerSyncJobs(1, Object(MediaWiki\Logger\LegacyLogger))
#13 ...\includes\MediaWiki.php(915): MediaWiki->triggerJobs()
#14 ...\includes\MediaWiki.php(737): MediaWiki->restInPeace('normal')
#15 ...\includes\MediaWiki.php(756): MediaWiki->{closure}()
#16 ...\includes\MediaWiki.php(553): MediaWiki->doPostOutputShutdown('normal')
#17 ...\index.php(43): MediaWiki->run()

https://gerrit.wikimedia.org/r/363727

With reference to https://gerrit.wikimedia.org/r/363727 and the comment "... should fix warnings about TransactionProfiler in objectcache...", it does NOT as it can be seen from the log output:

[DBPerformance] Expectation (writes <= 0) by MediaWiki::main not met (actual: 2):
query-m: INSERT INTO 'X' (keyname,value,exptime) VALUES ('X') [TRX#d53d8a]
#0 ...\mw-master-pg\includes\libs\rdbms\TransactionProfiler.php(219): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated('writes', 'query-m: INSERT...', 2)
#1 ...\mw-master-pg\includes\libs\rdbms\database\Database.php(1032): Wikimedia\Rdbms\TransactionProfiler->recordQueryCompletion('query-m: INSERT...', 1499381629.4608, true, 1)
#2 ...\mw-master-pg\includes\libs\rdbms\database\Database.php(933): Wikimedia\Rdbms\Database->doProfiledQuery('INSERT INTO "ob...', 'INSERT /* SqlBa...', true, 'SqlBagOStuff::s...')
#3 ...\mw-master-pg\includes\libs\rdbms\database\DatabasePostgres.php(646): Wikimedia\Rdbms\Database->query('INSERT INTO "ob...', 'SqlBagOStuff::s...', NULL)
#4 ...\mw-master-pg\includes\libs\rdbms\database\Database.php(2223): Wikimedia\Rdbms\DatabasePostgres->insert('"objectcache"', Array, 'SqlBagOStuff::s...')
#5 ...\mw-master-pg\includes\objectcache\SqlBagOStuff.php(372): Wikimedia\Rdbms\Database->replace('objectcache', Array, Array, 'SqlBagOStuff::s...')
#6 ...\mw-master-pg\includes\objectcache\SqlBagOStuff.php(387): SqlBagOStuff->setMulti(Array, 30)
#7 ...\mw-master-pg\includes\libs\objectcache\BagOStuff.php(545): SqlBagOStuff->set('mwmasterpg:mess...', 1, 30)
#8 ...\mw-master-pg\includes\libs\objectcache\BagOStuff.php(418): BagOStuff->add('mwmasterpg:mess...', 1, 30)
#9 [internal function]: BagOStuff->{closure}()
#10 ...\mw-master-pg\vendor\wikimedia\wait-condition-loop\src\WaitConditionLoop.php(92): call_user_func(Object(Closure))
#11 ...\mw-master-pg\includes\libs\objectcache\BagOStuff.php(429): Wikimedia\WaitConditionLoop->invoke()
#12 ...\mw-master-pg\includes\libs\objectcache\BagOStuff.php(472): BagOStuff->lock('mwmasterpg:mess...', 0, 30, 'MessageCache::g...')
#13 ...\mw-master-pg\includes\cache\MessageCache.php(762): BagOStuff->getScopedLock('mwmasterpg:mess...', 0, 30, 'MessageCache::g...')
#14 ...\mw-master-pg\includes\cache\MessageCache.php(420): MessageCache->getReentrantScopedLock('mwmasterpg:mess...', 0)
#15 ...\mw-master-pg\includes\cache\MessageCache.php(350): MessageCache->loadFromDBWithLock('en', Array, NULL)
#16 ...\mw-master-pg\includes\cache\MessageCache.php(991): MessageCache->load('en')
#17 ...\mw-master-pg\includes\cache\MessageCache.php(919): MessageCache->getMsgFromNamespace('Pagetitle', 'en')
#18 ...\mw-master-pg\includes\cache\MessageCache.php(888): MessageCache->getMessageForLang(Object(LanguageEn), 'pagetitle', true, Array)
#19 ...\mw-master-pg\includes\cache\MessageCache.php(828): MessageCache->getMessageFromFallbackChain(Object(LanguageEn), 'pagetitle', true)
#20 ...\mw-master-pg\includes\Message.php(1257): MessageCache->get('pagetitle', true, Object(LanguageEn))
#21 ...\mw-master-pg\includes\Message.php(842): Message->fetchMessage()
#22 ...\mw-master-pg\includes\Message.php(934): Message->toString('text')
#23 ...\mw-master-pg\includes\OutputPage.php(936): Message->text()
#24 ...\mw-master-pg\includes\OutputPage.php(983): OutputPage->setHTMLTitle(Object(Message))
#25 ...\mw-master-pg\includes\page\Article.php(463): OutputPage->setPageTitle('Main Page')
#26 ...\mw-master-pg\includes\actions\ViewAction.php(68): Article->view()
#27 ...\mw-master-pg\includes\MediaWiki.php(499): ViewAction->show()
#28 ...\mw-master-pg\includes\MediaWiki.php(293): MediaWiki->performAction(Object(Article), Object(Title))
#29 ...\mw-master-pg\includes\MediaWiki.php(867): MediaWiki->performRequest()
#30 ...\mw-master-pg\includes\MediaWiki.php(523): MediaWiki->main()
#31 ...\mw-master-pg\index.php(43): MediaWiki->run()
#32 {main}
Krinkle closed this task as Resolved.Jul 6 2017, 11:53 PM
Krinkle reopened this task as Open.
Krinkle assigned this task to aaron.
Krinkle removed aaron as the assignee of this task.
Krinkle edited projects, added Performance-Team; removed Patch-For-Review.
Krinkle removed a project: Performance-Team.
Krinkle added a subscriber: aaron.

Change 363727 merged by jenkins-bot:
[mediawiki/core@master] objectcache: Use a separate postgres connection in SqlBagOStuff

https://gerrit.wikimedia.org/r/363727

Change 363995 had a related patch set uploaded (by Chad; owner: Aaron Schulz):
[mediawiki/core@REL1_29] objectcache: Use a separate postgres connection in SqlBagOStuff

https://gerrit.wikimedia.org/r/363995

Change 363995 merged by jenkins-bot:
[mediawiki/core@REL1_29] objectcache: Use a separate postgres connection in SqlBagOStuff

https://gerrit.wikimedia.org/r/363995

In config, with $wgTrxProfilerLimits you can do:

unset( $wgTrxProfilerLimits['GET']['masterConns'] );
unset( $wgTrxProfilerLimits['GET']['writes'] );

Or if you want to keep some level of these warnings on GET:

$wgTrxProfilerLimits['GET'] = $wgTrxProfilerLimits['POST'];

Change 462130 had a related patch set uploaded (by Umherirrender; owner: Umherirrender):
[mediawiki/core@master] Use a ScopedCallback to silence transaction profiler in SqlBagOStuff

https://gerrit.wikimedia.org/r/462130

Change 462130 merged by jenkins-bot:
[mediawiki/core@master] Use a ScopedCallback to silence transaction profiler in SqlBagOStuff

https://gerrit.wikimedia.org/r/462130

Umherirrender closed this task as Resolved.Oct 12 2018, 7:06 PM
Umherirrender claimed this task.