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

Inefficient cache rebuilding when bulk-updating course module visibility

XMLWordPrintable

    • MOODLE_401_STABLE, MOODLE_402_STABLE, MOODLE_403_STABLE
    • MOODLE_401_STABLE, MOODLE_402_STABLE, MOODLE_403_STABLE
    • MDL-79615_401_STABLE
    • MDL-79615_403_STABLE
    • MDL-79615_master
    • Hide
      1. Go to Site Administration > Development > Make test course and create an M-sized course.
      2. Open the course page and turn editing mode on.
      3. In config.php, enable performance logging by adding the following lines:
        define('MDL_PERF'  , true);
        define('MDL_PERFTOLOG'  , true);
      4. Where /var/log/error.log is your error log file, run the following command in a terminal and leave it running:
        tail -f /var/log/error.log | grep core_courseformat_update_course
      5. On the course page, find a section containing 10 or more course modules.
      6. Open the action menu and select "Hide topic"
      7. In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo.
        1. BEFORE FIX The numbers are the dozens, e.g. core/coursemodinfo {default_application(51/14/39) } for 12 CMs.
        2. AFTER FIX The numbers are in single digits, e.g. core/coursemodinfo {default_application(5/2/4) } **
      8. Confirm that the section and all its course modules are hidden
      9. Open the section's action menu and select "Show topic"
      10. In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo.
        1. BEFORE FIX The numbers are lower but still high, e.g. core/coursemodinfo {default_application(27/14/27) }
        2. AFTER FIX The numbers are in single digits, e.g. core/coursemodinfo {default_application(5/2/4) }
      11. Confirm that the section and all its course modules are visible
      12. At the top of the course page, select "Bulk actions".
      13. Pick 10 course modules from anywhere on the page.
      14. In the bulk actions UI, select "Availability" > "Hide on course page" and click "Apply"
      15. In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo.
        1. BEFORE FIX The numbers are high, e.g. core/coursemodinfo {default_application(31/10/20) }
        2. AFTER FIX The numbers are low, e.g. core/coursemodinfo {default_application(4/1/2) }
      16. Confirm that the selected course modules are hidden
      17. Pick the 10 hidden course modules
      18. In the bulk actions UI, select "Availability" > "Show on course page" and click "Apply"
      19. In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo.
        1. BEFORE FIX The numbers are high, e.g. core/coursemodinfo {default_application(31/10/20) }
        2. AFTER FIX The numbers are low, e.g. core/coursemodinfo {default_application(4/1/2) }
      20. Confirm that the course modules are now visible.
      Show
      Go to Site Administration > Development > Make test course and create an M-sized course. Open the course page and turn editing mode on. In config.php, enable performance logging by adding the following lines: define('MDL_PERF'  , true); define('MDL_PERFTOLOG'  , true); Where /var/log/error.log is your error log file, run the following command in a terminal and leave it running: tail -f /var/log/error.log | grep core_courseformat_update_course On the course page, find a section containing 10 or more course modules. Open the action menu and select "Hide topic" In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo. BEFORE FIX The numbers are the dozens, e.g. core/coursemodinfo {default_application(51/14/39) } for 12 CMs. AFTER FIX The numbers are in single digits, e.g. core/coursemodinfo {default_application(5/2/4) } ** Confirm that the section and all its course modules are hidden Open the section's action menu and select "Show topic" In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo. BEFORE FIX The numbers are lower but still high, e.g. core/coursemodinfo {default_application(27/14/27) } AFTER FIX The numbers are in single digits, e.g. core/coursemodinfo {default_application(5/2/4) } Confirm that the section and all its course modules are visible At the top of the course page, select "Bulk actions". Pick 10 course modules from anywhere on the page. In the bulk actions UI, select "Availability" > "Hide on course page" and click "Apply" In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo. BEFORE FIX The numbers are high, e.g. core/coursemodinfo {default_application(31/10/20) } AFTER FIX The numbers are low, e.g. core/coursemodinfo {default_application(4/1/2) } Confirm that the selected course modules are hidden Pick the 10 hidden course modules In the bulk actions UI, select "Availability" > "Show on course page" and click "Apply" In your terminal, check the last line of log output, and find the (hits/misses/sets) numbers for the core/coursemodinfo. BEFORE FIX The numbers are high, e.g. core/coursemodinfo {default_application(31/10/20) } AFTER FIX The numbers are low, e.g. core/coursemodinfo {default_application(4/1/2) } Confirm that the course modules are now visible.

      I have been doing some performance analysis on a large site, and found that requests which show/hide a section containing a large number of course modules can be very slow. Analysis of long session locks on the site showed that 10% of locks lasting more than 10s were performing these actions. A big part of the reason for this is that it course_update_section() does the following:

      • Set the section visibility
      • purge the section from the coursemodinfo cache
      • Perform a partial rebuild the coursemodinfo cache for the course
      • For each course module,
        • call set_coursemodule_visible, which will purge the cm from the coursemodinfo cache, then perform a partial rebuild
        • If the section is being hidden, store the visibility in visibleold and purge the cm from the cache again
      • Perform a partial rebuild the coursemodinfo cache for the course

      This results in 2n+3 writes to the coursemodinfo cache when showing a section, and 3n+3 when hiding a section, including n+2 partial rebuilds, where n is the number of course modules within a section. Each of these writes requires a cache lock.

      I propose adding an additional parameter to set_coursemodule_visible() to skip purging and rebuilding the cache, and instead let the calling code be responsible for updating the cache. In addition, a new course_modinfo::purge_course_module_cache_many() function which takes a list of cmids would allow us to purge several course modules from the cache at once, rather than doing it in a loop.

      The combination of these would reduce the cache writes to 4 including 2 partial rebuilds, for any number of course modules.

      This could also be used in stateactions::set_cm_visibility(), and anywhere else that bulk updates cm visibility.

        1. (1) 10 Passed -- (Master)MDL-79615.png
          59 kB
          Kim Jared Lucas
        2. (1) 15 Passed -- (Master)MDL-79615.png
          35 kB
          Kim Jared Lucas
        3. (1) 19 Passed -- (Master)MDL-79615.png
          61 kB
          Kim Jared Lucas
        4. (1) 20 Passed -- (Master)MDL-79615.png
          29 kB
          Kim Jared Lucas
        5. (1) 7 Passed -- (Master)MDL-79615.png
          73 kB
          Kim Jared Lucas
        6. Screenshot from 2023-10-11 13-49-41.png
          102 kB
          Mark Johnson

            marxjohnson Mark Johnson
            marxjohnson Mark Johnson
            Ferran Recio Ferran Recio
            Ilya Tregubov Ilya Tregubov
            Kim Jared Lucas Kim Jared Lucas
            Votes:
            5 Vote for this issue
            Watchers:
            27 Start watching this issue

              Created:
              Updated:
              Resolved:

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

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