Details
-
New Feature
-
Status: Closed
-
Minor
-
Resolution: Fixed
-
3.7
-
MOODLE_37_STABLE
-
MOODLE_37_STABLE
-
session-debug
-
We have written a temporary admin tool to consistently simulate some session blocking bugs:
1) Install this plugin:
https://github.com/brendanheywood/moodle-tool_sessionbreaker
2) In config.php
$CFG->debugsessionlock = 2; // Set debugpageinfo to a log threshold of 2 seconds:
$CFG->debugpageinfo = 1; // Show perf info in footer
3) Now go to this page
http://moodle.local/admin/tool/sessionbreaker/lock.php
Which simulates a bunch of good and bad pages using careful timing and iframes. If you look at the chrome network tab you should see a waterfall like this:
The second long blue bar shows the bad session lock, the long green bars under it show the victim pages being delayed.
4) See in the page footer and see things like:
Session (core\session\database): 31.6KB
Session lock open: 0.542 secs
Session lock wait: 0.002 secs
5) Check the error logs and see messages likeScript /admin/tool/sessionbreaker/good.php?id=1 was blocked for 3.944 second(s) by script: /admin/tool/sessionbreaker/bad.php?wait=4
and
Script /admin/tool/sessionbreaker/bad.php?wait=4 is slow, it should close the session using
core
session
manager::write_close().We have written a temporary admin tool to consistently simulate some session blocking bugs: 1) Install this plugin: https://github.com/brendanheywood/moodle-tool_sessionbreaker 2) In config.php $CFG->debugsessionlock = 2; // Set debugpageinfo to a log threshold of 2 seconds: $CFG->debugpageinfo = 1; // Show perf info in footer 3) Now go to this page http://moodle.local/admin/tool/sessionbreaker/lock.php Which simulates a bunch of good and bad pages using careful timing and iframes. If you look at the chrome network tab you should see a waterfall like this: The second long blue bar shows the bad session lock, the long green bars under it show the victim pages being delayed. 4) See in the page footer and see things like: Session (core\session\database): 31.6KB Session lock open: 0.542 secs Session lock wait: 0.002 secs 5) Check the error logs and see messages like Script /admin/tool/sessionbreaker/good.php?id=1 was blocked for 3.944 second(s) by script: /admin/tool/sessionbreaker/bad.php?wait=4 and Script /admin/tool/sessionbreaker/bad.php?wait=4 is slow, it should close the session using core session manager::write_close().
Description
There are lots of places which either fire of multiple ajax processes, or long running reports, and in theory if these are written well they should close the session asap to unblock the other processes running potentially in parallel:
\core\session\manager::write_close();
The issue is that there is a lot of code in core and in the plugins dir and out in the wild which doesn't do this, and there is not much in the way of tooling to help detect this.
From an end users point of view, "things are just slow", and so they typically open up a new browser tab, which of course is also blocked and they think that it's just a system performance and / or scaling issue.
This issue will expose a new developer debug setting which exposes lengthy lock wait times in the performance stuff in the footer as well as in the error log, which in turn will inform where development effort should be focused to fix these blocking sessions bugs.
Attachments
Issue Links
- has a non-specific relationship to
-
MDL-70828 Add ability to switch off session lock debugging
-
- Closed
-
- has been marked as being related by
-
-
- Closed
-
-
-
- Closed
-
-
-
- Closed
-
- is duplicated by
-
-
- Closed
-
- Testing discovered
-
MDL-65393 Edge case bug with $SESSION->recentsessionlocks growing unchecked when using $CFG->debugsessionlock
-
- Closed
-
-
MDL-60978 Fix Redis session tests
-
- Closed
-
