Merge pull request #2960 from NoelDeMartin/MOBILE-3875

MOBILE-3875 ci: Improve performance measures

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

scripts/print-measure-timings.js

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

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

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) {
+    public function i_start_measuring(string $name) {
-        $this->timings[$measure] = new measure_timing($measure);
+        $this->measures[$name] = new performance_measure($name, $this->getSession()->getDriver());
-        $this->timings[$measure]->start();
+        $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) {
+    public function i_stop_measuring(string $name) {
-        $this->get_measure_timing($measure)->end();
+        $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.
+     * @param string $name Performance measure name.
-     * @return measure_timing Measure timing.
+     * @return performance_measure Performance measure.
      */
-    private function get_measure_timing(string $measure): measure_timing {
+    private function get_performance_measure(string $name): performance_measure {
-        if (!isset($this->timings[$measure])) {
+        if (!isset($this->measures[$name])) {
-            throw new DriverException("Timing for '$measure' measure does not exist.");
+            throw new DriverException("'$name' performance measure does not exist.");
         }
 
-        return $this->timings[$measure];
+        return $this->measures[$name];
     }
 
 }

tests/behat/classes/measure_timing.php

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

tests/behat/classes/performance_measure.php

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

tests/behat/performance.feature

@@ -1,32 +1,34 @@
 @app @javascript @performance
 Feature: Measure performance.
 
-Scenario: [FCP] First Contentful Paint
+Scenario: First Contentful Paint
-    Given I start timing "FCP"
+    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"
+    When I stop measuring "First Contentful Paint"
-    Then "FCP" should have taken less than 5 seconds
+    Then "First Contentful Paint" should have taken less than 6 seconds
 
-Scenario: [TTI] Time to Interactive
+Scenario: Time to Interactive
-    Given I start timing "TTI"
+    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"
+    When I stop measuring "Time to Interactive"
-    Then "TTI" should have taken less than 6 seconds
+    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"
+    When I stop measuring "Total Blocking Time"
-    Then "TBT" should have taken less than 2 seconds
+    Then "Total Blocking Time" should have taken less than 2 seconds