Details

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

      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.

        Activity

        Hide
        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
        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
        Dan Poltawski added a comment -

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

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

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

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

        Looks OK to me.

        Show
        Tim Hunt added a comment - Looks OK to me.
        Hide
        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
        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 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 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
        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
        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
        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
        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
        Sam Marshall added a comment -

        Changes applied as per review, submitting for integration review.

        Show
        Sam Marshall added a comment - Changes applied as per review, submitting for integration review.
        Hide
        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 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
        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
        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
        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
        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
        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
        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
        Dan Poltawski added a comment -

        (running again)

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

        Second time, it was the reverse

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

        Integrated to master, 25 and 24 - thanks Sam

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

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

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

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

        Closing as fixed!

        Show
        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: