Details

    • Type: Sub-task
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 2.4.3
    • Fix Version/s: 2.4.5, 2.5.1
    • Component/s: Caching
    • Labels:
    • Testing Instructions:
      Hide

      (This is a 'check it isn't broken' test as there should be no functional change.)

      1. Browse around a few pages of the site including a course view page.
      2. Turn on the performance information and check that the cache information shown at the bottom of the page still looks plausible.

      Show
      (This is a 'check it isn't broken' test as there should be no functional change.) 1. Browse around a few pages of the site including a course view page. 2. Turn on the performance information and check that the cache information shown at the bottom of the page still looks plausible.
    • Affected Branches:
      MOODLE_24_STABLE
    • Fixed Branches:
      MOODLE_24_STABLE, MOODLE_25_STABLE
    • Pull Master Branch:
      MDL-39472-master

      Description

      The get_from_persist_cache function could benefit from optimisations:

      1) Where perfdebug is turned on (some live sites used this option), record_cache_hit takes an annoyingly long time.
      2) Micro-optimisations could improve performance of the main function.

      I'll give details in comments.

        Gliffy Diagrams

          Activity

          Hide
          quen Sam Marshall added a comment -

          Based on profiling runs, I made the following changes:

          1) The ensure_ready_for_stats function, called via record_cache_hit (only if perfdebug is on), now does a single 'isset' check (faster than array_key_exists and especially faster than two of them) as a shortcut for the common case where it doesn't need to do anything.

          2) Function calls directly inside get_from_persist_cache took a surprising amount of the profile time. I have made micro-optimisations to improve performance:

          a. Replace is_array with (array)$key === $key (Eloy says it's eight times faster)

          b. Replace an array_key_exists call with isset (it's faster).

          c. Replace function call $this->has_a_ttl() with field access $this->hasattl; I don't object to accessor methods in general, but this seems to be wasting a bit of time in a frequently-called function. I've made the function final so that nobody can override it to change behaviour without changing the field value (which comes from the cache definition).

          I evaluated these changes using a 'best-of-three' methodology: (a) switch to the old branch, then make three course page requests quickly with profiling turned on; (b) switch to the new branch, then make three requests quickly with profiling; (c) out of each set of three, select the profiling run with lowest total time; (d) compare these two profiles.

          On a test course page (OU 2.4.3) there are 482 calls to cache::get_from_persist_cache. Presumably, if usage of MUC increases, this performance will become more important.

          I have run the cache unit tests after this change and they still pass.

          TEST: ALL CHANGES ABOVE (done twice, once again after all the others)

          23.6ms --> 13.3ms (~10ms)
          23.7ms --> 13.2ms (~10ms)

          TEST: Change (1) only

          22.9ms --> 18.6ms (~4ms)

          TEST: Change (2a) only

          22.7ms --> 21.7ms (~1ms)

          TEST: Change (2b) only

          23.1ms --> 21.7ms (~1ms)

          TEST: Change (2c) only (done twice because I didn't believe the first time)

          22.8ms --> 19.0ms (~3ms)
          23.1ms --> 21.5ms (~2ms)

          Show
          quen Sam Marshall added a comment - Based on profiling runs, I made the following changes: 1) The ensure_ready_for_stats function, called via record_cache_hit (only if perfdebug is on), now does a single 'isset' check (faster than array_key_exists and especially faster than two of them) as a shortcut for the common case where it doesn't need to do anything. 2) Function calls directly inside get_from_persist_cache took a surprising amount of the profile time. I have made micro-optimisations to improve performance: a. Replace is_array with (array)$key === $key (Eloy says it's eight times faster) b. Replace an array_key_exists call with isset (it's faster). c. Replace function call $this->has_a_ttl() with field access $this->hasattl; I don't object to accessor methods in general, but this seems to be wasting a bit of time in a frequently-called function. I've made the function final so that nobody can override it to change behaviour without changing the field value (which comes from the cache definition). I evaluated these changes using a 'best-of-three' methodology: (a) switch to the old branch, then make three course page requests quickly with profiling turned on; (b) switch to the new branch, then make three requests quickly with profiling; (c) out of each set of three, select the profiling run with lowest total time; (d) compare these two profiles. On a test course page (OU 2.4.3) there are 482 calls to cache::get_from_persist_cache. Presumably, if usage of MUC increases, this performance will become more important. I have run the cache unit tests after this change and they still pass. TEST: ALL CHANGES ABOVE (done twice, once again after all the others) 23.6ms --> 13.3ms (~10ms) 23.7ms --> 13.2ms (~10ms) TEST: Change (1) only 22.9ms --> 18.6ms (~4ms) TEST: Change (2a) only 22.7ms --> 21.7ms (~1ms) TEST: Change (2b) only 23.1ms --> 21.7ms (~1ms) TEST: Change (2c) only (done twice because I didn't believe the first time) 22.8ms --> 19.0ms (~3ms) 23.1ms --> 21.5ms (~2ms)
          Hide
          poltawski Dan Poltawski added a comment -

          Adding Sam Hemelryk here and saying, wow, those are pretty impressive improvements.

          Show
          poltawski Dan Poltawski added a comment - Adding Sam Hemelryk here and saying, wow, those are pretty impressive improvements.
          Hide
          poltawski Dan Poltawski added a comment -

          heh, I think i overstated that, forgetting these are milliseconds

          Show
          poltawski Dan Poltawski added a comment - heh, I think i overstated that, forgetting these are milliseconds
          Hide
          timhunt Tim Hunt added a comment -

          Looks OK to me.

          Show
          timhunt Tim Hunt added a comment - Looks OK to me.
          Hide
          stronk7 Eloy Lafuente (stronk7) added a comment - - edited

          Just a side comment/warning about the proposed array_key_exists() ==> isset() change:

          I'm pretty sure that along the multiple iterations of the MUC, at some point, we discussed about that optimization but, at some point, there were NULLs involved that prevented us to do so. Note I don't remember the places nor have looked to the proposed changes here. It's just a warning for Sam that sure will know, at first sight, if there are NULLs involved there.

          Thanks for the hard work, ciao

          Edited: "at some point" I'll stop saying "at some point" :-P

          Show
          stronk7 Eloy Lafuente (stronk7) added a comment - - edited Just a side comment/warning about the proposed array_key_exists() ==> isset() change: I'm pretty sure that along the multiple iterations of the MUC, at some point, we discussed about that optimization but, at some point, there were NULLs involved that prevented us to do so. Note I don't remember the places nor have looked to the proposed changes here. It's just a warning for Sam that sure will know, at first sight, if there are NULLs involved there. Thanks for the hard work, ciao Edited: "at some point" I'll stop saying "at some point" :-P
          Hide
          matteo Matteo Scaramuccia added a comment -

          Just for the record the story was also (probably partially, but for sure at some point written there ) told here: MDL-37472.

          HTH,
          Matteo

          Show
          matteo Matteo Scaramuccia added a comment - Just for the record the story was also (probably partially, but for sure at some point written there ) told here: MDL-37472 . HTH, Matteo
          Hide
          samhemelryk Sam Hemelryk added a comment -

          Hiya,

          These changes look good, I'm glad you guys have hit on them as they are areas I've picked up as well.
          There are a couple of things to note:

          1. $key === (array)$key - this is very cool! The same change should be applied to is_in_persist_cache and set_in_persist_cache to keep things consistent when checking this.
          2. Its worth noting you can provide null as the value for a key. This change will result in the persist cache never being used to retrieve a key with a null value. It will always go to the store. Given that this wouldn't cause a bug, that it is likely to be very rare that someone sets that a null value, and that it will only impact performance I think it is a worthwhile change to make still.

          Many thanks
          Sam

          Show
          samhemelryk Sam Hemelryk added a comment - Hiya, These changes look good, I'm glad you guys have hit on them as they are areas I've picked up as well. There are a couple of things to note: $key === (array)$key - this is very cool! The same change should be applied to is_in_persist_cache and set_in_persist_cache to keep things consistent when checking this. Its worth noting you can provide null as the value for a key. This change will result in the persist cache never being used to retrieve a key with a null value. It will always go to the store. Given that this wouldn't cause a bug, that it is likely to be very rare that someone sets that a null value, and that it will only impact performance I think it is a worthwhile change to make still. Many thanks Sam
          Hide
          quen Sam Marshall added a comment -

          Thanks for review comments. I'm going to make the following changes based on Sam's review:

          1. is_array perf: apply change to is_in_persist_cache and set_in_persist_cache for consistency.
          2. Add comment about the null values.

          Will submit for integration when ready.

          Show
          quen Sam Marshall added a comment - Thanks for review comments. I'm going to make the following changes based on Sam's review: 1. is_array perf: apply change to is_in_persist_cache and set_in_persist_cache for consistency. 2. Add comment about the null values. Will submit for integration when ready.
          Hide
          quen Sam Marshall added a comment -

          Changes applied as per review, submitting for integration review.

          Show
          quen Sam Marshall added a comment - Changes applied as per review, submitting for integration review.
          Hide
          damyon Damyon Wiese added a comment -

          I might leave this one for Eloy to comment on - my 2c is that I agree with all the changes except the hasattl one. While this shows a small improvement, the confusion over having a function call that is never used and set final is not worth it.

          Show
          damyon Damyon Wiese added a comment - I might leave this one for Eloy to comment on - my 2c is that I agree with all the changes except the hasattl one. While this shows a small improvement, the confusion over having a function call that is never used and set final is not worth it.
          Hide
          quen Sam Marshall added a comment -

          Damyon: OK, I accept that one's a bit confusing. I have revised the patch to remove the function call change. I haven't redone timings but presumably this means it would save about 7ms per page on my system instead of 10ms.

          This change may fall into the category of a couple that were considered yesterday i.e. should be put on hold to consider after release. Will leave that for reviewers to decide.

          Show
          quen Sam Marshall added a comment - Damyon: OK, I accept that one's a bit confusing. I have revised the patch to remove the function call change. I haven't redone timings but presumably this means it would save about 7ms per page on my system instead of 10ms. This change may fall into the category of a couple that were considered yesterday i.e. should be put on hold to consider after release. Will leave that for reviewers to decide.
          Hide
          poltawski Dan Poltawski added a comment -

          Yes, i'm putting this on hold this for after release so we can focus on release blockers. Thanks

          Show
          poltawski Dan Poltawski added a comment - Yes, i'm putting this on hold this for after release so we can focus on release blockers. Thanks
          Hide
          poltawski Dan Poltawski added a comment - - edited

          Before:
          Time: 18:24, Memory: 279.25Mb

          OK, but incomplete or skipped tests!
          Tests: 1910, Assertions: 32119, Skipped: 5.

          After:
          Time: 19:17, Memory: 278.50Mb

          OK, but incomplete or skipped tests!
          Tests: 1910, Assertions: 32119, Skipped: 5.

          Show
          poltawski Dan Poltawski added a comment - - edited Before: Time: 18:24, Memory: 279.25Mb OK, but incomplete or skipped tests! Tests: 1910, Assertions: 32119, Skipped: 5. After: Time: 19:17, Memory: 278.50Mb OK, but incomplete or skipped tests! Tests: 1910, Assertions: 32119, Skipped: 5.
          Hide
          poltawski Dan Poltawski added a comment -

          (running again)

          Show
          poltawski Dan Poltawski added a comment - (running again)
          Hide
          poltawski Dan Poltawski added a comment -

          Second time, it was the reverse

          Show
          poltawski Dan Poltawski added a comment - Second time, it was the reverse
          Hide
          poltawski Dan Poltawski added a comment -

          Integrated to master, 25 and 24 - thanks Sam

          Show
          poltawski Dan Poltawski added a comment - Integrated to master, 25 and 24 - thanks Sam
          Hide
          poltawski Dan Poltawski added a comment -

          Tested during integration and I couldn't find any problems.

          Show
          poltawski Dan Poltawski added a comment - Tested during integration and I couldn't find any problems.
          Hide
          marina Marina Glancy added a comment -

          Thanks for your awesome work! This has now become a part of Moodle.

          Closing as fixed!

          Show
          marina Marina Glancy added a comment - Thanks for your awesome work! This has now become a part of Moodle. Closing as fixed!

            People

            • Votes:
              1 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:
                Fix Release Date:
                8/Jul/13