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

Reduce session lock contention with opt-in READ_ONLY_SESSION

XMLWordPrintable

    • MOODLE_33_STABLE
    • MOODLE_39_STABLE
    • MDL-58018_master-arraycomparison
    • Hide

      Requirement:

      1. A server with the PHP memcached and Redis extensions installed (see memcached docs and Redis docs).
      2. A memcached daemon running on port 11211, eg memcached -d -m 24 -p 11211
      3. A Redis daemon running, eg redis-server /usr/local/etc/redis.conf
      4. Open lib/amd/src/notification.js.
      5. Remove all the code from fetchNotifications so it looks like the following 

        fetchNotifications: function() {
        		 
         
        		 
        },

      6. Run grunt amd.
      7. Purge your caches.

      Test 1 (memcached):

      1. Fresh install of Moodle.
      2. Add the attached test_async_requests_session_locking.php to your wwwroot.
      3. Edit config.php to configure Moodle to talk to the memcached server for sessions 

        $CFG->session_handler_class = '\core\session\memcached';
        		 
        $CFG->session_memcached_save_path = '127.0.0.1:11211';
        		 
        $CFG->session_memcached_prefix = 'memc.sess.key.';
        		 
        $CFG->session_memcached_acquire_lock_timeout = 120;
        		 
        $CFG->session_memcached_lock_expire = 7200;

      4. Apply the changes in the commit https://github.com/mdjnelson/moodle/commit/10af67a6d493f9565d4ad7bedc4022f47b642db1 to your code.
      5. Watch the php_error log (eg. tail -f /usr/local/var/log/httpd/error_log in your terminal) on another screen.
      6. Log in as the admin.
      7. Visit the page <yoursite>/test_async_requests_session_locking.php.
      8. Note similar to the following in your PHP error_log: 

        [21-Feb-2017 00:57:34 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 00:57:34 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 00:57:34 ...<snip>... |duration:0.002s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 00:57:34 ...<snip>... |duration:0.224s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 00:57:34 ...<snip>... |duration:0.448s|session_url:/lib/ajax/service.php

        Note the concurrent AJAX requests that arrive immediately after the page is loaded, and note that in this case the fourth one was blocked for one cycle and the fifth had to wait for another cycle after that.

      9. Edit config.php and add the following line to enable this patch: 

        $CFG->enable_read_only_sessions = true;

      10. Reload the page:
      11. Note similar to the following in your PHP error_log (note there are more logs as we are restarting write lock sessions as read only): 

        [21-Feb-2017 01:00:59 ...<snip>... |duration:0s|session_url:/test_async_requests_session_locking.php
        		 
        [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 01:01:01 ...<snip>... |duration:0.002s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 01:01:01 ...<snip>... |duration:0.002s|session_url:/lib/ajax/service.php
        		 
        [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php

        Note the concurrent AJAX requests now waste no time with session acquisition. While one of them is configured to wait for a lock, the others don't need it, and as such not only load instantly, they also don't prevent the thread that need it from being blocked.

      12. Edit config.php and edit the following setting to disable this patch: 

        $CFG->enable_read_only_sessions = false;

      Test 2 (Redis):

      1. Same instructions as above except for step 3 configure Moodle to talk to the Redis server for sessions 

        $CFG->session_handler_class = '\core\session\redis';
        		 
        $CFG->session_redis_host = '127.0.0.1';
        		 
        $CFG->session_redis_port = 6379;  // Optional.
        		 
        $CFG->session_redis_database = 0;  // Optional, default is db 0.
        		 
        $CFG->session_redis_auth = ''; // Optional, default is don't set one.
        		 
        $CFG->session_redis_prefix = ''; // Optional, default is don't set one.
        		 
        $CFG->session_redis_acquire_lock_timeout = 120;
        		 
        $CFG->session_redis_lock_expire = 7200;
        		 
        $CFG->session_redis_serializer_use_igbinary = false; // Optional, default is PHP builtin serializer.

      Test 3 (DB):

      1. Same instructions as above except for step 3 configure Moodle to talk to the DB for sessions 

        $CFG->session_handler_class = '\core\session\database';
        		 
        $CFG->session_database_acquire_lock_timeout = 120;

      Test 4

      1. Remove the changes you made to lib/classes/session/manager.php.
      2. Ensure your Redis server is up and running.
      3. Add $CFG->enable_read_only_sessions = true; to your config.php file.
      4. Watch the php_error log (eg. tail -f /usr/local/var/log/httpd/error_log in your terminal) on another screen.
      5. Add the attached test_session_read_only_with_write.php to your wwwroot.
      6. Visit <yoursite>/test_session_read_only_with_write.php.
      7. Confirm you get the error "The session store can not be in the session when enable_read_only_sessions is enabled" in your error log.
      8. Log in as an admin.
      9. Visit 'Site administration' > 'Plugins' > 'Caching' > 'Configuration'.
      10. Click 'Add instance' next to 'Redis'.
      11. Add an instance with 'Store name' set to 'Session cache', 'Server' set to '127.0.0.1' and Key prefix set to 'seshcache' and then clicking 'Save'.
      12. Scroll down to 'Stores used when no mapping is present' and click on 'Edit mappings'.
      13. For 'Session' set it to 'Session cache' and save.
      14. Visit <yoursite>/test_session_read_only_with_write.php
      15. Confirm you get the error "This session was started as a read-only session but writes have been detected" in your error log.
      16. Comment out $SESSION->random = rand(0,100); in test_session_read_only_with_write.php.
      17. Refresh the page.
      18. Confirm nothing is displayed in your error log.
      Show
      Requirement: A server with the PHP memcached and Redis extensions installed (see memcached docs and Redis docs ). A memcached daemon running on port 11211, eg memcached -d -m 24 -p 11211 A Redis daemon running, eg redis-server /usr/local/etc/redis.conf Open lib/amd/src/notification.js . Remove all the code from fetchNotifications so it looks like the following fetchNotifications: function() {   }, Run grunt amd . Purge your caches. Test 1 (memcached): Fresh install of Moodle. Add the attached test_async_requests_session_locking.php to your wwwroot. Edit config.php to configure Moodle to talk to the memcached server for sessions $CFG ->session_handler_class = '\core\session\memcached' ; $CFG ->session_memcached_save_path = '127.0.0.1:11211' ; $CFG ->session_memcached_prefix = 'memc.sess.key.' ; $CFG ->session_memcached_acquire_lock_timeout = 120; $CFG ->session_memcached_lock_expire = 7200; Apply the changes in the commit https://github.com/mdjnelson/moodle/commit/10af67a6d493f9565d4ad7bedc4022f47b642db1 to your code. Watch the php_error log (eg. tail -f /usr/local/var/log/httpd/error_log in your terminal) on another screen. Log in as the admin. Visit the page <yoursite>/test_async_requests_session_locking.php. Note similar to the following in your PHP error_log: [21-Feb-2017 00:57:34 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php [21-Feb-2017 00:57:34 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php [21-Feb-2017 00:57:34 ...<snip>... |duration:0.002s|session_url:/lib/ajax/service.php [21-Feb-2017 00:57:34 ...<snip>... |duration:0.224s|session_url:/lib/ajax/service.php [21-Feb-2017 00:57:34 ...<snip>... |duration:0.448s|session_url:/lib/ajax/service.php Note the concurrent AJAX requests that arrive immediately after the page is loaded, and note that in this case the fourth one was blocked for one cycle and the fifth had to wait for another cycle after that. Edit config.php and add the following line to enable this patch: $CFG ->enable_read_only_sessions = true; Reload the page: Note similar to the following in your PHP error_log (note there are more logs as we are restarting write lock sessions as read only): [21-Feb-2017 01:00:59 ...<snip>... |duration:0s|session_url:/test_async_requests_session_locking.php [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php [21-Feb-2017 01:01:01 ...<snip>... |duration:0.002s|session_url:/lib/ajax/service.php [21-Feb-2017 01:01:01 ...<snip>... |duration:0.002s|session_url:/lib/ajax/service.php [21-Feb-2017 01:01:01 ...<snip>... |duration:0.001s|session_url:/lib/ajax/service.php Note the concurrent AJAX requests now waste no time with session acquisition. While one of them is configured to wait for a lock, the others don't need it, and as such not only load instantly, they also don't prevent the thread that need it from being blocked. Edit config.php and edit the following setting to disable this patch: $CFG ->enable_read_only_sessions = false; Test 2 (Redis): Same instructions as above except for step 3 configure Moodle to talk to the Redis server for sessions $CFG ->session_handler_class = '\core\session\redis' ; $CFG ->session_redis_host = '127.0.0.1' ; $CFG ->session_redis_port = 6379; // Optional. $CFG ->session_redis_database = 0; // Optional, default is db 0. $CFG ->session_redis_auth = '' ; // Optional, default is don't set one. $CFG ->session_redis_prefix = '' ; // Optional, default is don't set one. $CFG ->session_redis_acquire_lock_timeout = 120; $CFG ->session_redis_lock_expire = 7200; $CFG ->session_redis_serializer_use_igbinary = false; // Optional, default is PHP builtin serializer. Test 3 (DB): Same instructions as above except for step 3 configure Moodle to talk to the DB for sessions $CFG ->session_handler_class = '\core\session\database' ; $CFG ->session_database_acquire_lock_timeout = 120; Test 4 Remove the changes you made to lib/classes/session/manager.php . Ensure your Redis server is up and running. Add $CFG->enable_read_only_sessions = true; to your config.php file. Watch the php_error log (eg. tail -f /usr/local/var/log/httpd/error_log in your terminal) on another screen. Add the attached test_session_read_only_with_write.php to your wwwroot. Visit <yoursite>/test_session_read_only_with_write.php. Confirm you get the error "The session store can not be in the session when enable_read_only_sessions is enabled" in your error log. Log in as an admin. Visit 'Site administration' > 'Plugins' > 'Caching' > 'Configuration'. Click 'Add instance' next to 'Redis'. Add an instance with 'Store name' set to 'Session cache', 'Server' set to '127.0.0.1' and Key prefix set to 'seshcache' and then clicking 'Save'. Scroll down to 'Stores used when no mapping is present' and click on 'Edit mappings'. For 'Session' set it to 'Session cache' and save. Visit <yoursite>/test_session_read_only_with_write.php Confirm you get the error "This session was started as a read-only session but writes have been detected" in your error log. Comment out $SESSION->random = rand(0,100); in test_session_read_only_with_write.php . Refresh the page. Confirm nothing is displayed in your error log.

      Background

      Many parts of Moodle now result in the browser making parallel requests to the Moodle server.

      For example, a home page load on a fresh Moodle installation makes no less than 3 AJAX requests in parallel. Similarly, calls to /pluginfile.php that return HTML, often result in multiple parallel requests for further resources such as JS, CSS, images etc.

      Problem Statement

      Currently when a request is processed by Moodle, a session is always started, and in order to start that session an exclusive lock is acquired on that session, which, in general, is not released until the server completes processing the request, where it is released by calling write_close() in the shutdown handler (although some pages explicitly release this early).

      The result is that even though the browser sends requests in parallel, once the requests hit the server they are in contention with each other, and effectively serialised by the session locking mechanism, resulting in busy spin locks and tying up server resources far longer than actually required. This is particularly apparent when the session lock code is buggy! (see MDL-57477, and PHP memcached issue: https://github.com/php-memcached-dev/php-memcached/issues/310)

      Observation

      In general, there is often no reason that a session lock is actually needed for cases where the processing of the request does not need any data to be persisted back to the session.

      For example, while retrieving the session is nearly always necessary (to check the user is authenticated and authorized to access the selected resource), for serving actual content, such as information about navigation items, where the context is fully specified in the request, or perhaps for serving static content, there is no need to acquire a session lock, where the underlying handler guarantees atomic operations (such as memcached, where a get / set is atomic).

      Proposed Solution

      We propose a patch that allows:
      1. Printing debug information on how long it takes to acquire a session.
      2. Ability for a page to declare that it needs only a READ_ONLY_SESSION, where, if supported by the session handler, sessions are acquired without waiting for a lock, sessions are not locked, and calls to write_close() are ignored.
      3. Opt-in of some key sources of contention to use this flag.

      Looking for feedback

      We would appreciate feedback on the validity of this approach, and the linked proposed patch.

        1. image-2020-02-12-15-49-00-176.png
          image-2020-02-12-15-49-00-176.png
          19 kB
        2. image-2020-02-12-15-49-12-586.png
          image-2020-02-12-15-49-12-586.png
          21 kB
        3. image-2020-04-29-16-56-48-965.png
          image-2020-04-29-16-56-48-965.png
          7 kB
        4. image-2020-05-01-19-13-46-416.png
          image-2020-05-01-19-13-46-416.png
          117 kB
        5. MDL-58018_test1_step11.png
          MDL-58018_test1_step11.png
          83 kB
        6. MDL-58018_test1_step8.png
          MDL-58018_test1_step8.png
          62 kB
        7. MDL-58018_test2_step11.png
          MDL-58018_test2_step11.png
          85 kB
        8. MDL-58018_test2_step8.png
          MDL-58018_test2_step8.png
          63 kB
        9. MDL-58018_test3_step11.png
          MDL-58018_test3_step11.png
          86 kB
        10. MDL-58018_test3_step8.png
          MDL-58018_test3_step8.png
          63 kB
        11. MDL-58018_test4_step15.png
          MDL-58018_test4_step15.png
          21 kB
        12. MDL-58018_test4_step18.png
          MDL-58018_test4_step18.png
          4 kB
        13. MDL58018_test4_step7.png
          MDL58018_test4_step7.png
          26 kB
        14. test_async_requests_session_locking.php
          0.9 kB
        15. test_session_read_only_with_write.php
          0.3 kB

            markn Mark Nelson
            aeijdenberg Adam Eijdenberg
            Brendan Heywood Brendan Heywood
            Eloy Lafuente (stronk7) Eloy Lafuente (stronk7)
            Michael Hawkins Michael Hawkins
            Votes:
            25 Vote for this issue
            Watchers:
            46 Start watching this issue

              Created:
              Updated:
              Resolved:

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 2 days, 5 hours, 50 minutes
                2d 5h 50m

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