Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-64449

Add debug feature to expose code issues with session locks

    XMLWordPrintable

    Details

    • Testing Instructions:
      Hide

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

       

       

      Show
      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().    
    • Affected Branches:
      MOODLE_37_STABLE
    • Fixed Branches:
      MOODLE_37_STABLE
    • Pull from Repository:
    • Pull Master Branch:
      session-debug

      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

        1. image-2019-01-09-12-30-41-281.png
          86 kB
          Brendan Heywood
        2. session-lock.png
          740 kB
          Bas Brands

          Issue Links

            Activity

              People

              • Votes:
                7 Vote for this issue
                Watchers:
                15 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Fix Release Date:
                  20/May/19

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 4 hours, 30 minutes
                  4h 30m