diff --git a/lib/classes/lock/lock.php b/lib/classes/lock/lock.php index 7012bcf1888..8bb332911b1 100644 --- a/lib/classes/lock/lock.php +++ b/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. diff --git a/lib/classes/lock/lock_config.php b/lib/classes/lock/lock_config.php index 31f3082e466..6843d976e66 100644 --- a/lib/classes/lock/lock_config.php +++ b/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; } diff --git a/lib/classes/lock/timing_wrapper_lock_factory.php b/lib/classes/lock/timing_wrapper_lock_factory.php new file mode 100644 index 00000000000..8563664e1d4 --- /dev/null +++ b/lib/classes/lock/timing_wrapper_lock_factory.php @@ -0,0 +1,172 @@ +. + +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); + } +} diff --git a/lib/moodlelib.php b/lib/moodlelib.php index fb26c16ad80..2f6542106ff 100644 --- a/lib/moodlelib.php +++ b/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'] .= ''; $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 ? '✓' : '❌'; + $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'] = '
'.$info['html'].'
'; return $info; } diff --git a/lib/tests/lock/timing_wrapper_lock_factory_test.php b/lib/tests/lock/timing_wrapper_lock_factory_test.php new file mode 100644 index 00000000000..a05815d4cd7 --- /dev/null +++ b/lib/tests/lock/timing_wrapper_lock_factory_test.php @@ -0,0 +1,65 @@ +. + +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); + } +} diff --git a/lib/tests/lock_config_test.php b/lib/tests/lock_config_test.php index 39c0dab3326..adc689a1607 100644 --- a/lib/tests/lock_config_test.php +++ b/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'); diff --git a/lib/tests/moodlelib_test.php b/lib/tests/moodlelib_test.php index 1f6876da60f..770a76baa98 100644 --- a/lib/tests/moodlelib_test.php +++ b/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('~