Page MenuHomePhabricator

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

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"
				]
			},

Event Timeline

Krinkle created this task.Feb 22 2017, 9:41 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

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',

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

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

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

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

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

Krinkle moved this task from Inbox to Doing on the Performance-Team board.Mar 1 2017, 8:51 PM
Krinkle closed this task as Resolved.EditedMar 4 2017, 4:38 AM

Success!

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

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

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