MDL-74960 core\lock: Performance info - display lock performance

Show performance information about locks (time taken to acquire lock,
time lock is held for) in the 'perfinfo' display.

Also show existing information (that was already calculated but not
shown before) about the session lock, which is not a 'core\lock' type
lock, but the information is similarly useful.

lib/classes/lock/lock.php

@@ -70,6 +70,19 @@ class lock {
         }
     }
 
+    /**
+     * Sets the lock factory that owns a lock. This function should not be called under normal use.
+     * It is intended only for cases like {@see timing_wrapper_lock_factory} where we wrap a lock
+     * factory.
+     *
+     * When used, it should be called immediately after constructing the lock.
+     *
+     * @param lock_factory $factory New lock factory that owns this lock
+     */
+    public function init_factory(lock_factory $factory): void {
+        $this->factory = $factory;
+    }
+
     /**
      * Return the unique key representing this lock.
      * @return string|int lock key.

lib/classes/lock/lock_config.php

@@ -84,11 +84,20 @@ class lock_config {
      * @throws \coding_exception
      */
     public static function get_lock_factory(string $type): \core\lock\lock_factory {
+        global $CFG;
+
         $lockfactoryclass = self::get_lock_factory_class();
         $lockfactory = new $lockfactoryclass($type);
         if (!$lockfactory->is_available()) {
             throw new \coding_exception("Lock factory class $lockfactoryclass is not available.");
         }
+
+        // If tracking performance, insert a timing wrapper to keep track of lock delays.
+        if (defined('MDL_PERF') || !empty($CFG->perfdebug)) {
+            $wrapper = new timing_wrapper_lock_factory($type, $lockfactory);
+            $lockfactory = $wrapper;
+        }
+
         return $lockfactory;
     }
 

lib/classes/lock/timing_wrapper_lock_factory.php

