Merge branch 'MDL-74960-master' of https://github.com/sammarshallou/moodle

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']);
+    }
 }