mirror of
https://github.com/moodle/moodle.git
synced 2025-04-15 05:25:08 +02:00
MDL-64449 core: Added Session lock debugging option
This commit is contained in:
Trisha Milan
parent
280cfdf05c
commit
fdb9c3217d
@ -614,6 +614,12 @@ $CFG->admin = 'admin';
|
||||
//
|
||||
// $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!!!
|
||||
//=========================================================================
|
||||
|
||||
@ -26,6 +26,8 @@ namespace core\session;
|
||||
|
||||
defined('MOODLE_INTERNAL') || die();
|
||||
|
||||
use html_writer;
|
||||
|
||||
/**
|
||||
* Session manager, this is the public Moodle API for sessions.
|
||||
*
|
||||
@ -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
|
||||
@ -82,6 +86,9 @@ class manager {
|
||||
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();
|
||||
@ -109,6 +116,8 @@ class manager {
|
||||
* @return array perf info
|
||||
*/
|
||||
public static function get_performance_info() {
|
||||
global $CFG, $PERF;
|
||||
|
||||
if (!session_id()) {
|
||||
return array();
|
||||
}
|
||||
@ -119,9 +128,26 @@ class manager {
|
||||
|
||||
$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;
|
||||
}
|
||||
|
||||
@ -530,6 +556,19 @@ class manager {
|
||||
* 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.
|
||||
@ -1024,4 +1063,134 @@ class manager {
|
||||
}
|
||||
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);
|
||||
}
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
@ -653,4 +653,205 @@ class core_session_manager_testcase extends advanced_testcase {
|
||||
$this->assertEquals($real, $user1);
|
||||
$this->assertSame($_SESSION['REALUSER'], $real);
|
||||
}
|
||||
|
||||
/**
|
||||
* Session lock info on pages.
|
||||
*
|
||||
* @return array
|
||||
*/
|
||||
public function pages_sessionlocks() {
|
||||
return [
|
||||
[
|
||||
'url' => '/good.php',
|
||||
'start' => 1500000001.000,
|
||||
'gained' => 1500000002.000,
|
||||
'released' => 1500000003.000,
|
||||
'wait' => 1.0,
|
||||
'held' => 1.0
|
||||
],
|
||||
[
|
||||
'url' => '/bad.php?wait=5',
|
||||
'start' => 1500000003.000,
|
||||
'gained' => 1500000005.000,
|
||||
'released' => 1500000007.000,
|
||||
'held' => 2.0,
|
||||
'wait' => 2.0
|
||||
]
|
||||
];
|
||||
}
|
||||
|
||||
/**
|
||||
* Test to get recent session locks.
|
||||
*/
|
||||
public function test_get_recent_session_locks() {
|
||||
global $CFG;
|
||||
|
||||
$this->resetAfterTest();
|
||||
$CFG->debugsessionlock = 5;
|
||||
$pages = $this->pages_sessionlocks();
|
||||
// Recent session locks must be empty at first.
|
||||
$recentsessionlocks = \core\session\manager::get_recent_session_locks();
|
||||
$this->assertEmpty($recentsessionlocks);
|
||||
|
||||
// Add page to the recentsessionlocks array.
|
||||
\core\session\manager::update_recent_session_locks($pages[0]);
|
||||
$recentsessionlocks = \core\session\manager::get_recent_session_locks();
|
||||
// Make sure we are getting the first page we added.
|
||||
$this->assertEquals($pages[0], $recentsessionlocks[0]);
|
||||
// There should be 1 page in the array.
|
||||
$this->assertCount(1, $recentsessionlocks);
|
||||
|
||||
// Add second page to the recentsessionlocks array.
|
||||
\core\session\manager::update_recent_session_locks($pages[1]);
|
||||
$recentsessionlocks = \core\session\manager::get_recent_session_locks();
|
||||
// Make sure we are getting the second page we added.
|
||||
$this->assertEquals($pages[1], $recentsessionlocks[1]);
|
||||
// There should be 2 pages in the array.
|
||||
$this->assertCount(2, $recentsessionlocks);
|
||||
}
|
||||
|
||||
/**
|
||||
* Test to update recent session locks.
|
||||
*/
|
||||
public function test_update_recent_session_locks() {
|
||||
global $CFG;
|
||||
|
||||
$this->resetAfterTest();
|
||||
$CFG->debugsessionlock = 5;
|
||||
$pages = $this->pages_sessionlocks();
|
||||
|
||||
\core\session\manager::update_recent_session_locks($pages[0]);
|
||||
\core\session\manager::update_recent_session_locks($pages[1]);
|
||||
$recentsessionlocks = \core\session\manager::get_recent_session_locks();
|
||||
// There should be 2 pages in the array.
|
||||
$this->assertCount(2, $recentsessionlocks);
|
||||
// Make sure the last page is added at the end of the array.
|
||||
$this->assertEquals($pages[1], end($recentsessionlocks));
|
||||
|
||||
}
|
||||
|
||||
/**
|
||||
* Test to get session lock info.
|
||||
*/
|
||||
public function test_get_session_lock_info() {
|
||||
global $PERF;
|
||||
|
||||
$this->resetAfterTest();
|
||||
|
||||
$pages = $this->pages_sessionlocks();
|
||||
$PERF->sessionlock = $pages[0];
|
||||
$sessionlock = \core\session\manager::get_session_lock_info();
|
||||
$this->assertEquals($pages[0], $sessionlock);
|
||||
}
|
||||
|
||||
/**
|
||||
* Session lock info on some pages to serve as history.
|
||||
*
|
||||
* @return array
|
||||
*/
|
||||
public function sessionlock_history() {
|
||||
return [
|
||||
[
|
||||
'url' => '/good.php',
|
||||
'start' => 1500000001.000,
|
||||
'gained' => 1500000001.100,
|
||||
'released' => 1500000001.500,
|
||||
'wait' => 0.1
|
||||
],
|
||||
[
|
||||
// This bad request doesn't release the session for 10 seconds.
|
||||
'url' => '/bad.php',
|
||||
'start' => 1500000012.000,
|
||||
'gained' => 1500000012.200,
|
||||
'released' => 1500000020.200,
|
||||
'wait' => 0.2
|
||||
],
|
||||
[
|
||||
// All subsequent requests are blocked and need to wait.
|
||||
'url' => '/good.php?id=1',
|
||||
'start' => 1500000012.900,
|
||||
'gained' => 1500000020.200,
|
||||
'released' => 1500000022.000,
|
||||
'wait' => 7.29
|
||||
],
|
||||
[
|
||||
'url' => '/good.php?id=2',
|
||||
'start' => 1500000014.000,
|
||||
'gained' => 1500000022.000,
|
||||
'released' => 1500000025.000,
|
||||
'wait' => 8.0
|
||||
],
|
||||
[
|
||||
'url' => '/good.php?id=3',
|
||||
'start' => 1500000015.000,
|
||||
'gained' => 1500000025.000,
|
||||
'released' => 1500000026.000,
|
||||
'wait' => 10.0
|
||||
],
|
||||
[
|
||||
'url' => '/good.php?id=4',
|
||||
'start' => 1500000016.000,
|
||||
'gained' => 1500000026.000,
|
||||
'released' => 1500000027.000,
|
||||
'wait' => 10.0
|
||||
]
|
||||
];
|
||||
}
|
||||
|
||||
/**
|
||||
* Data provider for test_get_locked_page_at function.
|
||||
*
|
||||
* @return array
|
||||
*/
|
||||
public function sessionlocks_info_provider() : array {
|
||||
return [
|
||||
[
|
||||
'url' => null,
|
||||
'time' => 1500000001.000
|
||||
],
|
||||
[
|
||||
'url' => '/bad.php',
|
||||
'time' => 1500000014.000
|
||||
],
|
||||
[
|
||||
'url' => '/good.php?id=2',
|
||||
'time' => 1500000022.500
|
||||
],
|
||||
];
|
||||
}
|
||||
|
||||
/**
|
||||
* Test to get locked page at a speficic timestamp.
|
||||
*
|
||||
* @dataProvider sessionlocks_info_provider
|
||||
* @param array $url Session lock page url.
|
||||
* @param array $time Session lock time.
|
||||
*/
|
||||
public function test_get_locked_page_at($url, $time) {
|
||||
global $CFG, $SESSION;
|
||||
|
||||
$this->resetAfterTest();
|
||||
$CFG->debugsessionlock = 5;
|
||||
$SESSION->recentsessionlocks = $this->sessionlock_history();
|
||||
|
||||
$page = \core\session\manager::get_locked_page_at($time);
|
||||
$this->assertEquals($url, $page['url']);
|
||||
}
|
||||
|
||||
/**
|
||||
* Test cleanup recent session locks.
|
||||
*/
|
||||
public function test_cleanup_recent_session_locks() {
|
||||
global $CFG, $SESSION;
|
||||
|
||||
$this->resetAfterTest();
|
||||
$CFG->debugsessionlock = 5;
|
||||
|
||||
$SESSION->recentsessionlocks = $this->sessionlock_history();
|
||||
$this->assertCount(6, $SESSION->recentsessionlocks);
|
||||
\core\session\manager::cleanup_recent_session_locks();
|
||||
// Make sure the session history has been cleaned up and only has the latest page.
|
||||
$this->assertCount(1, $SESSION->recentsessionlocks);
|
||||
$this->assertEquals('/good.php?id=4', $SESSION->recentsessionlocks[0]['url']);
|
||||
}
|
||||
}
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user