@@ -0,0 +1,172 @@
+<?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/>.
+
+namespace core\lock;
+
+/**
+ * Timing wrapper around a lock factory.
+ *
+ * This passes all calls through to the underlying lock factory, but adds timing information on how
+ * long it takes to get a lock and how long the lock is held for.
+ *
+ * @package core
+ * @category lock
+ * @copyright 2022 The Open University
+ * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class timing_wrapper_lock_factory implements lock_factory {
+
+    /** @var lock_factory Real lock factory */
+    protected $factory;
+
+    /** @var string Type (Frankenstyle) used for these locks */
+    protected $type;
+
+    /**
+     * Constructor required by interface.
+     *
+     * @param string $type Type (should be same as passed to real lock factory)
+     * @param lock_factory $factory Real lock factory
+     */
+    public function __construct($type, lock_factory $factory = null) {
+        $this->type = $type;
+        if (!$factory) {
+            // This parameter has to be optional because of the interface, but it is actually
+            // required.
+            throw new \coding_exception('The $factory parameter must be specified');
+        }
+        $this->factory = $factory;
+    }
+
+    /**
+     * Gets the real lock factory that this is wrapping.
+     *
+     * @return lock_factory ReaL lock factory
+     */
+    public function get_real_factory(): lock_factory {
+        return $this->factory;
+    }
+
+    /**
+     * Implementation of lock_factory::get_lock that defers to function inner_get_lock and keeps
+     * track of how long it took.
+     *
+     * @param string $resource Identifier for the lock
+     * @param int $timeout Number of seconds to wait for a lock before giving up
+     * @param int $maxlifetime Number of seconds to wait before reclaiming a stale lock
+     * @return \core\lock\lock|boolean - An instance of \core\lock\lock if the lock was obtained, or false.
+     */
+    public function get_lock($resource, $timeout, $maxlifetime = 86400) {
+        global $PERF;
+
+        $before = microtime(true);
+
+        $result = $this->factory->get_lock($resource, $timeout, $maxlifetime);
+
+        $after = microtime(true);
+        $duration = $after - $before;
+        if (empty($PERF->locks)) {
+            $PERF->locks = [];
+        }
+        $lockdata = (object) [
+            'type' => $this->type,
+            'resource' => $resource,
+            'wait' => $duration,
+            'success' => (bool)$result
+        ];
+        if ($result) {
+            $lockdata->lock = $result;
+            $lockdata->timestart = $after;
+            $result->init_factory($this);
+        }
+        $PERF->locks[] = $lockdata;
+
+        return $result;
+    }
+
+    /**
+     * Release a lock that was previously obtained with @lock.
+     *
+     * @param lock $lock - The lock to release.
+     * @return boolean - True if the lock is no longer held (including if it was never held).
+     */
+    public function release_lock(lock $lock) {
+        global $PERF;
+
+        // Find this lock in the list of locks we got, looking backwards since it is probably
+        // the last one.
+        for ($index = count($PERF->locks) - 1; $index >= 0; $index--) {
+            $lockdata = $PERF->locks[$index];
+            if (!empty($lockdata->lock) && $lockdata->lock === $lock) {
+                // Update the time held.
+                unset($lockdata->lock);
+                $lockdata->held = microtime(true) - $lockdata->timestart;
+                break;
+            }
+        }
+
+        return $this->factory->release_lock($lock);
+    }
+
+    /**
+     * Calls parent factory to check if it supports timeout.
+     *
+     * @return boolean False if attempting to get a lock will block indefinitely.
+     */
+    public function supports_timeout() {
+        return $this->factory->supports_timeout();
+    }
+
+    /**
+     * Calls parent factory to check if it auto-releases locks.
+     *
+     * @return boolean True if this lock type will be automatically released when the current process ends.
+     */
+    public function supports_auto_release() {
+        return $this->factory->supports_auto_release();
+    }
+
+    /**
+     * Calls parent factory to check if it supports recursion.
+     *
+     * @deprecated since Moodle 3.10.
+     * @return boolean True if attempting to get 2 locks on the same resource will "stack"
+     */
+    public function supports_recursion() {
+        return $this->factory->supports_recursion();
+    }
+
+    /**
+     * Calls parent factory to check if it is available.
+     *
+     * @return boolean True if this lock type is available in this environment.
+     */
+    public function is_available() {
+        return $this->factory->is_available();
+    }
+
+    /**
+     * Calls parent factory to try to extend the lock.
+     *
+     * @deprecated since Moodle 3.10.
+     * @param lock $lock Lock obtained from this factory
+     * @param int $maxlifetime New max time to hold the lock
+     * @return boolean True if the lock was extended.
+     */
+    public function extend_lock(lock $lock, $maxlifetime = 86400) {
+        return $this->factory->extend_lock($lock, $maxlifetime);
+    }
+}

lib/moodlelib.php

@@ -9621,6 +9621,15 @@ function get_performance_info() {
         $info['txt'] .= $si['txt'];
     }
 
