From 8340400f27ac1831258af4da00894242e683294f Mon Sep 17 00:00:00 2001 From: Ori Livneh Date: Mon, 2 Nov 2015 18:26:07 -0800 Subject: [PATCH] Add Timing interface * Add `Timing`, an interface which mimics the W3C User Timing API. It provides a canonical way to store and retrieve markers (timestamps) and measures (timestamps + duration). * As the initial use-case, use it to record 'requestShutdown'. Change-Id: I36b29162ffcc091406df025463b0e2797e52f19a --- autoload.php | 1 + includes/MediaWiki.php | 3 + includes/context/ContextSource.php | 10 ++ includes/context/DerivativeContext.php | 18 +++ includes/context/IContextSource.php | 8 + includes/context/RequestContext.php | 17 +++ includes/libs/Timing.php | 168 +++++++++++++++++++++ tests/phpunit/includes/libs/TimingTest.php | 111 ++++++++++++++ 8 files changed, 336 insertions(+) create mode 100644 includes/libs/Timing.php create mode 100644 tests/phpunit/includes/libs/TimingTest.php diff --git a/autoload.php b/autoload.php index 6c792e2aee..1c3bf20567 100644 --- a/autoload.php +++ b/autoload.php @@ -1253,6 +1253,7 @@ $wgAutoloadLocalClasses = array( 'TidyUpBug37714' => __DIR__ . '/maintenance/tidyUpBug37714.php', 'TiffHandler' => __DIR__ . '/includes/media/Tiff.php', 'TimestampException' => __DIR__ . '/includes/exception/TimestampException.php', + 'Timing' => __DIR__ . '/includes/libs/Timing.php', 'Title' => __DIR__ . '/includes/Title.php', 'TitleArray' => __DIR__ . '/includes/TitleArray.php', 'TitleArrayFromResult' => __DIR__ . '/includes/TitleArrayFromResult.php', diff --git a/includes/MediaWiki.php b/includes/MediaWiki.php index 676108c757..d048b57cfa 100644 --- a/includes/MediaWiki.php +++ b/includes/MediaWiki.php @@ -531,6 +531,9 @@ class MediaWiki { * @since 1.26 */ public function doPostOutputShutdown( $mode = 'normal' ) { + $timing = $this->context->getTiming(); + $timing->mark( 'requestShutdown' ); + // Show visible profiling data if enabled (which cannot be post-send) Profiler::instance()->logDataPageOutputOnly(); diff --git a/includes/context/ContextSource.php b/includes/context/ContextSource.php index caf5afaa86..a8850fc8bd 100644 --- a/includes/context/ContextSource.php +++ b/includes/context/ContextSource.php @@ -152,6 +152,16 @@ abstract class ContextSource implements IContextSource { return $this->getContext()->getSkin(); } + /** + * Get the Timing object + * + * @since 1.27 + * @return Timing + */ + public function getTiming() { + return $this->getContext()->getTiming(); + } + /** * Get the Stats object * diff --git a/includes/context/DerivativeContext.php b/includes/context/DerivativeContext.php index 09c3939696..1b881e49dd 100644 --- a/includes/context/DerivativeContext.php +++ b/includes/context/DerivativeContext.php @@ -72,6 +72,11 @@ class DerivativeContext extends ContextSource implements MutableContext { */ private $stats; + /** + * @var Timing + */ + private $timing; + /** * Constructor * @param IContextSource $context Context to inherit from @@ -115,6 +120,19 @@ class DerivativeContext extends ContextSource implements MutableContext { } } + /** + * Get the timing object + * + * @return Timing + */ + public function getTiming() { + if ( !is_null( $this->timing ) ) { + return $this->timing; + } else { + return $this->getContext()->getTiming(); + } + } + /** * Set the WebRequest object * diff --git a/includes/context/IContextSource.php b/includes/context/IContextSource.php index 58bf5d985e..750389ddd5 100644 --- a/includes/context/IContextSource.php +++ b/includes/context/IContextSource.php @@ -131,6 +131,14 @@ interface IContextSource { */ public function getStats(); + /** + * Get the timing object + * + * @since 1.27 + * @return Timing + */ + public function getTiming(); + /** * Get a Message object with context set. See wfMessage for parameters. * diff --git a/includes/context/RequestContext.php b/includes/context/RequestContext.php index 42a2aee642..4f8e65d01b 100644 --- a/includes/context/RequestContext.php +++ b/includes/context/RequestContext.php @@ -66,6 +66,11 @@ class RequestContext implements IContextSource, MutableContext { */ private $stats; + /** + * @var Timing + */ + private $timing; + /** * @var Config */ @@ -139,6 +144,18 @@ class RequestContext implements IContextSource, MutableContext { return $this->stats; } + /** + * Get the timing object + * + * @return Timing + */ + public function getTiming() { + if ( $this->timing === null ) { + $this->timing = new Timing(); + } + return $this->timing; + } + /** * Set the Title object * diff --git a/includes/libs/Timing.php b/includes/libs/Timing.php new file mode 100644 index 0000000000..653227e1b4 --- /dev/null +++ b/includes/libs/Timing.php @@ -0,0 +1,168 @@ +clearMarks(); + } + + /** + * Store a timestamp with the associated name (a "mark") + * + * @param string $markName The name associated with the timestamp. + * If there already exists an entry by that name, it is overwritten. + * @return array The mark that has been created. + */ + public function mark( $markName ) { + $this->entries[$markName] = array( + 'name' => $markName, + 'entryType' => 'mark', + 'startTime' => microtime( true ), + 'duration' => 0, + ); + return $this->entries[$markName]; + } + + /** + * @param string $markName The name of the mark that should + * be cleared. If not specified, all marks will be cleared. + */ + public function clearMarks( $markName = null ) { + if ( $markName !== null ) { + unset( $this->entries[$markName] ); + } else { + $this->entries = array( + 'requestStart' => array( + 'name' => 'requestStart', + 'entryType' => 'mark', + 'startTime' => isset( $_SERVER['REQUEST_TIME_FLOAT'] ) + ? $_SERVER['REQUEST_TIME_FLOAT'] + : $_SERVER['REQUEST_TIME'], + 'duration' => 0, + ), + ); + } + } + + /** + * This method stores the duration between two marks along with + * the associated name (a "measure"). + * + * If neither the startMark nor the endMark argument is specified, + * measure() will store the duration from $_SERVER['REQUEST_TIME_FLOAT'] to + * the current time. + * If the startMark argument is specified, but the endMark argument is not + * specified, measure() will store the duration from the most recent + * occurrence of the start mark to the current time. + * If both the startMark and endMark arguments are specified, measure() + * will store the duration from the most recent occurrence of the start + * mark to the most recent occurrence of the end mark. + * + * @param string $measureName + * @param string $startMark + * @param string $endMark + * @return array The measure that has been created. + */ + public function measure( $measureName, $startMark = 'requestStart', $endMark = null ) { + $start = $this->getEntryByName( $startMark ); + $startTime = $start['startTime']; + + if ( $endMark ) { + $end = $this->getEntryByName( $endMark ); + $endTime = $end['startTime']; + } else { + $endTime = microtime( true ); + } + + $this->entries[$measureName] = array( + 'name' => $measureName, + 'entryType' => 'measure', + 'startTime' => $startTime, + 'duration' => $endTime - $startTime, + ); + + return $this->entries[$measureName]; + } + + /** + * Sort entries in chronological order with respect to startTime. + */ + private function sortEntries() { + uasort( $this->entries, function ( $a, $b ) { + return 10000 * ( $a['startTime'] - $b['startTime'] ); + } ); + } + + /** + * @return array[] All entries in chronological order. + */ + public function getEntries() { + $this->sortEntries(); + return $this->entries; + } + + /** + * @param string $entryType + * @return array[] Entries (in chronological order) that have the same value + * for the entryType attribute as the $entryType parameter. + */ + public function getEntriesByType( $entryType ) { + $this->sortEntries(); + $entries = array(); + foreach ( $this->entries as $entry ) { + if ( $entry['entryType'] === $entryType ) { + $entries[] = $entry; + } + } + return $entries; + } + + /** + * @param string $name + * @return array|null Entry named $name or null if it does not exist. + */ + public function getEntryByName( $name ) { + return isset( $this->entries[$name] ) ? $this->entries[$name] : null; + } +} diff --git a/tests/phpunit/includes/libs/TimingTest.php b/tests/phpunit/includes/libs/TimingTest.php new file mode 100644 index 0000000000..93e9d6be98 --- /dev/null +++ b/tests/phpunit/includes/libs/TimingTest.php @@ -0,0 +1,111 @@ + + */ + +class TimingTest extends PHPUnit_Framework_TestCase { + + /** + * @covers Timing::clearMarks + * @covers Timing::getEntries + */ + public function testClearMarks() { + $timing = new Timing; + $this->assertCount( 1, $timing->getEntries() ); + + $timing->mark( 'a' ); + $timing->mark( 'b' ); + $this->assertCount( 3, $timing->getEntries() ); + + $timing->clearMarks( 'a' ); + $this->assertNull( $timing->getEntryByName( 'a' ) ); + $this->assertNotNull( $timing->getEntryByName( 'b' ) ); + + $timing->clearMarks(); + $this->assertCount( 1, $timing->getEntries() ); + } + + /** + * @covers Timing::mark + * @covers Timing::getEntryByName + */ + public function testMark() { + $timing = new Timing; + $timing->mark( 'a' ); + + $entry = $timing->getEntryByName( 'a' ); + $this->assertEquals( 'a', $entry['name'] ); + $this->assertEquals( 'mark', $entry['entryType'] ); + $this->assertArrayHasKey( 'startTime', $entry ); + $this->assertEquals( 0, $entry['duration'] ); + + $timing->mark( 'a' ); + $newEntry = $timing->getEntryByName( 'a' ); + $this->assertGreaterThan( $entry['startTime'], $newEntry['startTime'] ); + } + + /** + * @covers Timing::measure + */ + public function testMeasure() { + $timing = new Timing; + + $timing->mark( 'a' ); + $a = $timing->getEntryByName( 'a' ); + + $timing->mark( 'b' ); + $b = $timing->getEntryByName( 'b' ); + + $timing->measure( 'a_to_b', 'a', 'b' ); + + $entry = $timing->getEntryByName( 'a_to_b' ); + $this->assertEquals( 'a_to_b', $entry['name'] ); + $this->assertEquals( 'measure', $entry['entryType'] ); + $this->assertEquals( $a['startTime'], $entry['startTime'] ); + $this->assertEquals( $b['startTime'] - $a['startTime'], $entry['duration'] ); + } + + /** + * @covers Timing::getEntriesByType + */ + public function testGetEntriesByType() { + $timing = new Timing; + + $timing->mark( 'mark_a' ); + usleep( 100 ); + $timing->mark( 'mark_b' ); + usleep( 100 ); + $timing->mark( 'mark_c' ); + + $timing->measure( 'measure_a', 'mark_a', 'mark_b' ); + $timing->measure( 'measure_b', 'mark_b', 'mark_c' ); + + $marks = array_map( function ( $entry ) { + return $entry['name']; + }, $timing->getEntriesByType( 'mark' ) ); + + $this->assertEquals( array( 'requestStart', 'mark_a', 'mark_b', 'mark_c' ), $marks ); + + $measures = array_map( function ( $entry ) { + return $entry['name']; + }, $timing->getEntriesByType( 'measure' ) ); + + $this->assertEquals( array( 'measure_a', 'measure_b' ), $measures ); + } +} -- 2.20.1