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

          Attachments

            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