EVOgeek
/
Vmeda.Online
1
0
Fork 0
Code Issues Pull Requests Packages Projects Releases Wiki Activity

MOBILE-3875 ci: Improve performance measures

main
Noel De Martin 2021-09-28 17:47:36 +02:00
parent 74891f4e2f
commit 2f4967b101
7 changed files with 396 additions and 171 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

12
.github/workflows/performance.yml vendored
View File

@ -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/

40
scripts/print-measure-timings.js
View File

@ -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)`);
}

75
scripts/print-performance-measures.js 100755
View File

@ -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);

40
tests/behat/behat_performance.php
View File

@ -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];
}
}

94
tests/behat/classes/measure_timing.php
View File

@ -1,94 +0,0 @@
<?php
// This file is part of Moodle - http://moodle.org/
//
// Moodle is free software: you can redistribute it and/or modify
// it under the terms of the GNU General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// Moodle is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU General Public License for more details.
//
// You should have received a copy of the GNU General Public License
// along with Moodle. If not, see <http://www.gnu.org/licenses/>.
/**
* 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);
}
}

276
tests/behat/classes/performance_measure.php 100644
View File

@ -0,0 +1,276 @@
<?php
// This file is part of Moodle - http://moodle.org/
//
// Moodle is free software: you can redistribute it and/or modify
// it under the terms of the GNU General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
//
// Moodle is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU General Public License for more details.
//
// You should have received a copy of the GNU General Public License
// along with Moodle. If not, see <http://www.gnu.org/licenses/>.
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;
}
}

30
tests/behat/performance.feature
View File

@ -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