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

Performance info: Display lock performance

XMLWordPrintable

    • MOODLE_401_STABLE
    • MOODLE_401_STABLE
    • MDL-74960-master
    • Hide
      1. Enable performance info if necessary (in admin menu, search for perfdebug admin setting and enable).
      2. View a course page.
      3. In another tab, open the Purge caches page (admin/purgecaches.php - admin settings / development / purge caches on the menu).
      4. Under Purge selected caches heading, tick All MUC caches and press Purge selected caches.
      5. Back in the first tab, reload the course page.
      6. Look at the performance information at the bottom of the page.
        • EXPECTED: You should see a table similar to the one shown in the screenshot for this issue, listing at least one lock that was obtained, the time it took to obtain, a tick indicating that it was obtained successfully, and the time it was held open for. (Unless you have a complicated test site, most likely the times will be 0.0 or 0.1.)
      7. Now edit your Moodle config.php and add the following line before the require_once at the end: define('MDL_PERFTOLOG', true);
      8. Purge the MUC cache again, and reload the course page again.
      9. Look near the end of your web server error logs.
        • EXPECTED: You should see a line relating to the course page (look for the course/view.php), which should contain the same lock information in text format at the end of the line, something like this: Locks (waited/obtained/held): core_coursecattree_cache (0.0/y/0.0) build_course_cache_1 (0.0/y/0.1) build_course_cache_2 (0.0/y/0.2).
      10. When you've finished testing, remember to remove or comment out the added line from your config.php.
      Show
      Enable performance info if necessary (in admin menu, search for perfdebug admin setting and enable). View a course page. In another tab, open the Purge caches page (admin/purgecaches.php - admin settings / development / purge caches on the menu). Under Purge selected caches heading, tick All MUC caches and press Purge selected caches . Back in the first tab, reload the course page. Look at the performance information at the bottom of the page. EXPECTED: You should see a table similar to the one shown in the screenshot for this issue, listing at least one lock that was obtained, the time it took to obtain, a tick indicating that it was obtained successfully, and the time it was held open for. (Unless you have a complicated test site, most likely the times will be 0.0 or 0.1.) Now edit your Moodle config.php and add the following line before the require_once at the end: define('MDL_PERFTOLOG', true); Purge the MUC cache again, and reload the course page again. Look near the end of your web server error logs. EXPECTED: You should see a line relating to the course page (look for the course/view.php), which should contain the same lock information in text format at the end of the line, something like this: Locks (waited/obtained/held): core_coursecattree_cache (0.0/y/0.0) build_course_cache_1 (0.0/y/0.1) build_course_cache_2 (0.0/y/0.2). When you've finished testing, remember to remove or comment out the added line from your config.php.

      The performance info (displayed at bottom of the page if enabled in admin settings) shows lots of useful information which can identify performance problems in production as well as test sites, such as too many database queries or incorrect cache usage.

      At present it does not show any information about waiting for locks. For example, while investigating a reported performance issue here I saw that a page sometimes took 38 seconds to load, with 1.5 seconds on database queries and nothing interesting in the cache area. It was not immediately obvious that the other 36.5 seconds was spent waiting for the course modinfo lock. (In this scenario, another user's request was actually building modinfo, and my request was waiting for theirs to complete, but once completed, it didn't have to build the cache.)

      I propose we add a table below the cache table, listing each lock used by the page (in the order they were requested), with:

      • The time taken to acquire (or fail to acquire) the lock.
      • Whether it was acquired or not.
      • The time that the lock was held before being released.

        1. mdl-74960.png
          7 kB
          Sam Marshall
        2. 1_MDL-74960_master.png
          12 kB
          John Edward Pedregosa
        3. 2_MDL-74960_master.png
          75 kB
          John Edward Pedregosa

            quen Sam Marshall
            quen Sam Marshall
            Tim Hunt Tim Hunt
            Andrew Lyons Andrew Lyons
            John Edward Pedregosa John Edward Pedregosa
            Votes:
            1 Vote for this issue
            Watchers:
            7 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, 50 minutes
                2h 50m

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