Page MenuHomePhabricator
Create Task
Maniphest T158813

Fix high build time for ext.uls.common, ext.echo.ui.desktop and others
Closed, ResolvedPublic
Actions

Description

There's a certain number of modules that appear to have little in common with each other but are consistently taking longer to build. Every minute at least one of these modules' builds is taking over 1 seconds, which is enormous considering our median of less than a millisecond.

The modules that seem to fit this slow pattern have the following in common so far:

  • p95 build time is consistently high at around 5ms for at least 1 build every minute (overall p95 is <1ms)
  • upper build time is consistently high at around 1000ms for at least 1 build every minute.
  • These are file modules with at least 1 stylesheet. Some also have scripts. Some CSS some LESS.
  • Scripts-only file modules are not affected.
  • Wiki modules are not affected.

Examples of affected modules:

ext.uls.common
		"ext.uls.common": {
			"targets": [ "desktop", "mobile" ],
			"scripts": "js/ext.uls.common.js",
			"styles": "css/ext.uls.css",
			"skinStyles": {
				"monobook": "css/ext.uls-monobook.css"
			},
ext.echo.ui.desktop
		"ext.echo.ui.desktop": {
			"scripts": [
				"ui/mw.echo.ui.BadgeLinkWidget.js",
				"ui/mw.echo.ui.NotificationBadgeWidget.js"
			],
			"styles": [
				"styles/mw.echo.ui.NotificationBadgeWidget.less"
			],
			"skinStyles": {
				"monobook": [
					"styles/mw.echo.ui.NotificationBadgeWidget.monobook.less"
				],
				"modern": [
					"styles/mw.echo.ui.NotificationBadgeWidget.modern.less"
				]
			},

Details

Related Changes in Gerrit:
SubjectRepoBranchLines +/-
resourceloader: Avoid endless module_deps write for the same valuemediawiki/coremaster+20 -6
resourceloader: Optimize WikiModule preload for reqs without wiki modulesmediawiki/coremaster+5 -0
Customize query in gerrit

Related Objects
Search...

Event Timeline

Krinkle created this task.Feb 22 2017, 9:41 PM
gerritbot subscribed.Feb 22 2017, 9:42 PM

Change 339260 had a related patch set uploaded (by Krinkle):
resourceloader: Optimize WikiModule preload for reqs without wiki modules

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

gerritbot added a project: Patch-For-Review.Feb 22 2017, 9:42 PM
Krinkle updated the task description. (Show Details)EditedFeb 22 2017, 9:42 PM

Based on an XHGui profile ran on mwdebug1001 for a ext.uls.common request, I noticed that about half the ResourceLoader::respond() time is spent in ResourceLoader::preloadModuleInfo, and half of ResourceLoader::preloadModuleInfo() is spent in ResourceLoaderWikiModule::preloadTitleInfo despite there being no wiki modules in this request.

https://gerrit.wikimedia.org/r/339260 should fix that.

The same profile also showed that the other half of ResourceLoader::respond() is spent in getModuleContent (as expected) and most of it in ResourceLoaderFileModule::getStyles. Surprisingly, most of getStyles was spent in saveFileDependencies - which is unusual, since that's only supposed to write to the database if the dependencies changed.

It seems that the following logic has a flaw.

ResourceLoader.php
class ResourceLoader {
	public function preloadModuleInfo( array $moduleNames, $context ) {
		...
		$res = $dbr->select( 'module_deps', [ 'md_module', 'md_deps' ],  ...
		$module->setFileDependencies( $context, ResourceLoaderModule::expandRelativePaths(
			FormatJson::decode( $row->md_deps, true )
		) );
ResourceLoaderFileModule.php
class ResourceLoaderFileModule
	public function setFileDependencies( $context, $files ) {
		...
		$this->fileDeps[$vary] = $files;
	}

	protected function saveFileDependencies( $context, $localFileRefs ) {
		// Normalise
		$localFileRefs = array_values( array_unique( $localFileRefs ) );
		sort( $localFileRefs );

		...
		if ( $localFileRefs !== $this->getFileDependencies( $context ) ) {
				...
				$deps = FormatJson::encode( self::getRelativePaths( $localFileRefs ) );
				$dbw->upsert( 'module_deps',
gerritbot added a comment.Feb 22 2017, 9:55 PM

Change 339260 merged by jenkins-bot:
resourceloader: Optimize WikiModule preload for reqs without wiki modules

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

gerritbot added a comment.Feb 22 2017, 9:58 PM

Change 339316 had a related patch set uploaded (by Krinkle):
resourceloader: Avoid endless module_deps write for the same value

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

ReleaseTaggerBot added projects: MW-1.29-release (WMF-deploy-2017-02-28_(1.29.0-wmf.14)), MW-1.29-release-notes.Feb 22 2017, 10:00 PM
gerritbot added a comment.Feb 22 2017, 10:46 PM

Change 339316 merged by jenkins-bot:
resourceloader: Avoid endless module_deps write for the same value

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

Krinkle removed projects: MW-1.29-release (WMF-deploy-2017-02-28_(1.29.0-wmf.14)), Patch-For-Review.Feb 23 2017, 4:16 AM

Let's see how this rolls out next week.

Krinkle moved this task from Inbox, needs triage to Doing (old) on the Performance-Team board.Mar 1 2017, 8:51 PM
Krinkle closed this task as Resolved.EditedMar 4 2017, 4:38 AM
Krinkle added a project: Wikimedia-Performance-publish.

Success!

https://grafana-admin.wikimedia.org/dashboard/db/resourceloadermodule?var-module=ext_uls_common&from=1487937600000&to=1488542400000

s.png (1×2 px, 256 KB)

(The unrelated 12-hour spike yesterday is most likely due to cache misses following the module_deps purge, per T158105)

In fact, since fixes for T158105 went out in the same release, build time has gone down quite universally for all file modules. Bringing the p99 of each minute from being typically 1s - 1.1s to being 200-600ms.

Screen Shot 2017-03-03 at 20.56.16.png (678×2 px, 217 KB)

Related changes:

(T158813) rMW49948457ecf9: resourceloader: Optimize WikiModule preload for reqs without wiki modules
(T158813) rMWe2c4c40c96b6: resourceloader: Avoid endless module_deps write for the same value
(T158105) rMW68c0eefc8509: resourceloader: Limit module_deps write lock to unique index
(T158105) rMWe7b57d881aaf: resourceloader: Use upsert() instead of replace() for module_deps write

Krinkle mentioned this in T160142: Build time regression for ext.wikimediaBadges.Mar 10 2017, 1:39 AM
Krinkle moved this task from Untriaged to Published on the Wikimedia-Performance-publish board.May 26 2017, 4:37 PM
Krinkle moved this task from Published to Ready for write-up on the Wikimedia-Performance-publish board.Jun 27 2017, 9:08 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