Page MenuHomePhabricator

PageTriage opens master connection on GET for ArticleMetadata cache misses
Closed, ResolvedPublic

Description

Happens multiple times per minute and seems to be especially common when viewing a page right after editing it.

This is a tough one: the metadata is not in cache this early (because the page was just edited, we legitimately need the metadata to render the page (because it tells us whether we need to set noindex), and using a master connection to build at least some parts of the metadata is probably also legitimate. Although, if this is a page view following an edit, I think ChronologyProtector will probably ensure that a replica DB wouldn't give us terribly out-of-date data either.

 Expectation (masterConns <= 0) by MediaWiki::main not met:
[connect to 10.64.32.27 (enwiki)]
#0 /srv/mediawiki/php-1.29.0-wmf.7/includes/libs/rdbms/TransactionProfiler.php(160): TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.29.0-wmf.7/includes/libs/rdbms/loadbalancer/LoadBalancer.php(590): TransactionProfiler->recordConnection()
#2 /srv/mediawiki/php-1.29.0-wmf.7/includes/GlobalFunctions.php(3081): LoadBalancer->getConnection()
#3 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/includes/ArticleMetadata.php(555): wfGetDB()
#4 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/includes/ArticleMetadata.php(660): ArticleCompileInterface->__construct()
#5 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/includes/ArticleMetadata.php(435): ArticleCompileBasicData->__construct()
#6 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/includes/ArticleMetadata.php(396): ArticleCompileProcessor->process()
#7 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/includes/ArticleMetadata.php(180): ArticleCompileProcessor->compileMetadata()
#8 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/PageTriage.hooks.php(333): ArticleMetadata->getMetadata()
#9 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/PageTriage.hooks.php(313): PageTriageHooks::isArticleNew()
#10 /srv/mediawiki/php-1.29.0-wmf.7/extensions/PageTriage/PageTriage.hooks.php(378): PageTriageHooks::shouldShowNoIndex()
#11 /srv/mediawiki/php-1.29.0-wmf.7/includes/Hooks.php(195): PageTriageHooks::onArticleViewFooter()
#12 /srv/mediawiki/php-1.29.0-wmf.7/includes/page/Article.php(954): Hooks::run()
#13 /srv/mediawiki/php-1.29.0-wmf.7/includes/page/Article.php(671): Article->showViewFooter()
#14 /srv/mediawiki/php-1.29.0-wmf.7/includes/actions/ViewAction.php(71): Article->view()
#15 /srv/mediawiki/php-1.29.0-wmf.7/includes/MediaWiki.php(495): ViewAction->show()
#16 /srv/mediawiki/php-1.29.0-wmf.7/includes/MediaWiki.php(289): MediaWiki->performAction()
#17 /srv/mediawiki/php-1.29.0-wmf.7/includes/MediaWiki.php(858): MediaWiki->performRequest()
#18 /srv/mediawiki/php-1.29.0-wmf.7/includes/MediaWiki.php(519): MediaWiki->main()
#19 /srv/mediawiki/php-1.29.0-wmf.7/index.php(43): MediaWiki->run()
#20 /srv/mediawiki/w/index.php(3): include()
#21 {main}

Event Timeline

Catrope created this task.Jan 5 2017, 11:38 PM
Restricted Application added a project: Collaboration-Team-Triage. · View Herald TranscriptJan 5 2017, 11:38 PM
Restricted Application added a subscriber: Aklapper. · View Herald Transcript

The call of ArticleCompileProcessor::compileMetadata() from from ArticleMetadata::getMetadata() is supposedly a "very rare case" according to a source code comment. It's incorrect in this case to do BasicData compilation from the master. ArticleMetadata::getMetadata() has just loaded the page information from the replica, so it knows all the data is already in the replica. It should override the componentDb config so that all data comes from the replica. Note that the backtrace shows this information being prepared for the footer of a page view. Page views use existence information from the replica DB, so if you loaded PageTriage data from the master, the best you could do would be to display a triage footer on a "page does not exist" error message.

There will still be a master connection due to ArticleCompileProcessor::save(), but it's deferred until post-save, so the latency will not be user visible.

The extension could do with some other improvements. ArticleCompileBasicData actually says:

// Process page individually because MIN() GROUP BY is slow

before proceeding to do those "slow" queries on the master! Why does it need to recalculate the page creation time on every edit, doesn't it stay the same by definition?

Also, note that it is doing these updates from a LinksUpdateComplete hook, which if I understand correctly is now run via the job queue, after the page data reaches the replica.

SBisson added a subscriber: SBisson.Jul 3 2018, 7:38 PM
kostajh added a subscriber: kostajh.

@Catrope @SBisson are you still seeing this error in the logs? I'm not seeing this specific one.

The REL1_29 tag (cc0d330) of PageTriage, the version in use when this error was reported, has this as the body of ArticleCompileProcessor's compileMetadata()

public function compileMetadata( $mode = self::SAVE_IMMEDIATE ) {
$this->prepare();
$this->process();

if ( $mode === self::SAVE_DEFERRED ) {
	DeferredUpdates::addCallableUpdate( function() {
		$this->save(); // T152847
} );
} else {
	$this->save();
}

but in master (b10d0abe9b228688b0748ec5474935c5d621524f) the componentDb is set to use the replica before $this->process(), because the calling method looks like this $pageData += $acp->compileMetadata( $acp::SAVE_DEFERRED );

	public function compileMetadata( $mode = self::SAVE_IMMEDIATE ) {
		if ( $mode === self::SAVE_DEFERRED ) {
			foreach ( $this->component as $key => $value ) {
				$this->componentDb[$key] = DB_REPLICA;
			}
		}
                [ ... ]
SBisson added a subscriber: aaron.EditedJul 17 2018, 1:10 PM

@kostajh pulled from the logs just now

Expectation (masterConns <= 0) by MediaWiki::restInPeace not met (actual: 1):
[connect to 10.64.16.77 (enwiki)]
#0 /srv/mediawiki/php-1.32.0-wmf.12/includes/libs/rdbms/TransactionProfiler.php(164): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.32.0-wmf.12/includes/libs/rdbms/loadbalancer/LoadBalancer.php(776): Wikimedia\Rdbms\TransactionProfiler->recordConnection()
#2 /srv/mediawiki/php-1.32.0-wmf.12/includes/GlobalFunctions.php(2790): Wikimedia\Rdbms\LoadBalancer->getConnection()
#3 /srv/mediawiki/php-1.32.0-wmf.12/extensions/PageTriage/includes/ArticleCompile/ArticleCompileProcessor.php(196): wfGetDB()
#4 /srv/mediawiki/php-1.32.0-wmf.12/extensions/PageTriage/includes/ArticleCompile/ArticleCompileProcessor.php(129): MediaWiki\Extension\PageTriage\ArticleCompile\ArticleCompileProcessor->save()
#5 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/MWCallableUpdate.php(34): Closure$MediaWiki\Extension\PageTriage\ArticleCompile\ArticleCompileProcessor::compileMetadata()
#6 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/DeferredUpdates.php(268): MWCallableUpdate->doUpdate()
#7 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/DeferredUpdates.php(214): DeferredUpdates::runUpdate()
#8 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/DeferredUpdates.php(134): DeferredUpdates::execute()
#9 /srv/mediawiki/php-1.32.0-wmf.12/includes/MediaWiki.php(913): DeferredUpdates::doUpdates()
#10 /srv/mediawiki/php-1.32.0-wmf.12/includes/MediaWiki.php(733): MediaWiki->restInPeace()
#11 (): Closure$MediaWiki::doPostOutputShutdown()
#12 {main}

Contrary to the stacktrace in the ticket description, this is clearly running in a deferred update. I thought it was OK to use a master connection there. Maybe @aaron
can help us understand what exactly is wrong in this case.

@SBisson I opened T199699 for the log message you posted; the masterConns expectation warning that this task was opened for doesn't seem to be occurring any more.

@SBisson I opened T199699 for the log message you posted; the masterConns expectation warning that this task was opened for doesn't seem to be occurring any more.

The stack trace I posted is a masterConns expectation warning.

Ah, yes I see that now. Sorry about that.

Change 446517 had a related patch set uploaded (by Kosta Harlan; owner: Kosta Harlan):
[mediawiki/extensions/PageTriage@master] WIP: Multi DC: Save data in context of POST requests, not GET

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

@SBisson After setting some breakpoints in TransactionProfiler::recordConnection() and TransactionProfiler::recordQueryCompletion(), I looked farther up the chain at where the expectations are set in ApiMain::setRequestExpectations(). I couldn't see a way to make DeferredUpdates work with a GET request and avoid the violations getting recorded by transaction profiler.

aaron added a comment.Aug 8 2018, 6:37 PM

Is it possible to just update pagetriage_page_tags on page saves (and other relavent POST requests) when there are already master connections? For anything that depends on things updated via the job queue (like backlinks), those would have to be attached such LinksUpdates (which already run in POST/jobs). Why do things have to be updated on page views?

@kostajh pulled from the logs just now

Expectation (masterConns <= 0) by MediaWiki::restInPeace not met (actual: 1):
[connect to 10.64.16.77 (enwiki)]
#0 /srv/mediawiki/php-1.32.0-wmf.12/includes/libs/rdbms/TransactionProfiler.php(164): Wikimedia\Rdbms\TransactionProfiler->reportExpectationViolated()
#1 /srv/mediawiki/php-1.32.0-wmf.12/includes/libs/rdbms/loadbalancer/LoadBalancer.php(776): Wikimedia\Rdbms\TransactionProfiler->recordConnection()
#2 /srv/mediawiki/php-1.32.0-wmf.12/includes/GlobalFunctions.php(2790): Wikimedia\Rdbms\LoadBalancer->getConnection()
#3 /srv/mediawiki/php-1.32.0-wmf.12/extensions/PageTriage/includes/ArticleCompile/ArticleCompileProcessor.php(196): wfGetDB()
#4 /srv/mediawiki/php-1.32.0-wmf.12/extensions/PageTriage/includes/ArticleCompile/ArticleCompileProcessor.php(129): MediaWiki\Extension\PageTriage\ArticleCompile\ArticleCompileProcessor->save()
#5 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/MWCallableUpdate.php(34): Closure$MediaWiki\Extension\PageTriage\ArticleCompile\ArticleCompileProcessor::compileMetadata()
#6 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/DeferredUpdates.php(268): MWCallableUpdate->doUpdate()
#7 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/DeferredUpdates.php(214): DeferredUpdates::runUpdate()
#8 /srv/mediawiki/php-1.32.0-wmf.12/includes/deferred/DeferredUpdates.php(134): DeferredUpdates::execute()
#9 /srv/mediawiki/php-1.32.0-wmf.12/includes/MediaWiki.php(913): DeferredUpdates::doUpdates()
#10 /srv/mediawiki/php-1.32.0-wmf.12/includes/MediaWiki.php(733): MediaWiki->restInPeace()
#11 (): Closure$MediaWiki::doPostOutputShutdown()
#12 {main}

Contrary to the stacktrace in the ticket description, this is clearly running in a deferred update. I thought it was OK to use a master connection there. Maybe @aaron
can help us understand what exactly is wrong in this case.

Is it possible to just update pagetriage_page_tags on page saves (and other relavent POST requests) when there are already master connections? For anything that depends on things updated via the job queue (like backlinks), those would have to be attached such LinksUpdates (which already run in POST/jobs). Why do things have to be updated on page views?

@aaron yes, that's the plan! Sorry my last comment didn't make that very clear. The patch for this should be ready later this month.

Change 446517 merged by jenkins-bot:
[mediawiki/extensions/PageTriage@master] DBPerformance: Master connections and writes via POST not GET

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

Change 454281 had a related patch set uploaded (by Kosta Harlan; owner: Kosta Harlan):
[mediawiki/extensions/PageTriage@master] Increase accuracy of logging metadata compilation attempts

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

Change 454281 merged by jenkins-bot:
[mediawiki/extensions/PageTriage@master] Increase accuracy of logging metadata compilation attempts

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

Etonkovidova closed this task as Resolved.Aug 22 2018, 10:57 PM