From: Timo Tijhof <krinklemail@gmail.com>
Date: Tue, 17 Oct 2017 01:48:54 +0000 (+0100)
Subject: resourceloader: Introduce metric for backend response timing
X-Git-Tag: 1.31.0-rc.0~1715^2
X-Git-Url: https://git.cyclocoop.org/%28%28?a=commitdiff_plain;h=b0910b7176208cbcb4ded20af1d75ae94c7fcc24;p=lhc%2Fweb%2Fwiklou.git

resourceloader: Introduce metric for backend response timing

We currently have several counts and timings of individual pieces
of ResourceLoader backend logic (minification, module building, ..)
but no measure of the response overall.

This responseTime metric will effectively provide both a timing
measure as well as a backend request count.

Bug: T178350
Change-Id: I625a5eb90f5a4ea90aebf9292dfda0f1c5ae4f2e
---

diff --git a/includes/resourceloader/ResourceLoader.php b/includes/resourceloader/ResourceLoader.php
index c58bb00b94..b2e1c49cfd 100644
--- a/includes/resourceloader/ResourceLoader.php
+++ b/includes/resourceloader/ResourceLoader.php
@@ -728,6 +728,8 @@ class ResourceLoader implements LoggerAwareInterface {
 		// See https://bugs.php.net/bug.php?id=36514
 		ob_start();
 
+		$this->measureResponseTime( RequestContext::getMain()->getTiming() );
+
 		// Find out which modules are missing and instantiate the others
 		$modules = [];
 		$missing = [];
@@ -828,6 +830,16 @@ class ResourceLoader implements LoggerAwareInterface {
 		echo $response;
 	}
 
+	protected function measureResponseTime( Timing $timing ) {
+		DeferredUpdates::addCallableUpdate( function () use ( $timing ) {
+			$measure = $timing->measure( 'responseTime', 'requestStart', 'requestShutdown' );
+			if ( $measure !== false ) {
+				$stats = MediaWikiServices::getInstance()->getStatsdDataFactory();
+				$stats->timing( 'resourceloader.responseTime', $measure['duration'] * 1000 );
+			}
+		} );
+	}
+
 	/**
 	 * Send main response headers to the client.
 	 *
diff --git a/tests/phpunit/includes/resourceloader/ResourceLoaderTest.php b/tests/phpunit/includes/resourceloader/ResourceLoaderTest.php
index e9d022f62e..f45f8aee15 100644
--- a/tests/phpunit/includes/resourceloader/ResourceLoaderTest.php
+++ b/tests/phpunit/includes/resourceloader/ResourceLoaderTest.php
@@ -869,4 +869,41 @@ mw.example();
 			'Extra headers'
 		);
 	}
+
+	/**
+	 * @covers ResourceLoader::respond
+	 */
+	public function testRespond() {
+		$rl = $this->getMockBuilder( EmptyResourceLoader::class )
+			->setMethods( [
+				'tryRespondNotModified',
+				'sendResponseHeaders',
+				'measureResponseTime',
+			] )
+			->getMock();
+		$context = $this->getResourceLoaderContext( [ 'modules' => '' ], $rl );
+
+		$rl->expects( $this->once() )->method( 'measureResponseTime' );
+		$this->expectOutputRegex( '/no modules were requested/' );
+
+		$rl->respond( $context );
+	}
+
+	/**
+	 * @covers ResourceLoader::measureResponseTime
+	 */
+	public function testMeasureResponseTime() {
+		$stats = $this->getMockBuilder( NullStatsdDataFactory::class )
+			->setMethods( [ 'timing' ] )->getMock();
+		$this->setService( 'StatsdDataFactory', $stats );
+
+		$stats->expects( $this->once() )->method( 'timing' )
+			->with( 'resourceloader.responseTime', $this->anything() );
+
+		$timing = new Timing();
+		$timing->mark( 'requestShutdown' );
+		$rl = TestingAccessWrapper::newFromObject( new EmptyResourceLoader );
+		$rl->measureResponseTime( $timing );
+		DeferredUpdates::doUpdates();
+	}
 }