diff --git a/.github/workflows/performance.yml b/.github/workflows/performance.yml index 6b894c8d8..99894bdde 100644 --- a/.github/workflows/performance.yml +++ b/.github/workflows/performance.yml @@ -31,7 +31,13 @@ jobs: run: | export MOODLE_DOCKER_WWWROOT=$GITHUB_WORKSPACE/moodle cp $GITHUB_WORKSPACE/moodle-docker/config.docker-template.php $GITHUB_WORKSPACE/moodle/config.php - sed -i "70i\$CFG->behat_ionic_wwwroot = \"http://moodleapp\";" $GITHUB_WORKSPACE/moodle/config.php + sed -i "58i\ 'capabilities' => [" $GITHUB_WORKSPACE/moodle/config.php + sed -i "59i\ 'extra_capabilities' => [" $GITHUB_WORKSPACE/moodle/config.php + sed -i "60i\ 'goog:loggingPrefs' => ['performance' => 'ALL']," $GITHUB_WORKSPACE/moodle/config.php + sed -i "61i\ 'chromeOptions' => ['perfLoggingPrefs' => ['traceCategories' => 'devtools.timeline']]," $GITHUB_WORKSPACE/moodle/config.php + sed -i "62i\ ]," $GITHUB_WORKSPACE/moodle/config.php + sed -i "63i\ ]," $GITHUB_WORKSPACE/moodle/config.php + sed -i "75i\$CFG->behat_ionic_wwwroot = 'http://moodleapp';" $GITHUB_WORKSPACE/moodle/config.php $GITHUB_WORKSPACE/moodle-docker/bin/moodle-docker-compose pull $GITHUB_WORKSPACE/moodle-docker/bin/moodle-docker-compose up -d $GITHUB_WORKSPACE/moodle-docker/bin/moodle-docker-wait-for-db @@ -47,9 +53,9 @@ jobs: - name: Run performance tests run: | export MOODLE_DOCKER_WWWROOT=$GITHUB_WORKSPACE/moodle - for i in {0..3} + for i in {0..2} do $GITHUB_WORKSPACE/moodle-docker/bin/moodle-docker-compose exec -T webserver sh -c "php admin/tool/behat/cli/run.php --tags="@performance" --auto-rerun" done - name: Show performance results - run: node ./scripts/print-measure-timings.js $GITHUB_WORKSPACE/moodle/behatmeasuretimings/ + run: node ./scripts/print-performance-measures.js $GITHUB_WORKSPACE/moodle/behatperformancemeasures/ diff --git a/scripts/print-measure-timings.js b/scripts/print-measure-timings.js deleted file mode 100755 index ccd9356e1..000000000 --- a/scripts/print-measure-timings.js +++ /dev/null @@ -1,40 +0,0 @@ -#!/usr/bin/env node - -// (C) Copyright 2015 Moodle Pty Ltd. -// -// Licensed under the Apache License, Version 2.0 (the "License"); -// you may not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, software -// distributed under the License is distributed on an "AS IS" BASIS, -// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. -// See the License for the specific language governing permissions and -// limitations under the License. - -const { readdirSync, readFileSync } = require('fs'); - -if (process.argv.length < 3) { - console.error('Missing measure timings storage path argument'); - process.exit(1); -} - -const measureTimingsStoragePath = process.argv[2].trimRight('/') + '/'; -const files = readdirSync(measureTimingsStoragePath); -const measureTimingsDurations = {}; - -for (const file of files) { - const measureTiming = JSON.parse(readFileSync(measureTimingsStoragePath + file)); - - measureTimingsDurations[measureTiming.measure] = measureTimingsDurations[measureTiming.measure] ?? []; - measureTimingsDurations[measureTiming.measure].push(measureTiming.duration); -} - -for (const [measure, durations] of Object.entries(measureTimingsDurations)) { - const totalRuns = durations.length; - const averageDuration = Math.round(durations.reduce((total, duration) => total + duration) / totalRuns); - - console.log(`${measure} took an average of ${averageDuration}ms per run (in ${totalRuns} runs)`); -} diff --git a/scripts/print-performance-measures.js b/scripts/print-performance-measures.js new file mode 100755 index 000000000..064a88181 --- /dev/null +++ b/scripts/print-performance-measures.js @@ -0,0 +1,75 @@ +#!/usr/bin/env node + +// (C) Copyright 2015 Moodle Pty Ltd. +// +// Licensed under the Apache License, Version 2.0 (the "License"); +// you may not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, software +// distributed under the License is distributed on an "AS IS" BASIS, +// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +// See the License for the specific language governing permissions and +// limitations under the License. + +const { readdirSync, readFileSync } = require('fs'); + +if (process.argv.length < 3) { + console.error('Missing measure timings storage path argument'); + process.exit(1); +} + +const performanceMeasuresStoragePath = process.argv[2].trimRight('/') + '/'; +const files = readdirSync(performanceMeasuresStoragePath); +const performanceMeasures = {}; + +if (files.length === 0) { + console.log('No logs found!'); + process.exit(0); +} + +// Aggregate data +for (const file of files) { + const performanceMeasure = JSON.parse(readFileSync(performanceMeasuresStoragePath + file)); + + performanceMeasures[performanceMeasure.name] = performanceMeasures[performanceMeasure.name] ?? { + duration: [], + scripting: [], + styling: [], + blocking: [], + longTasks: [], + networking: [], + }; + performanceMeasures[performanceMeasure.name].duration.push(performanceMeasure.duration); + performanceMeasures[performanceMeasure.name].scripting.push(performanceMeasure.scripting); + performanceMeasures[performanceMeasure.name].styling.push(performanceMeasure.styling); + performanceMeasures[performanceMeasure.name].blocking.push(performanceMeasure.blocking); + performanceMeasures[performanceMeasure.name].longTasks.push(performanceMeasure.longTasks); + performanceMeasures[performanceMeasure.name].networking.push(performanceMeasure.networking); +} + +// Calculate averages +for (const [name, { duration, scripting, styling, blocking, longTasks, networking }] of Object.entries(performanceMeasures)) { + const totalRuns = duration.length; + const averageDuration = Math.round(duration.reduce((total, duration) => total + duration) / totalRuns); + const averageScripting = Math.round(scripting.reduce((total, scripting) => total + scripting) / totalRuns); + const averageStyling = Math.round(styling.reduce((total, styling) => total + styling) / totalRuns); + const averageBlocking = Math.round(blocking.reduce((total, blocking) => total + blocking) / totalRuns); + const averageLongTasks = Math.round(longTasks.reduce((total, longTasks) => total + longTasks) / totalRuns); + const averageNetworking = Math.round(networking.reduce((total, networking) => total + networking) / totalRuns); + + performanceMeasures[name] = { + 'Total duration': `${averageDuration}ms`, + 'Scripting': `${averageScripting}ms`, + 'Styling': `${averageStyling}ms`, + 'Blocking': `${averageBlocking}ms`, + '# Network requests': averageNetworking, + '# Long Tasks': averageLongTasks, + '# runs': totalRuns, + }; +} + +// Display data +console.table(performanceMeasures); diff --git a/tests/behat/behat_performance.php b/tests/behat/behat_performance.php index 1097c982e..499fc1fea 100644 --- a/tests/behat/behat_performance.php +++ b/tests/behat/behat_performance.php @@ -18,7 +18,7 @@ use Behat\Mink\Exception\DriverException; use Behat\Mink\Exception\ExpectationException; require_once(__DIR__ . '/../../../../lib/behat/behat_base.php'); -require_once(__DIR__ . '/classes/measure_timing.php'); +require_once(__DIR__ . '/classes/performance_measure.php'); /** * Behat step definitions to measure performance. @@ -28,25 +28,25 @@ class behat_performance extends behat_base { /** * @var array */ - private $timings = []; + private $measures = []; /** - * Start timing a performance measure. + * Start measuring performance. * - * @When /^I start timing "([^"]+)"$/ + * @When /^I start measuring "([^"]+)"$/ */ - public function i_start_timing(string $measure) { - $this->timings[$measure] = new measure_timing($measure); - $this->timings[$measure]->start(); + public function i_start_measuring(string $name) { + $this->measures[$name] = new performance_measure($name, $this->getSession()->getDriver()); + $this->measures[$name]->start(); } /** - * Stop timing a performance measure. + * Stop measuring performance. * - * @When /^I stop timing "([^"]+)"$/ + * @When /^I stop measuring "([^"]+)"$/ */ - public function i_stop_timing(string $measure) { - $this->get_measure_timing($measure)->end(); + public function i_stop_measuring(string $name) { + $this->get_performance_measure($name)->end(); } /** @@ -55,11 +55,11 @@ class behat_performance extends behat_base { * @Then /^"([^"]+)" should have taken (less than|more than|exactly) (\d+(?:\.\d+)? (?:seconds|milliseconds))$/ */ public function timing_should_have_taken(string $measure, Closure $comparison, float $expectedtime) { - $measuretiming = $this->get_measure_timing($measure); + $measuretiming = $this->get_performance_measure($measure); if (!call_user_func($comparison, $measuretiming->duration, $expectedtime)) { throw new ExpectationException( - "Expected timing for '$measure' measure failed! (took {$measuretiming->duration}ms)", + "Expected duration for '$measure' failed! (took {$measuretiming->duration}ms)", $this->getSession()->getDriver() ); } @@ -112,17 +112,17 @@ class behat_performance extends behat_base { } /** - * Get measure timing by name. + * Get performance measure by name. * - * @param string $measure Measure timing name. - * @return measure_timing Measure timing. + * @param string $name Performance measure name. + * @return performance_measure Performance measure. */ - private function get_measure_timing(string $measure): measure_timing { - if (!isset($this->timings[$measure])) { - throw new DriverException("Timing for '$measure' measure does not exist."); + private function get_performance_measure(string $name): performance_measure { + if (!isset($this->measures[$name])) { + throw new DriverException("'$name' performance measure does not exist."); } - return $this->timings[$measure]; + return $this->measures[$name]; } } diff --git a/tests/behat/classes/measure_timing.php b/tests/behat/classes/measure_timing.php deleted file mode 100644 index 4baa699f9..000000000 --- a/tests/behat/classes/measure_timing.php +++ /dev/null @@ -1,94 +0,0 @@ -. - -/** - * Performance timing for one particular measure. - */ -class measure_timing { - - const STORAGE_FOLDER = '/behatmeasuretimings/'; - - /** - * @var string - */ - public $measure; - - /** - * @var int - */ - public $start; - - /** - * @var int - */ - public $end; - - /** - * @var int - */ - public $duration; - - public function __construct(string $measure) { - $this->measure = $measure; - } - - /** - * Start timing. - */ - public function start(): void { - $this->start = $this->now(); - } - - /** - * Stop timing. - */ - public function end(): void { - $this->end = $this->now(); - $this->duration = $this->end - $this->start; - } - - /** - * Persist measure timing in storage. - */ - public function store(): void { - global $CFG; - - $storagefolderpath = $CFG->dirroot . static::STORAGE_FOLDER; - - if (!file_exists($storagefolderpath)) { - mkdir($storagefolderpath); - } - - $data = [ - 'measure' => $this->measure, - 'start' => $this->start, - 'end' => $this->end, - 'duration' => $this->duration, - ]; - - file_put_contents($storagefolderpath . time() . '.json', json_encode($data)); - } - - /** - * Get current time. - * - * @return int Current time in milliseconds. - */ - private function now(): int { - return round(microtime(true) * 1000); - } - -} diff --git a/tests/behat/classes/performance_measure.php b/tests/behat/classes/performance_measure.php new file mode 100644 index 000000000..6646f5ce4 --- /dev/null +++ b/tests/behat/classes/performance_measure.php @@ -0,0 +1,276 @@ +. + +use Moodle\BehatExtension\Driver\WebDriver; + +/** + * Performance measures for one particular metric. + */ +class performance_measure implements behat_app_listener { + + const STORAGE_FOLDER = '/behatperformancemeasures/'; + + /** + * @var string + */ + public $name; + + /** + * @var int + */ + public $start; + + /** + * @var int + */ + public $end; + + /** + * @var int + */ + public $duration; + + /** + * @var int + */ + public $scripting; + + /** + * @var int + */ + public $styling; + + /** + * @var int + */ + public $blocking; + + /** + * @var int + */ + public $networking; + + /** + * @var array + */ + private $longTasks = []; + + /** + * @var Closure + */ + private $behatAppUnsubscribe; + + /** + * @var Moodle\BehatExtension\Driver\WebDriver + */ + private $driver; + + public function __construct(string $name, WebDriver $driver) { + $this->name = $name; + $this->driver = $driver; + } + + /** + * Start timing. + */ + public function start(): void { + $this->start = $this->now(); + + $this->observeLongTasks(); + + $this->behatAppUnsubscribe = behat_app::listen($this); + } + + /** + * Stop timing. + */ + public function end(): void { + $this->end = $this->now(); + + $this->stopLongTasksObserver(); + + call_user_func($this->behatAppUnsubscribe); + $this->behatAppUnsubscribe = null; + + $this->analyseDuration(); + $this->analyseLongTasks(); + $this->analysePerformanceLogs(); + } + + /** + * Persist measure logs in storage. + */ + public function store(): void { + global $CFG; + + $storagefolderpath = $CFG->dirroot . static::STORAGE_FOLDER; + + if (!file_exists($storagefolderpath)) { + mkdir($storagefolderpath); + } + + $data = [ + 'name' => $this->name, + 'start' => $this->start, + 'end' => $this->end, + 'duration' => $this->duration, + 'scripting' => $this->scripting, + 'styling' => $this->styling, + 'blocking' => $this->blocking, + 'longTasks' => count($this->longTasks), + 'networking' => $this->networking, + ]; + + file_put_contents($storagefolderpath . time() . '.json', json_encode($data)); + } + + /** + * @inheritdoc + */ + public function on_app_load(): void { + if (is_null($this->start) || !is_null($this->end)) { + return; + } + + $this->observeLongTasks(); + } + + /** + * @inheritdoc + */ + public function on_app_unload(): void { + $this->stopLongTasksObserver(); + } + + /** + * Get current time. + * + * @return int Current time in milliseconds. + */ + private function now(): int { + return $this->driver->evaluateScript('Date.now();'); + } + + /** + * Start observing long tasks. + */ + private function observeLongTasks(): void { + $this->driver->executeScript(" + if (window.MA_PERFORMANCE_OBSERVER) return; + + window.MA_LONG_TASKS = []; + window.MA_PERFORMANCE_OBSERVER = new PerformanceObserver(list => { + for (const entry of list.getEntries()) { + window.MA_LONG_TASKS.push(entry); + } + }); + window.MA_PERFORMANCE_OBSERVER.observe({ entryTypes: ['longtask'] }); + "); + } + + /** + * Flush Performance observer. + */ + private function stopLongTasksObserver(): void { + $newLongTasks = $this->driver->evaluateScript(" + return (function() { + if (!window.MA_PERFORMANCE_OBSERVER) { + return []; + } + + window.MA_PERFORMANCE_OBSERVER.disconnect(); + + const observer = window.MA_PERFORMANCE_OBSERVER; + const longTasks = window.MA_LONG_TASKS; + + delete window.MA_PERFORMANCE_OBSERVER; + delete window.MA_LONG_TASKS; + + return [...longTasks, ...observer.takeRecords()]; + })(); + "); + + if ($newLongTasks) { + $this->longTasks = array_merge($this->longTasks, $newLongTasks); + } + } + + /** + * Analyse duration. + */ + private function analyseDuration(): void { + $this->duration = $this->end - $this->start; + } + + /** + * Analyse long tasks. + */ + private function analyseLongTasks(): void { + $blocking = 0; + + foreach ($this->longTasks as $longTask) { + $blocking += $longTask['duration'] - 50; + } + + $this->blocking = $blocking; + } + + /** + * Analyse performance logs. + */ + private function analysePerformanceLogs(): void { + global $CFG; + + $scripting = 0; + $styling = 0; + $networking = 0; + $logs = $this->driver->getWebDriver()->manage()->getLog('performance'); + + foreach ($logs as $log) { + // TODO this should filter by end time as well, but it seems like the timestamps are not + // working as expected. + if (($log['timestamp'] < $this->start)) { + continue; + } + + $message = json_decode($log['message'])->message; + $messagename = $message->params->name ?? ''; + + if (in_array($messagename, ['FunctionCall', 'GCEvent', 'MajorGC', 'MinorGC', 'EvaluateScript'])) { + $scripting += $message->params->dur; + + continue; + } + + if (in_array($messagename, ['UpdateLayoutTree', 'RecalculateStyles', 'ParseAuthorStyleSheet'])) { + $styling += $message->params->dur; + + continue; + } + + if (in_array($messagename, ['XHRLoad']) && !str_starts_with($message->params->args->data->url, $CFG->behat_ionic_wwwroot)) { + $networking++; + + continue; + } + } + + $this->scripting = round($scripting / 1000); + $this->styling = round($styling / 1000); + $this->networking = $networking; + } + +} diff --git a/tests/behat/performance.feature b/tests/behat/performance.feature index 203737163..f955ff63e 100644 --- a/tests/behat/performance.feature +++ b/tests/behat/performance.feature @@ -1,32 +1,34 @@ @app @javascript @performance Feature: Measure performance. -Scenario: [FCP] First Contentful Paint - Given I start timing "FCP" +Scenario: First Contentful Paint + Given I start measuring "First Contentful Paint" When I launch the app runtime Then I should find "Welcome to the Moodle App!" in the app - When I stop timing "FCP" - Then "FCP" should have taken less than 5 seconds + When I stop measuring "First Contentful Paint" + Then "First Contentful Paint" should have taken less than 6 seconds -Scenario: [TTI] Time to Interactive - Given I start timing "TTI" +Scenario: Time to Interactive + Given I start measuring "Time to Interactive" When I launch the app runtime Then I should find "Welcome to the Moodle App!" in the app When I press "Skip" in the app - Then I should find "Connect to Moodle" in the app + Then I should not find "Skip" in the app + And I should find "Connect to Moodle" in the app - When I stop timing "TTI" - Then "TTI" should have taken less than 6 seconds + When I stop measuring "Time to Interactive" + Then "Time to Interactive" should have taken less than 7 seconds -Scenario: [TBT] Total Blocking Time +Scenario: Total Blocking Time Given I launch the app runtime Then I should find "Welcome to the Moodle App!" in the app - When I start timing "TBT" + When I start measuring "Total Blocking Time" And I press "Skip" in the app - Then I should find "Connect to Moodle" in the app + Then I should not find "Skip" in the app + And I should find "Connect to Moodle" in the app - When I stop timing "TBT" - Then "TBT" should have taken less than 2 seconds + When I stop measuring "Total Blocking Time" + Then "Total Blocking Time" should have taken less than 2 seconds