Page MenuHomePhabricator
Create Task
Maniphest T154719

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

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}

Details

SubjectRepoBranchLines +/-
Increase accuracy of logging metadata compilation attemptsmediawiki/extensions/PageTriagemaster+17 -18
DBPerformance: Master connections and writes via POST not GETmediawiki/extensions/PageTriagemaster+101 -155
Customize query in gerrit

Related Objects
Search...

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
Catrope added a parent task: T92357: Fix database master queries from HTTP GET/HEAD before active-active multi-dc.Jan 5 2017, 11:40 PM
• jmatazzoni edited projects, added Collaboration-Team-Triage (Collab-Team-Q3-Jan-Mar-2017); removed Collaboration-Team-Triage.Jan 25 2017, 3:01 AM
• jmatazzoni moved this task from Untriaged to Ready for Pickup on the Collaboration-Team-Triage (Collab-Team-Q3-Jan-Mar-2017) board.
• jmatazzoni edited projects, added Collaboration-Team-Triage (Collab-Team-Q4-Apr-Jun-2017); removed Collaboration-Team-Triage (Collab-Team-Q3-Jan-Mar-2017).Apr 18 2017, 12:57 AM
• jmatazzoni moved this task from Untriaged to Ready for Pickup on the Collaboration-Team-Triage (Collab-Team-Q4-Apr-Jun-2017) board.Apr 18 2017, 12:59 AM
• jmatazzoni edited projects, added Collaboration-Team-Triage (Collab-Team-This-Quarter); removed Collaboration-Team-Triage (Collab-Team-Q4-Apr-Jun-2017).Jul 12 2017, 10:03 PM
• jmatazzoni moved this task from Untriaged to Ready for Pickup on the Collaboration-Team-Triage (Collab-Team-This-Quarter) board.Jul 12 2017, 10:29 PM
tstarling subscribed.Feb 21 2018, 4:29 AM

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 subscribed.Jul 3 2018, 7:38 PM
SBisson mentioned this in Collaboration-Team-Triage (Collab-Team-This-Quarter).Jul 4 2018, 5:11 PM
JTannerWMF added a project: Growth-Team.Jul 5 2018, 2:52 AM
JTannerWMF moved this task from Inbox to Needs Discussion on the Growth-Team board.Jul 5 2018, 2:54 AM
Catrope moved this task from Needs Discussion to Sprint 0 (Growth Team) on the Growth-Team board.Jul 5 2018, 5:50 PM
Catrope edited projects, added Growth-Team (Sprint 0 (Growth Team)); removed Growth-Team.
Catrope moved this task from Incoming to Ready for Development on the Growth-Team (Sprint 0 (Growth Team)) board.
kostajh moved this task from Ready for Development to In Progress on the Growth-Team (Sprint 0 (Growth Team)) board.EditedJul 16 2018, 2:49 AM
kostajh subscribed.

@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;
			}
		}
                [ ... ]
kostajh mentioned this in T199699: PageTriage performs unexpected db writes on GET request (TransactionProfiler warning from ArticleCompileProcessor).Jul 16 2018, 2:22 PM
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.

kostajh added a comment.Jul 17 2018, 1:59 PM

@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 added a comment.Jul 17 2018, 2:10 PM
In T154719#4430637, @kostajh wrote:

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

kostajh added a comment.Jul 17 2018, 2:11 PM

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

gerritbot subscribed.Jul 18 2018, 2:39 AM

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

gerritbot added a project: Patch-For-Review.Jul 18 2018, 2:39 AM
kostajh added a comment.Jul 18 2018, 2:40 AM

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

JTannerWMF assigned this task to kostajh.Jul 18 2018, 5:46 PM
kostajh moved this task from In Progress to Code Review on the Growth-Team (Sprint 0 (Growth Team)) board.Jul 18 2018, 9:23 PM
kostajh moved this task from Code Review to In Progress on the Growth-Team (Sprint 0 (Growth Team)) board.Jul 19 2018, 12:24 PM
Catrope mentioned this in T88143: Move writes on read requests to the job queue.Aug 7 2018, 5:45 PM
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?

In T154719#4430491, @SBisson wrote:

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

Krinkle added a project: Performance-Team (Radar).Aug 13 2018, 7:38 PM
Krinkle moved this task from Limbo to Watching on the Performance-Team (Radar) board.
kostajh added a comment.Aug 16 2018, 12:57 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?

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

Catrope mentioned this in T202175: Delete rows for 'pagetriage-lastuse' preference.Aug 17 2018, 10:37 PM
kostajh moved this task from In Progress to Code Review on the Growth-Team (Sprint 0 (Growth Team)) board.Aug 19 2018, 10:04 PM
gerritbot added a comment.Aug 20 2018, 7:34 PM

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

kostajh moved this task from Code Review to QA on the Growth-Team (Sprint 0 (Growth Team)) board.Aug 20 2018, 8:40 PM
gerritbot added a comment.Aug 21 2018, 1:51 PM

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

kostajh moved this task from QA to Code Review on the Growth-Team (Sprint 0 (Growth Team)) board.Aug 21 2018, 1:59 PM
gerritbot added a comment.Aug 21 2018, 3:35 PM

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

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

ReleaseTaggerBot added a project: MW-1.32-notes (WMF-deploy-2018-08-21 (1.32.0-wmf.18)).Aug 21 2018, 4:00 PM
JTannerWMF moved this task from Code Review to QA on the Growth-Team (Sprint 0 (Growth Team)) board.Aug 22 2018, 5:37 PM
Etonkovidova closed this task as Resolved.Aug 22 2018, 10:57 PM
kostajh mentioned this in T202735: Prevent article metadata compilation on rollback actions.Aug 24 2018, 2:11 PM
kostajh mentioned this in T202815: [wmf.18] enwiki NPP page - no scroll.Aug 26 2018, 11:50 PM
kostajh mentioned this in T203008: Ensure retrieval and storage of article metadata.Aug 28 2018, 6:32 PM
kostajh mentioned this in T110444: SpecialNewPagesFeed abuses preferences for 'pagetriage-lastuse' key.Oct 10 2018, 3:36 PM
kostajh mentioned this in T206580: Use object stash for persisting last-use proprety to control curation toolbar display.Oct 10 2018, 3:57 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