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

Course cache rebuilt unnecessarily if $course has old cacherev

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: Minor Minor
    • 4.0.5
    • 4.0.4
    • Libraries
    • MOODLE_400_STABLE
    • MOODLE_400_STABLE
    • MDL-75736-master
    • Hide

      It's difficult to test the 'real life' behaviour, but we can use the attached test script to check it in code. (There is also a PHPunit test which does something fairly similar so I'm not sure how necessary this is, but...)

      1. Place the attached modinfo-test.php in the root directory of your Moodle installation.
      2. In your web browser, access /modinfo-test,php within your Moodle web site.
        • EXPECTED: The first of 10 lines should say 'Modinfo load: N queries' (where N is a number that isn't zero) but the other 9 lines should all say '0 queries'.
      Show
      It's difficult to test the 'real life' behaviour, but we can use the attached test script to check it in code. (There is also a PHPunit test which does something fairly similar so I'm not sure how necessary this is, but...) Place the attached modinfo-test.php in the root directory of your Moodle installation. In your web browser, access /modinfo-test,php within your Moodle web site. EXPECTED: The first of 10 lines should say 'Modinfo load: N queries' (where N is a number that isn't zero) but the other 9 lines should all say '0 queries'.

      MDL-72991 made a change in course_modinfo::__construct which can cause unnecessary rebuilding of the course cache (which is an extremely expensive operation on large courses, taking several seconds), potentially multiple times in a request. This is causing severe performance problems in some OU code, but it can also cause problems when multiple requests are taking place simultaneously.

      Specifically, the previous logic was:

      • Request the modinfo data from cache. If it is not present, or if the cached data is OLDER than the cacherev value stored in the course object, then rebuild the cache.

      The new logic is:

      • Request the modinfo data from cache. If it is not present, or if the cached data is DIFFERENT to the cacherev value stored in the course object, then rebuild the cache.

      Within a single request, the impact of this is if you do code like the following:

      // Get a course object with the initial cacherev.
      $course = get_course($id);
      make_a_change($course);
      // Rebuild the course cache, updating cacherev.
      rebuild_course_cache($course->id, 0, true);
      // Now do more actions.
      do_something_else($course);
      and_something_else($course);
      then_something_else($course);
      

      If all of the 'something_else' functions end up calling get_fast_modinfo, then every single one of those get_fast_modinfo calls will rebuild the course cache again, because the passed-in $course object has an old cacherev (say, 100) but the cached value will be a newer one.

      The example I have that causes this is an AJAX script - we don't really call 3 other functions, what we do is render part of the course page so we can return it from the script. Rendering the course page causes loads of templates and output classes to be generated, and many of these call get_fast_modinfo, because why wouldn't they, often with the passed-in $course object. As a result the cache is rebuilt 29 times which is extremely expensive, mainly in database queries (27,000 in my example) and presumably also cache I/O (29 * whatever size of modinfo, across all cache layers).

      This is fixable in our code - we simply need to refresh the $course object after rebuilding course cache. But it doesn't seem an unreasonable usage pattern.

      See the attached modinfo-test.php; if you place this in Moodle root, it will do this code pattern, calling 'get_fast_modinfo($course)' 10 times in a row and reporting how many queries are used each time. If working, all but the first should be zero queries. Before fix, they all use the same number of queries.

      Does anyone know why the logic was changed to make it require the identical version rather than '...or a later one' as originally implemented? Obviously something to do with partial rebuilds which I don't know anything about...

      The other place this causes performance problems is if multiple requests occur simultaneously:

      • User A starts a request, which loads the course object with cacherev 123.
      • User B carries out a request which makes a change to the course and rebuilds cache, seting cacherev to 456.
      • User A's request now calls get_fast_modinfo. Because it is expecting cacherev 123, but gets 456, it decides to helpfully rebuild the cached data even though nothing changed.

      We can see that this 3rd step is a waste of time and reduces performance, but it also extends further - now user A has changed the cache and cacherev, so User C might also be affected, etc.

      This behaviour is even worse if there might be a delay in database updates, as can happen in some clustering scenarios. After an update to cacherev, there might be a short period of time in which anyone using the read-only database will get an older value. This will cause all these requests to rebuild course cache.

      Note: I haven't seen for-real the multi-user behaviour, because we haven't deployed Moodle 4 to production servers yet. I think our clustering delay is probably short enough (typically 2-12ms) that this normally won't actually take down our system anyway, but it's a bit of a worry.

        1. MDL-75736_master.png
          MDL-75736_master.png
          32 kB
        2. MDL-75736_v400.png
          MDL-75736_v400.png
          32 kB
        3. modinfo-test.php
          1 kB

            quen Sam Marshall
            quen Sam Marshall
            Katie Ransom Katie Ransom
            Victor Déniz Falcón Victor Déniz Falcón
            Angelia Dela Cruz Angelia Dela Cruz
            Votes:
            2 Vote for this issue
            Watchers:
            10 Start watching this issue

              Created:
              Updated:
              Resolved:

                Estimated:
                Original Estimate - Not Specified
                Not Specified
                Remaining:
                Remaining Estimate - 0 minutes
                0m
                Logged:
                Time Spent - 1 hour, 5 minutes
                1h 5m

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