+    // Display time waiting for session if applicable.
+    if (!empty($PERF->sessionlock['wait'])) {
+        $sessionwait = number_format($PERF->sessionlock['wait'], 3) . ' secs';
+        $info['html'] .= html_writer::tag('li', 'Session wait: ' . $sessionwait, [
+            'class' => 'sessionwait col-sm-4'
+        ]);
+        $info['txt'] .= 'sessionwait: ' . $sessionwait . ' ';
+    }
+
     $info['html'] .= '</ul>';
     $html = '';
     if ($stats = cache_helper::get_stats()) {
@@ -9853,6 +9862,53 @@ function get_performance_info() {
         $info['txt'] .= 'Caches used (hits/misses/sets): 0/0/0 ';
     }
 
+    // Display lock information if any.
+    if (!empty($PERF->locks)) {
+        $table = new html_table();
+        $table->attributes['class'] = 'locktimings table table-dark table-sm w-auto table-bordered';
+        $table->head = ['Lock', 'Waited (s)', 'Obtained', 'Held for (s)'];
+        $table->align = ['left', 'right', 'center', 'right'];
+        $table->data = [];
+        $text = 'Locks (waited/obtained/held):';
+        foreach ($PERF->locks as $locktiming) {
+            $row = [];
+            $row[] = s($locktiming->type . '/' . $locktiming->resource);
+            $text .= ' ' . $locktiming->type . '/' . $locktiming->resource . ' (';
+
+            // The time we had to wait to get the lock.
+            $roundedtime = number_format($locktiming->wait, 1);
+            $cell = new html_table_cell($roundedtime);
+            if ($locktiming->wait > 0.5) {
+                $cell->attributes = ['class' => 'bg-warning text-dark'];
+            }
+            $row[] = $cell;
+            $text .= $roundedtime . '/';
+
+            // Show a tick or cross for success.
+            $row[] = $locktiming->success ? '&#x2713;' : '&#x274c;';
+            $text .= ($locktiming->success ? 'y' : 'n') . '/';
+
+            // If applicable, show how long we held the lock before releasing it.
+            if (property_exists($locktiming, 'held')) {
+                $roundedtime = number_format($locktiming->held, 1);
+                $cell = new html_table_cell($roundedtime);
+                if ($locktiming->held > 0.5) {
+                    $cell->attributes = ['class' => 'bg-warning text-dark'];
+                }
+                $row[] = $cell;
+                $text .= $roundedtime;
+            } else {
+                $row[] = '-';
+                $text .= '-';
+            }
+            $text .= ')';
+
+            $table->data[] = $row;
+        }
+        $info['html'] .= html_writer::table($table);
+        $info['txt'] .= $text . '. ';
+    }
+
     $info['html'] = '<div class="performanceinfo siteinfo container-fluid px-md-0 overflow-auto pt-3">'.$info['html'].'</div>';
     return $info;
 }

lib/tests/lock/timing_wrapper_lock_factory_test.php

@@ -0,0 +1,65 @@
+<?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/>.
+
+namespace core\lock;
+
+/**
+ * Unit tests for the lock factory.
+ *
+ * @covers \core\lock\timing_wrapper_lock_factory
+ * @package core
+ * @copyright 2022 The Open University
+ * @license http://www.gnu.org/copyleft/gpl.html GNU GPL v3 or later
+ */
+class timing_wrapper_lock_factory_test extends \advanced_testcase {
+
+    /**
+     * Tests lock timing wrapper class.
+     */
+    public function test_lock_timing(): void {
+        global $PERF;
+
+        $this->resetAfterTest();
+
+        // Reset the storage in case previous tests have added anything.
+        unset($PERF->locks);
+
+        // Set up a lock factory using the db record lock type which is always available.
+        $lockfactory = new timing_wrapper_lock_factory('phpunit',
+                new db_record_lock_factory('phpunit'));
+
+        // Get 2 locks and release them.
+        $before = microtime(true);
+        $lock1 = $lockfactory->get_lock('frog', 2);
+        $lock2 = $lockfactory->get_lock('toad', 2);
+        $lock2->release();
+        $lock1->release();
+        $duration = microtime(true) - $before;
+
+        // Confirm that perf info is now logged and appears plausible.
+        $this->assertObjectHasAttribute('locks', $PERF);
+        $this->assertEquals('phpunit', $PERF->locks[0]->type);
+        $this->assertEquals('frog', $PERF->locks[0]->resource);
+        $this->assertTrue($PERF->locks[0]->wait <= $duration);
+        $this->assertTrue($PERF->locks[0]->success);
+        $this->assertTrue($PERF->locks[0]->held <= $duration);
+        $this->assertEquals('phpunit', $PERF->locks[1]->type);
+        $this->assertEquals('toad', $PERF->locks[1]->resource);
+        $this->assertTrue($PERF->locks[1]->wait <= $duration);
+        $this->assertTrue($PERF->locks[1]->success);
+        $this->assertTrue($PERF->locks[1]->held <= $duration);
+    }
+}

lib/tests/lock_config_test.php

