From f7a9b46920d848db109788dd5a2592fdb13911f1 Mon Sep 17 00:00:00 2001 From: Benjamin Walker Date: Tue, 7 May 2024 10:34:57 +1000 Subject: [PATCH] Add session lock info #314 --- classes/helper.php | 53 +++++++++++++++++++++++++++----- classes/profile.php | 6 +++- classes/profile_table.php | 16 +++++++++- classes/recent_profile_table.php | 1 + classes/script_metadata.php | 31 +++++++++++++++++++ classes/web_processor.php | 3 ++ db/install.xml | 3 ++ db/upgrade.php | 31 +++++++++++++++++++ lang/en/tool_excimer.php | 9 ++++++ profile.php | 15 ++++++++- templates/profile.mustache | 18 +++++++++++ version.php | 4 +-- 12 files changed, 178 insertions(+), 12 deletions(-) diff --git a/classes/helper.php b/classes/helper.php index c3e07cb..794fa8d 100644 --- a/classes/helper.php +++ b/classes/helper.php @@ -92,22 +92,27 @@ public static function reason_display(int $reason): string { * * @param float $duration * @param bool $markup If true, then use markup on the result. + * @param int $dp Number of decimal places to round to. * @return string * @throws \Exception */ - public static function duration_display(float $duration, bool $markup = true): string { + public static function duration_display(float $duration, bool $markup = true, int $dp = 1): string { // Variable $markup allows a different format when viewed (true) vs downloaded (false). if ($markup) { if (intval($duration) > 10) { // Use whole seconds. $usetime = intval($duration); } else { - // Add one decimal place. - $usetime = round($duration, 1); - // Fallback case to prevent format_time() returning the translated string 'now' when $usetime is less than 100ms. - // It will still appear if less than 1ms rounded. Discuss. - if ($usetime < 0.1) { - $usetime = round($duration, 3); + // Add the decimal place. + $usetime = round($duration, $dp); + // Fallback to prevent format_time returning the translated string 'now' when the rounded version is 0. + if ($usetime == 0) { + // Try rounding to 3 decimal places, otherwise return 0 secs. + if ($dp < 3 && round($duration, 3) > 0) { + $usetime = round($duration, 3); + } else { + return $usetime . ' ' . get_string('secs'); + } } } // This currently works with floats, but relies on undocumented behaviour of format_time(), which normally takes an int. @@ -269,4 +274,38 @@ public static function course_display_name(int $courseid): string { return $course->fullname; } + + /** + * Returns a HTML link based on the lockwait url. + * @param string|null $lockwaiturl Relative lockwait url + * @param float $lockwait Time spent waiting for the lock + * @return string html string + */ + public static function lockwait_display_link(?string $lockwaiturl, float $lockwait) { + if (empty($lockwaiturl)) { + return ($lockwait > 1) ? get_string('unknown', 'tool_excimer') : '-'; + } + + // Ideally we should link to an excimer profile of the url. + // If we don't have that, return a direct link. + $directlink = new \moodle_url($lockwaiturl); + return \html_writer::link($directlink, get_string('link', 'tool_excimer')); + } + + /** + * Returns lockwait help formatted after exporting for template. + * @param \renderer_base $output + * @param string $lockwaiturl lockwait display link url + * @return array export for template + */ + public static function lockwait_display_help(\renderer_base $output, string $lockwaiturl) { + GLOBAL $CFG; + + // Only show help information if we have an 'Unknown' url and debug session lock is off. + if ($lockwaiturl === get_string('unknown', 'tool_excimer') && empty($CFG->debugsessionlock)) { + $help = new \help_icon('field_lockwaiturl', 'tool_excimer'); + return $help->export_for_template($output); + } + return []; + } } diff --git a/classes/profile.php b/classes/profile.php index 8fa482b..8b9f63d 100644 --- a/classes/profile.php +++ b/classes/profile.php @@ -353,7 +353,11 @@ protected static function define_properties(): array { 'dbwrites' => ['type' => PARAM_INT, 'default' => 0], 'dbreplicareads' => ['type' => PARAM_INT, 'default' => 0], 'lockreason' => ['type' => PARAM_TEXT, 'default' => ''], - 'courseid' => ['type' => PARAM_INT, 'default' => null] + 'courseid' => ['type' => PARAM_INT, 'default' => null], + 'lockheld' => ['type' => PARAM_FLOAT, 'default' => 0], + 'lockwait' => ['type' => PARAM_FLOAT, 'default' => 0], + 'lockwaiturl' => ['type' => PARAM_TEXT, 'default' => ''], + 'processing' => ['type' => PARAM_FLOAT, 'default' => 0], ]; } } diff --git a/classes/profile_table.php b/classes/profile_table.php index 155f1b8..e0fdbbd 100644 --- a/classes/profile_table.php +++ b/classes/profile_table.php @@ -29,6 +29,7 @@ class profile_table extends \table_sql { /** Columns to be displayed. */ const COLUMNS = [ 'duration', + 'processing', 'responsecode', 'request', 'reason', @@ -96,6 +97,7 @@ public function make_columns(): void { $this->define_columns($columns); $this->column_class('duration', 'text-right'); + $this->column_class('processing', 'text-right'); $this->column_class('responsecode', 'text-right'); $this->define_headers($headers); } @@ -187,7 +189,9 @@ protected function put_sql(): void { 'middlename', 'alternatename', 'lockreason', - 'courseid' + 'courseid', + 'lockwait', + 'duration - lockwait AS processing', ]; $fieldsstr = implode(',', $fields); @@ -294,6 +298,16 @@ public function col_duration(\stdClass $record): string { return helper::duration_display($record->duration, !$this->is_downloading()); } + /** + * Display value for 'processing' column entries. + * + * @param \stdClass $record + * @return string + */ + public function col_processing(\stdClass $record): string { + return helper::duration_display($record->duration - $record->lockwait, !$this->is_downloading()); + } + /** * Display value for 'created' column entries. * diff --git a/classes/recent_profile_table.php b/classes/recent_profile_table.php index c51c008..ffe5e6c 100644 --- a/classes/recent_profile_table.php +++ b/classes/recent_profile_table.php @@ -34,6 +34,7 @@ class recent_profile_table extends profile_table { 'reason', 'type', 'duration', + 'processing', 'userid', 'courseid' ]; diff --git a/classes/script_metadata.php b/classes/script_metadata.php index ff1d4a2..55e7351 100644 --- a/classes/script_metadata.php +++ b/classes/script_metadata.php @@ -461,4 +461,35 @@ public static function get_sample_limit(): int { public static function get_stack_limit(): int { return self::$stacklimit; } + + /** + * Returns information extracted from session lock info. + * + * @return array key value pairs that are ready to be saved to the profile + */ + public static function get_lock_info(): array { + $lockinfo = []; + $sessionlock = \core\session\manager::get_session_lock_info(); + if (empty($sessionlock)) { + return $lockinfo; + } + + // Get time spent waiting for lock and time spent holding a lock. + $lockinfo['lockwait'] = $sessionlock['wait'] ?? 0; + + if (isset($sessionlock['held'])) { + $lockinfo['lockheld'] = $sessionlock['held']; + } else if (isset($sessionlock['gained'])) { + // Lock hasn't been released yet, so use current time as an estimate. + $lockinfo['lockheld'] = microtime(true) - $sessionlock['gained']; + } + + // More info about the page holding the url is available when $CFG->debugsessionlock is set. + $url = \core\session\manager::get_locked_page_at($sessionlock['start']); + if (isset($url) && !empty($url['url'])) { + $lockinfo['lockwaiturl'] = $url['url']; + } + + return $lockinfo; + } } diff --git a/classes/web_processor.php b/classes/web_processor.php index 502dc9a..df4f0fa 100644 --- a/classes/web_processor.php +++ b/classes/web_processor.php @@ -124,6 +124,9 @@ public function process(manager $manager, bool $isfinal) { $this->profile->set('flamedatad3', flamed3_node::from_excimer_log_entries($this->sampleset->samples)); $this->profile->set('numsamples', $this->sampleset->count()); $this->profile->set('samplerate', $this->sampleset->filter_rate() * $this->samplems); + foreach (script_metadata::get_lock_info() as $field => $value) { + $this->profile->set($field, $value); + } $this->profile->save_record(); } } diff --git a/db/install.xml b/db/install.xml index 82e5a7f..6718108 100755 --- a/db/install.xml +++ b/db/install.xml @@ -45,6 +45,9 @@ + + + diff --git a/db/upgrade.php b/db/upgrade.php index afa05bf..90b081a 100644 --- a/db/upgrade.php +++ b/db/upgrade.php @@ -459,5 +459,36 @@ function xmldb_tool_excimer_upgrade($oldversion) { upgrade_plugin_savepoint(true, 2023082900, 'tool', 'excimer'); } + if ($oldversion < 2024050700) { + + // Define field id to be added to tool_excimer_profiles. + $table = new xmldb_table('tool_excimer_profiles'); + $field = new xmldb_field('lockheld', XMLDB_TYPE_NUMBER, '12, 6', null, null, null, null); + + // Conditionally launch add field id. + if (!$dbman->field_exists($table, $field)) { + $dbman->add_field($table, $field); + } + + // Define field id to be added to tool_excimer_profiles. + $field = new xmldb_field('lockwait', XMLDB_TYPE_NUMBER, '12, 6', null, null, null, null); + + // Conditionally launch add field id. + if (!$dbman->field_exists($table, $field)) { + $dbman->add_field($table, $field); + } + + // Define field id to be added to tool_excimer_profiles. + $field = new xmldb_field('lockwaiturl', XMLDB_TYPE_TEXT, null, null, null, null, null); + + // Conditionally launch add field id. + if (!$dbman->field_exists($table, $field)) { + $dbman->add_field($table, $field); + } + + // Excimer savepoint reached. + upgrade_plugin_savepoint(true, 2024050700, 'tool', 'excimer'); + } + return true; } diff --git a/lang/en/tool_excimer.php b/lang/en/tool_excimer.php index 59c8ddf..e594645 100644 --- a/lang/en/tool_excimer.php +++ b/lang/en/tool_excimer.php @@ -120,6 +120,7 @@ $string['field_finished'] = 'Finished'; $string['field_userid'] = 'User'; $string['field_duration'] = 'Duration'; +$string['field_processing'] = 'Processing'; $string['field_request'] = 'Request'; $string['field_pathinfo'] = 'Pathinfo'; $string['field_explanation'] = 'Explanation'; @@ -145,6 +146,11 @@ $string['field_useragent'] = 'User agent'; $string['field_versionhash'] = 'Version Hash'; $string['field_courseid'] = 'Course'; +$string['field_lockheld'] = 'Lock held'; +$string['field_lockwait'] = 'Lock wait'; +$string['field_lockwaitheld'] = 'Lock wait/held'; +$string['field_lockwaiturl'] = 'Page holding lock'; +$string['field_lockwaiturl_help'] = 'Page holding lock info may only be available when $CFG->debugsessionlock is set.'; // Page count table. $string['field_name'] = 'Name'; @@ -218,3 +224,6 @@ $string['duration'] = 'duration'; $string['no_month_in_page_group_table'] = 'Month value not set in page group table.'; $string['deletedcourse'] = 'Deleted course id: {$a}'; +$string['unknown'] = 'Unknown'; +$string['link'] = 'Direct link'; +$string['profilelocknotification'] = 'The majority of the duration was spent waiting for a lock, the page may not be slow.'; diff --git a/profile.php b/profile.php index 09eb55d..44215ca 100644 --- a/profile.php +++ b/profile.php @@ -121,7 +121,20 @@ $data['created'] = userdate($data['created']); $data['finished'] = userdate($data['finished']); -$data['duration'] = format_time(round($data['duration'], 3)); +$duration = $data['duration']; +$data['duration'] = format_time(round($duration, 3)); +if (isset($data['lockwait'])) { + $lockwait = $data['lockwait']; + $data['lockwait'] = helper::duration_display($lockwait, true, 3); + $data['lockheld'] = helper::duration_display($data['lockheld'], true, 3); + $data['lockwaiturl'] = helper::lockwait_display_link($data['lockwaiturl'], $lockwait); + $data['lockwaiturlhelp'] = helper::lockwait_display_help($OUTPUT, $data['lockwaiturl']); + + $processing = $duration - $lockwait; + if (($processing / $duration) < 0.1 && $processing < 10) { + \core\notification::info(get_string('profilelocknotification', 'tool_excimer')); + } +} $data['request'] = helper::full_request($profile->to_record()); diff --git a/templates/profile.mustache b/templates/profile.mustache index 8742cfc..cb200b5 100644 --- a/templates/profile.mustache +++ b/templates/profile.mustache @@ -124,6 +124,17 @@ {{#str}} field_memoryusagemax, tool_excimer {{/str}} {{memoryusagemax}} + + {{#str}} field_lockwaitheld, tool_excimer {{/str}} + + {{#lockwait}} + {{lockwait}} / {{lockheld}} + {{/lockwait}} + {{^lockwait}} + {{#str}} unknown, tool_excimer {{/str}} + {{/lockwait}} + +
@@ -170,6 +181,13 @@ {{#str}} field_courseid, tool_excimer {{/str}} {{{ course }}} + + {{#str}} field_lockwaiturl, tool_excimer {{/str}} + + {{{ lockwaiturl }}} + {{#lockwaiturlhelp}} {{>core/help_icon}} {{/lockwaiturlhelp}} + +
diff --git a/version.php b/version.php index fb22bda..e25677a 100644 --- a/version.php +++ b/version.php @@ -25,8 +25,8 @@ defined('MOODLE_INTERNAL') || die(); -$plugin->version = 2023082901; -$plugin->release = 2023082901; +$plugin->version = 2024050700; +$plugin->release = 2024050700; $plugin->requires = 2017051500; // Moodle 3.3 for Totara support. $plugin->supported = [35, 401]; // Supports Moodle 3.5 or later. // TODO $plugin->incompatible = ; // Available as of Moodle 3.9.0 or later.