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

Early warning session lock debugging for redis session handler

XMLWordPrintable

    • MOODLE_401_STABLE
    • MDL-68668-extra-redis-debugging
    • Hide
      Setup
      1. Install the PHP Redis extension (replace "X" as your server's PHP version, e.g. 8.0) 

        sudo apt update && sudo apt install -y phpX-redis

      2. Restart your web server.
      3. Confirm the redis PHP extension is enabled: "php -i | grep redis" - You should see a bunch of lines related to redis.
      4. Install redis. e.g. using Docker 

        docker run --name redis -p 6379:6379 -d redis

      5. Setup redis as the session handler, eg, copy the following to your config.php: 

        $CFG->session_handler_class = '\core\session\redis';
        		 
        $CFG->session_redis_host = '127.0.0.1';
        		 
        $CFG->session_redis_port = 6379;
        		 
        $CFG->session_redis_acquire_lock_timeout = 10;

      6. Install the session breaker plugin to help with testing: 

        git clone https://github.com/catalyst/moodle-tool_sessionbreaker/ admin/tool/sessionbreaker

      7. Tail the web server logs 

        tail -f /var/log/apache2/error.log

      Test
      1. Visit this page: /admin/tool/sessionbreaker/index.php
      2. Confirm you after 10 seconds you see some errors 

        Error: Cannot obtain session lock for sid: pvga0j242mh5csbcc645mpvqtp within 10 seconds ...

      3. Now add the extra warning: 

        $CFG->session_redis_acquire_lock_warn = 2;

      4. Reload the page
      5. Confirm after roughly 2 seconds you get a series of warnings like: 

        Warning: Cannot obtain session lock for sid: pvga0j242mh5csbcc645mpvqtp within 2 seconds but will keep trying. It is likely another page ([pid 1758327] catau-desktop0372:/admin/tool/sessionbreaker/count.php?c=4&delay=500&readonly=) has a long session lock, or the session lock was never released., referer: http://moodle.local/admin/tool/sessionbreaker/index.php

      Show
      Setup Install the PHP Redis extension (replace " X " as your server's PHP version, e.g. 8.0) sudo apt update && sudo apt install -y phpX-redis Restart your web server. Confirm the redis PHP extension is enabled: " php -i | grep redis " - You should see a bunch of lines related to redis. Install redis. e.g. using Docker docker run --name redis -p 6379:6379 -d redis Setup redis as the session handler, eg, copy the following to your config.php: $CFG->session_handler_class = '\core\session\redis' ; $CFG->session_redis_host = '127.0.0.1' ; $CFG->session_redis_port = 6379 ; $CFG->session_redis_acquire_lock_timeout = 10 ; Install the session breaker plugin to help with testing: git clone https://github.com/catalyst/moodle-tool_sessionbreaker/ admin/tool/sessionbreaker Tail the web server logs tail -f /var/log/apache2/error.log Test Visit this page: /admin/tool/sessionbreaker/index.php Confirm you after 10 seconds you see some errors Error: Cannot obtain session lock for sid: pvga0j242mh5csbcc645mpvqtp within 10 seconds ... Now add the extra warning: $CFG->session_redis_acquire_lock_warn = 2 ; Reload the page Confirm after roughly 2 seconds you get a series of warnings like: Warning: Cannot obtain session lock for sid: pvga0j242mh5csbcc645mpvqtp within 2 seconds but will keep trying. It is likely another page ([pid 1758327 ] catau-desktop0372:/admin/tool/sessionbreaker/count.php?c= 4 &delay= 500 &readonly=) has a long session lock, or the session lock was never released., referer: http: //moodle.local/admin/tool/sessionbreaker/index.php

      Follow up from MDL-67075 with hindsight, in production we will want a reasonably high acquire lock threshold so we do not lose data, but at the same time we want to emit warnings if the lock does take longer than a smaller threshold to be gain, but isn't so bad that it actually fails. This is to inform where to target further dev work to reduce lock contention.

      1) Add in the timestamp of when the lock was acquired

      2) Allow a shorter warning threshold so we could do say debug at 10 seconds, but keep waiting for another 110 = 120 total

       This could reuse $CFG->debugsessionlock if set or have it's own config.php level setting

      3) Also when we warn ask redis for the current locks TTL and add that to debug message

        1. MDL-68668 testing.png
          MDL-68668 testing.png
          174 kB

            brendanheywood Brendan Heywood
            brendanheywood Brendan Heywood
            cameron1729 cameron1729
            Jun Pataleta Jun Pataleta
            Angelia Dela Cruz Angelia Dela Cruz
            Votes:
            4 Vote for this issue
            Watchers:
            12 Start watching this issue

              Created:
              Updated:
              Resolved:

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

                  Error rendering 'clockify-timesheets-time-tracking-reports:timer-sidebar'. Please contact your Jira administrators.