TransactionProfiler should not apply to SqlBagOStuff
Closed, ResolvedPublic
Actions

Assigned To

Authored By

	mwjames
	Jan 2 2017, 2:19 PM

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?

Details

Subject	Repo	Branch	Lines +/-
Use a ScopedCallback to silence transaction profiler in SqlBagOStuff	mediawiki/core	master	+41 -17
objectcache: Use a separate postgres connection in SqlBagOStuff	mediawiki/core	REL1_29	+2 -3
objectcache: Use a separate postgres connection in SqlBagOStuff	mediawiki/core	master	+2 -3

Customize query in gerrit

Related Objects
Search...

		Status	Subtype	Assigned	Task
		Resolved		Umherirrender	T154424 TransactionProfiler should not apply to SqlBagOStuff
		Resolved		aaron	T167946 SqlBagOStuff for PostgreSQL should not re-use main connection

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

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.

Krinkle moved this task from General to libs/objectcache on the MediaWiki-libs-BagOStuff board.Apr 8 2017, 12:07 AM

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.

mwjames added a project: MW-1.29-release.Apr 27 2017, 10:51 AM

Krinkle moved this task from Untriaged to Usage problem on the MediaWiki-libs-Rdbms board.May 8 2017, 1:06 AM

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

Seb35 mentioned this in T97693: TransactionProfiler should not apply to using LCStoreDB.Jun 1 2017, 12:40 AM

mwjames mentioned this in T166855: TransactionProfiler spams log with "DELETE FROM `l10n_cache` ..." on LocalisationCache::recache.Jun 2 2017, 4:32 AM

Liuxinyu970226 subscribed.Jun 8 2017, 12:58 PM

Reception123 subscribed.Jun 9 2017, 4:47 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.

In T154424#3287219, @Legoktm wrote:

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

mwjames mentioned this in T167941: TransactionProfiler throws a "Expectation ..." on SqlBagOStuff::setMulti.Jun 15 2017, 7:52 AM

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

Krinkle merged a task: T167941: TransactionProfiler throws a "Expectation ..." on SqlBagOStuff::setMulti.Jun 15 2017, 2:39 PM

Krinkle subscribed.

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.

Seb35 mentioned this in T168723: LinksUpdate totally broken when JobQueueDB is in use.Jul 4 2017, 10:36 PM

Krinkle mentioned this in T167946: SqlBagOStuff for PostgreSQL should not re-use main connection.Jul 6 2017, 8:28 PM

Krinkle added a subtask: T167946: SqlBagOStuff for PostgreSQL should not re-use main connection.

In T154424#3351642, @mwjames wrote:

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

gerritbot added a project: Patch-For-Review.Jul 6 2017, 11:08 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 closed subtask T167946: SqlBagOStuff for PostgreSQL should not re-use main connection as Resolved.

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

gerritbot added a project: Patch-For-Review.Jul 7 2017, 11:59 PM

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

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

ReleaseTaggerBot added a project: MW-1.30-release-notes (WMF-deploy-2017-07-11_(1.30.0-wmf.9)).Jul 8 2017, 4:01 AM

Krinkle removed projects: MW-1.30-release-notes (WMF-deploy-2017-07-11_(1.30.0-wmf.9)), Patch-For-Review.Jul 8 2017, 4:37 AM

ReleaseTaggerBot added a project: MW-1.29-release-notes.Jul 8 2017, 5:01 AM

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'];

Anomie mentioned this in T191537: MediaWiki core's selenium tests flaky when run as part of mwext-mw-selenium-node-composer-jessie job.Jun 7 2018, 1:54 PM

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

gerritbot added a project: Patch-For-Review.Sep 22 2018, 12:38 PM

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.

Liuxinyu970226 unsubscribed.Oct 27 2018, 7:40 AM