Add session lock info #314

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

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],
         ];
     }
 }

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

classes/recent_profile_table.php

@@ -34,6 +34,7 @@ class recent_profile_table extends profile_table {
         'reason',
         'type',
         'duration',
+        'processing',
         'userid',
         'courseid'
     ];

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

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

db/install.xml

@@ -45,6 +45,9 @@
         <FIELD NAME="samplerate" TYPE="int" LENGTH="11" NOTNULL="false" SEQUENCE="false" COMMENT="Base sample rate at the time the profile was recorded"/>
         <FIELD NAME="lockreason" TYPE="text" NOTNULL="false" SEQUENCE="false" COMMENT="Holds reasons for keeping this profile. Any non-empty value will prevent purging."/>
         <FIELD NAME="courseid" TYPE="int" LENGTH="10" NOTNULL="false" SEQUENCE="false" COMMENT="The id of $COURSE at the time of profiling"/>
+        <FIELD NAME="lockheld" TYPE="number" LENGTH="12" NOTNULL="false" SEQUENCE="false" DECIMALS="6" COMMENT="Length of time a lock was held in seconds"/>
+        <FIELD NAME="lockwait" TYPE="number" LENGTH="12" NOTNULL="false" SEQUENCE="false" DECIMALS="6" COMMENT="Wait time on a lock in seconds"/>
+        <FIELD NAME="lockwaiturl" TYPE="text" NOTNULL="false" SEQUENCE="false" COMMENT="URL of the page holding the lock, if known"/>
       </FIELDS>
       <KEYS>
         <KEY NAME="primary" TYPE="primary" FIELDS="id"/>

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

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.';

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

templates/profile.mustache

@@ -124,6 +124,17 @@
                     <th>{{#str}} field_memoryusagemax, tool_excimer {{/str}}</th>
                     <td>{{memoryusagemax}}</td>
                 </tr>
+                <tr>
+                    <th>{{#str}} field_lockwaitheld, tool_excimer {{/str}}</th>
+                    <td>
+                        {{#lockwait}}
+                            {{lockwait}} / {{lockheld}}
+                        {{/lockwait}}
+                        {{^lockwait}}
+                            {{#str}} unknown, tool_excimer {{/str}}
+                        {{/lockwait}}
+                    </td>
+                </tr>
             </table>
         </div>
         <div class="">
@@ -170,6 +181,13 @@
                     <th>{{#str}} field_courseid, tool_excimer {{/str}}</th>
                     <td>{{{ course }}}</td>
                 </tr>
+                <tr>
+                    <th>{{#str}} field_lockwaiturl, tool_excimer {{/str}}</th>
+                    <td>
+                        {{{ lockwaiturl }}}
+                        {{#lockwaiturlhelp}} {{>core/help_icon}} {{/lockwaiturlhelp}}
+                    </td>
+                </tr>
             </table>
         </div>
     </div>

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.