@@ -59,6 +59,9 @@ class lock_config_test extends \advanced_testcase {
         // Test explicit file locks.
         $CFG->lock_factory = '\core\lock\file_lock_factory';
         $factory = \core\lock\lock_config::get_lock_factory('cache');
+        if ($factory instanceof \core\lock\timing_wrapper_lock_factory) {
+            $factory = $factory->get_real_factory();
+        }
         $this->assertTrue($factory instanceof \core\lock\file_lock_factory,
                 'Get an explicit file lock factory');
 
@@ -74,6 +77,9 @@ class lock_config_test extends \advanced_testcase {
         // Test explicit db locks.
         $CFG->lock_factory = '\core\lock\db_record_lock_factory';
         $factory = \core\lock\lock_config::get_lock_factory('cache');
+        if ($factory instanceof \core\lock\timing_wrapper_lock_factory) {
+            $factory = $factory->get_real_factory();
+        }
         $this->assertTrue($factory instanceof \core\lock\db_record_lock_factory,
                 'Get an explicit db record lock factory');
 

lib/tests/moodlelib_test.php

@@ -5354,4 +5354,74 @@ EOF;
         $default = get_default_home_page();
         $this->assertEquals(HOMEPAGE_MYCOURSES, $default);
     }
+
+    /**
+     * Tests the get_performance_info function with regard to locks.
+     *
+     * @covers ::get_performance_info
+     */
+    public function test_get_performance_info_locks(): void {
+        global $PERF;
+
+        // Unset lock data just in case previous tests have set it.
+        unset($PERF->locks);
+
+        // With no lock data, there should be no information about locks in the results.
+        $result = get_performance_info();
+        $this->assertStringNotContainsString('Lock', $result['html']);
+        $this->assertStringNotContainsString('Lock', $result['txt']);
+
+        // Rather than really do locks, just fill the array with fake data in the right format.
+        $PERF->locks = [
+            (object) [
+                'type' => 'phpunit',
+                'resource' => 'lock1',
+                'wait' => 0.59,
+                'success' => true,
+                'held' => '6.04'
+            ], (object) [
+                'type' => 'phpunit',
+                'resource' => 'lock2',
+                'wait' => 0.91,
+                'success' => false
+            ]
+        ];
+        $result = get_performance_info();
+
+        // Extract HTML table rows.
+        $this->assertEquals(1, preg_match('~<table class="locktimings.*?</table>~s',
+                $result['html'], $matches));
+        $this->assertEquals(3, preg_match_all('~<tr[> ].*?</tr>~s', $matches[0], $matches2));
+        $rows = $matches2[0];
+
+        // Check header.
+        $this->assertMatchesRegularExpression('~Lock.*Waited.*Obtained.*Held~s', $rows[0]);
+        // Check both locks.
+        $this->assertMatchesRegularExpression('~phpunit/lock1.*0\.6.*&#x2713;.*6\.0~s', $rows[1]);
+        $this->assertMatchesRegularExpression('~phpunit/lock2.*0\.9.*&#x274c;.*-~s', $rows[2]);
+
+        $this->assertStringContainsString('Locks (waited/obtained/held): ' .
+                'phpunit/lock1 (0.6/y/6.0) phpunit/lock2 (0.9/n/-).', $result['txt']);
+    }
+
+    /**
+     * Tests the get_performance_info function with regard to session wait time.
+     *
+     * @covers ::get_performance_info
+     */
+    public function test_get_performance_info_session_wait(): void {
+        global $PERF;
+
+        // With no session lock data, there should be no session wait information in the results.
+        unset($PERF->sessionlock);
+        $result = get_performance_info();
+        $this->assertStringNotContainsString('Session wait', $result['html']);
+        $this->assertStringNotContainsString('sessionwait', $result['txt']);
+
+        // With suitable data, it should be included in the result.
+        $PERF->sessionlock = ['wait' => 4.2];
+        $result = get_performance_info();
+        $this->assertStringContainsString('Session wait: 4.200 secs', $result['html']);
+        $this->assertStringContainsString('sessionwait: 4.200 secs', $result['txt']);
+    }
 }