Skip to content

Commit

Permalink
Merge branch 'session-debug' of https://github.com/tsmilan/moodle
Browse files Browse the repository at this point in the history
  • Loading branch information
@abgreeve
abgreeve committed Apr 3, 2019
2 parents 143122b + fdb9c32 commit af53b33
Show file tree
Hide file tree
Showing 3 changed files with 378 additions and 2 deletions.
6 changes: 6 additions & 0 deletions config-dist.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -614,6 +614,12 @@
//
// $CFG->expectedcronfrequency = 200;
//
// Session lock warning threshold. Long running pages should release the session using \core\session\manager::write_close().
// Set this threshold to any value greater than 0 to add developer warnings when a page locks the session for too long.
// The session should rarely be locked for more than 1 second. The input should be in seconds and may be a float.
//
// $CFG->debugsessionlock = 5;
//
//=========================================================================
// 7. SETTINGS FOR DEVELOPMENT SERVERS - not intended for production use!!!
//=========================================================================
Expand Down
173 changes: 171 additions & 2 deletions lib/classes/session/manager.php
View file
Original file line number Diff line number Diff line change
Expand Up @@ -26,6 +26,8 @@

defined('MOODLE_INTERNAL') || die();

use html_writer;

/**
* Session manager, this is the public Moodle API for sessions.
*
Expand Down Expand Up @@ -55,13 +57,15 @@ class manager {
* Note: This is intended to be called only from lib/setup.php!
*/
public static function start() {
global $CFG, $DB;
global $CFG, $DB, $PERF;

if (isset(self::$sessionactive)) {
debugging('Session was already started!', DEBUG_DEVELOPER);
return;
}

// Grab the time before session lock starts.
$PERF->sessionlock['start'] = microtime(true);
self::load_handler();

// Init the session handler only if everything initialised properly in lib/setup.php file
Expand All @@ -82,6 +86,9 @@ public static function start() {
throw new \core\session\exception(get_string('servererror'));
}

// Grab the time when session lock starts.
$PERF->sessionlock['gained'] = microtime(true);
$PERF->sessionlock['wait'] = $PERF->sessionlock['gained'] - $PERF->sessionlock['start'];
self::initialise_user_session($isnewsession);
self::$sessionactive = true; // Set here, so the session can be cleared if the security check fails.
self::check_security();
Expand Down Expand Up @@ -109,6 +116,8 @@ public static function start() {
* @return array perf info
*/
public static function get_performance_info() {
global $CFG, $PERF;

if (!session_id()) {
return array();
}
Expand All @@ -119,9 +128,26 @@ public static function get_performance_info() {

$info = array();
$info['size'] = $size;
$info['html'] = "<span class=\"sessionsize\">Session ($handler): $size</span> ";
$info['html'] = html_writer::div("Session ($handler): $size", "sessionsize");
$info['txt'] = "Session ($handler): $size ";

if (!empty($CFG->debugsessionlock)) {
$sessionlock = self::get_session_lock_info();
if (!empty($sessionlock['held'])) {
// The page displays the footer and the session has been closed.
$sessionlocktext = "Session lock held: ".number_format($sessionlock['held'], 3)." secs";
} else {
// The session hasn't yet been closed and so we assume now with microtime.
$sessionlockheld = microtime(true) - $PERF->sessionlock['gained'];
$sessionlocktext = "Session lock open: ".number_format($sessionlockheld, 3)." secs";
}
$info['txt'] .= $sessionlocktext;
$info['html'] .= html_writer::div($sessionlocktext, "sessionlockstart");
$sessionlockwaittext = "Session lock wait: ".number_format($sessionlock['wait'], 3)." secs";
$info['txt'] .= $sessionlockwaittext;
$info['html'] .= html_writer::div($sessionlockwaittext, "sessionlockwait");
}

return $info;
}

Expand Down Expand Up @@ -530,6 +556,19 @@ public static function terminate_current() {
* Unblocks the sessions, other scripts may start executing in parallel.
*/
public static function write_close() {
global $PERF;

if (self::$sessionactive) {
// Grab the time when session lock is released.
$PERF->sessionlock['released'] = microtime(true);
if (!empty($PERF->sessionlock['gained'])) {
$PERF->sessionlock['held'] = $PERF->sessionlock['released'] - $PERF->sessionlock['gained'];
}
$PERF->sessionlock['url'] = me();
self::update_recent_session_locks($PERF->sessionlock);
self::sessionlock_debugging();
}

if (version_compare(PHP_VERSION, '5.6.0', '>=')) {
// More control over whether session data
// is persisted or not.
Expand Down Expand Up @@ -1024,4 +1063,134 @@ public static function validate_login_token($token = false) {
}
return true;
}

/**
* Get the recent session locks array.
*
* @return array Recent session locks array.
*/
public static function get_recent_session_locks() {
global $SESSION;

if (!isset($SESSION->recentsessionlocks)) {
// This will hold the pages that blocks other page.
$SESSION->recentsessionlocks = array();
}

return $SESSION->recentsessionlocks;
}

/**
* Updates the recent session locks.
*
* This function will store session lock info of all the pages visited.
*
* @param array $sessionlock Session lock array.
*/
public static function update_recent_session_locks($sessionlock) {
global $CFG, $SESSION;

if (empty($CFG->debugsessionlock)) {
return;
}

$SESSION->recentsessionlocks = self::get_recent_session_locks();
array_push($SESSION->recentsessionlocks, $sessionlock);

self::cleanup_recent_session_locks();
}

/**
* Reset recent session locks array if there is a 10 seconds time gap.
*
* @return array Recent session locks array.
*/
public static function cleanup_recent_session_locks() {
global $SESSION;

$locks = self::get_recent_session_locks();
if (count($locks) > 2) {
for ($i = count($locks) - 1; $i > 0; $i--) {
// Calculate the gap between session locks.
$gap = $locks[$i]['released'] - $locks[$i - 1]['start'];
if ($gap >= 10) {
// Remove previous locks if the gap is 10 seconds or more.
$SESSION->recentsessionlocks = array_slice($locks, $i);
break;
}
}
}
}

/**
* Get the page that blocks other pages at a specific timestamp.
*
* Look for a page whose lock was gained before that timestamp, and released after that timestamp.
*
* @param float $time Time before session lock starts.
* @return array|null
*/
public static function get_locked_page_at($time) {
$recentsessionlocks = self::get_recent_session_locks();
foreach ($recentsessionlocks as $recentsessionlock) {
if ($time >= $recentsessionlock['gained'] &&
$time <= $recentsessionlock['released']) {
return $recentsessionlock;
}
}
}

/**
* Display the page which blocks other pages.
*
* @return string
*/
public static function display_blocking_page() {
global $PERF;

$page = self::get_locked_page_at($PERF->sessionlock['start']);
$output = "Script ".me()." was blocked for ";
$output .= number_format($PERF->sessionlock['wait'], 3);
if ($page != null) {
$output .= " second(s) by script: ";
$output .= $page['url'];
} else {
$output .= " second(s) by an unknown script.";
}

return $output;
}

/**
* Get session lock info of the current page.
*
* @return array
*/
public static function get_session_lock_info() {
global $PERF;

if (!isset($PERF->sessionlock)) {
return null;
}
return $PERF->sessionlock;
}

/**
* Display debugging info about slow and blocked script.
*/
public static function sessionlock_debugging() {
global $CFG, $PERF;

if (!empty($CFG->debugsessionlock)) {
if (isset($PERF->sessionlock['held']) && $PERF->sessionlock['held'] > $CFG->debugsessionlock) {
debugging("Script ".me()." locked the session for ".number_format($PERF->sessionlock['held'], 3)
." seconds, it should close the session using \core\session\manager::write_close().", DEBUG_NORMAL);
}

if (isset($PERF->sessionlock['wait']) && $PERF->sessionlock['wait'] > $CFG->debugsessionlock) {
$output = self::display_blocking_page();
debugging($output, DEBUG_DEVELOPER);
}
}
}
}
Loading

0 comments on commit af53b33

Please sign in to comment.