Moodle
  1. Moodle
  2. MDL-41292

MUC set_identifiers removes singlekeyprefix cache, even when identifiers have not changed

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Minor Minor
    • Resolution: Fixed
    • Affects Version/s: 2.4.5, 2.5, 2.6, 2.7
    • Fix Version/s: 2.4.8, 2.5.4, 2.6.1
    • Component/s: Caching
    • Labels:
    • Testing Instructions:
      Hide

      1. Run PHPUnit tests
      2. Browse course pages

      If you have XHProf installed...

      Review a profile of a course page and confirm that generate_single_key_prefix does not make function calls in the numbers that approach the number of calls being made to set_identifiers.

      Show
      1. Run PHPUnit tests 2. Browse course pages If you have XHProf installed... Review a profile of a course page and confirm that generate_single_key_prefix does not make function calls in the numbers that approach the number of calls being made to set_identifiers.
    • Affected Branches:
      MOODLE_24_STABLE, MOODLE_25_STABLE, MOODLE_26_STABLE, MOODLE_27_STABLE
    • Fixed Branches:
      MOODLE_24_STABLE, MOODLE_25_STABLE, MOODLE_26_STABLE
    • Pull from Repository:
    • Pull Master Branch:
      MDL-41292-master

      Description

      When set_identifiers is called, it resets singlekeyprefix. So each time cache::make factory method is called with the same set of identifiers, the cache is reset. This uses unnecessary time rebuilding the key, which is attempted to be cached.

      If the identifiers are the same as the currently set ones, they should be ignored and just return.

        Gliffy Diagrams

          Activity

          Hide
          Russell Smith added a comment -

          Reviewing this code after thinking about it...

          There is likely an issue with cache::make factory method that doesn't send any identifiers.

          The obvious first solution is to initialize the class $identifiers variable to null rather than array, however that doesn't help if the variable is used prior to a call to set_identifiers.

          Sam, can you offer any guidance on that?

          Show
          Russell Smith added a comment - Reviewing this code after thinking about it... There is likely an issue with cache::make factory method that doesn't send any identifiers. The obvious first solution is to initialize the class $identifiers variable to null rather than array, however that doesn't help if the variable is used prior to a call to set_identifiers. Sam, can you offer any guidance on that?
          Hide
          Sam Hemelryk added a comment -

          First up I like the direction of this change, obviously there is still an issue to sort out but its a very good improvement.

          I'm not too sure what you mean about cache::make not sending identifiers, looking through the construction path it appears that definition->set_identifiers is always called after creating a definition.
          The unit tests turn up an issue with the new set_identifier routine however, I'm guessing that is what you are referring to.

          Initialising identifiers to null would require us to make several changes to API functions and could break backwards compatibility limiting us to master only.
          I've three other ideas about how to proceed to solve this:

          1. Move the requireidentifiers check above the === check you've added here. Not ideal but as set_identifiers is not called often perhaps permissible and is a relatively minor change.
          2. Add an identifiersinitialised flag and perform relevant checks to the tracked state. Should be easy enough to add, but has a higher risk of regressions than the above option.
          3. Alter your check to include $this->keyprefixsingle !== null. Such a change would ensure we set identifier only if the new identifiers were different and the prefix's hadn't been generated. It'd get the unit tests passing but would hold the largest chance of regressions.

          Do any of those options appeal more to you?

          My personal preference would be to go with option 2. We could create a flag and then ensure identifiers had been initialised before operation requiring them to have been initialised (such as within the calls to generate prefixes).
          I suppose my biggest concern with this would be performance.

          What are your thoughts Russell?

          Show
          Sam Hemelryk added a comment - First up I like the direction of this change, obviously there is still an issue to sort out but its a very good improvement. I'm not too sure what you mean about cache::make not sending identifiers, looking through the construction path it appears that definition->set_identifiers is always called after creating a definition. The unit tests turn up an issue with the new set_identifier routine however, I'm guessing that is what you are referring to. Initialising identifiers to null would require us to make several changes to API functions and could break backwards compatibility limiting us to master only. I've three other ideas about how to proceed to solve this: Move the requireidentifiers check above the === check you've added here. Not ideal but as set_identifiers is not called often perhaps permissible and is a relatively minor change. Add an identifiersinitialised flag and perform relevant checks to the tracked state. Should be easy enough to add, but has a higher risk of regressions than the above option. Alter your check to include $this->keyprefixsingle !== null . Such a change would ensure we set identifier only if the new identifiers were different and the prefix's hadn't been generated. It'd get the unit tests passing but would hold the largest chance of regressions. Do any of those options appeal more to you? My personal preference would be to go with option 2. We could create a flag and then ensure identifiers had been initialised before operation requiring them to have been initialised (such as within the calls to generate prefixes). I suppose my biggest concern with this would be performance. What are your thoughts Russell?
          Hide
          Russell Smith added a comment -

          I went for a variation on option 2 as the number of places identifiers is used is very small. It's only 3 places which is safe to work with.

          I'm pushing this back for peer review after implementing the change. It passes all unit tests.

          The code in set_identifiers is now a little confusing to me. It allows updates to the identifier list that are increment. However at the same time it will throw and exception if you don't include all of the required identifiers on each update. I would think either you test the list has the required items after setting them, or you initialize the identifiers array to empty before making any updates. Do you have any thoughts on that Sam, should I include that here, or raise a separate issue?

          Sending for peer review of the latest version.

          Show
          Russell Smith added a comment - I went for a variation on option 2 as the number of places identifiers is used is very small. It's only 3 places which is safe to work with. I'm pushing this back for peer review after implementing the change. It passes all unit tests. The code in set_identifiers is now a little confusing to me. It allows updates to the identifier list that are increment. However at the same time it will throw and exception if you don't include all of the required identifiers on each update. I would think either you test the list has the required items after setting them, or you initialize the identifiers array to empty before making any updates. Do you have any thoughts on that Sam, should I include that here, or raise a separate issue? Sending for peer review of the latest version.
          Hide
          Sam Hemelryk added a comment -

          Looks spot on thanks Russell - moving to integration now.

          Show
          Sam Hemelryk added a comment - Looks spot on thanks Russell - moving to integration now.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Any reason not to fix this in stables? (24-26) ? Seems to be a nice fix for them.

          Show
          Eloy Lafuente (stronk7) added a comment - Any reason not to fix this in stables? (24-26) ? Seems to be a nice fix for them.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          After asking to Sam, it seem this if a nice fix for stables too, so applying to them...

          Show
          Eloy Lafuente (stronk7) added a comment - After asking to Sam, it seem this if a nice fix for stables too, so applying to them...
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Integrated (24, 25, 26 & master), thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Integrated (24, 25, 26 & master), thanks!
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Note to tester: I've run phpunit for all stable branches before integrating this so surely that step can be skipped by you (also http://integration.moodle.org wil tell you if there is any phpunit failing - red).

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Note to tester: I've run phpunit for all stable branches before integrating this so surely that step can be skipped by you (also http://integration.moodle.org wil tell you if there is any phpunit failing - red). Ciao
          Hide
          Mark Nelson added a comment -

          Thanks for contributing to Moodle Russel, great work.

          I am slightly confused about the wording - "Review a profile of a course page and confirm that generate_single_key_prefix does not make function calls in the numbers that approach the number of calls being made to set_identifiers." To me, this would mean that generate_single_key_prefix would be making less calls than set_identifiers, but this is not the case.

          The results I got are as follows -

          Integration master

          cache_definition::generate_single_key_prefix: 390
          cache_definition::set_identifiers: 42

          Integration 2.6

          cache_definition::generate_single_key_prefix: 1,071
          cache_definition::set_identifiers: 92

          Integration 2.5

          cache_definition::generate_single_key_prefix: 5,281
          cache_definition::set_identifiers: 2,187

          Integration 2.4

          cache_definition::generate_single_key_prefix: 2,978
          cache::set_identifiers: 99

          Show
          Mark Nelson added a comment - Thanks for contributing to Moodle Russel, great work. I am slightly confused about the wording - "Review a profile of a course page and confirm that generate_single_key_prefix does not make function calls in the numbers that approach the number of calls being made to set_identifiers." To me, this would mean that generate_single_key_prefix would be making less calls than set_identifiers, but this is not the case. The results I got are as follows - Integration master cache_definition::generate_single_key_prefix: 390 cache_definition::set_identifiers: 42 Integration 2.6 cache_definition::generate_single_key_prefix: 1,071 cache_definition::set_identifiers: 92 Integration 2.5 cache_definition::generate_single_key_prefix: 5,281 cache_definition::set_identifiers: 2,187 Integration 2.4 cache_definition::generate_single_key_prefix: 2,978 cache::set_identifiers: 99
          Hide
          Mark Nelson added a comment -

          If these numbers are as expected, then this can be considered passed. I just wanted to make sure.

          Show
          Mark Nelson added a comment - If these numbers are as expected, then this can be considered passed. I just wanted to make sure.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          I don't think this makes any change to the number of calls to both set_identifiers() and generate_single_key_prefix(). Both continue being called the same number of times.

          The only difference IMO is that both functions will run faster after the change, not having to recalculate anything (if the multiple cache "make" calls are using the same identifiers).

          So, if you compare 2 profiling runs of the same course page, the diff in the number of calls should be ZERO, just the execution time spent in those 2 functions with the patch applied should be better (green in the profiling diff).

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - I don't think this makes any change to the number of calls to both set_identifiers() and generate_single_key_prefix(). Both continue being called the same number of times. The only difference IMO is that both functions will run faster after the change, not having to recalculate anything (if the multiple cache "make" calls are using the same identifiers). So, if you compare 2 profiling runs of the same course page, the diff in the number of calls should be ZERO, just the execution time spent in those 2 functions with the patch applied should be better (green in the profiling diff). Ciao
          Hide
          Eloy Lafuente (stronk7) added a comment - - edited

          About the numbers above (once stated where the differences should happen in my previous comment)... I really would expect both 26_STABLE and master to have the same number of calls (rendering the course page of the same course, so I assume the differences there are because a different course was used).

          And about differences with 25_STABLE, for sure it had tons more that anyone else, because it's when the domain/secret identifiers were added and, also, because for that version, every make() call was reinstantiating the whole cache configs, surely causing identifiers and keys to be called way more times (that was one of the improvements done for 2.6).

          Finally, 2.4, surely a lower number of calls may be justified, although I'd say it should be, more or less like 2.5.

          In any case, again:

          • Any comparison has to be done with the same course.
          • I'd not expect any difference in the number of calls to those 2 methods.
          • I'd expect a quicker execution of those to methods.
          • Note that profiling do not show those methods by default, aka, they are not in the top-100 list of consuming methods... so the performance gain is really small (unless the course is very-vey-big).

          Hope this helps to understand the numbers and the expected results a bit better. Surely Sam Hemelryk / Russell Smith can confirm those points.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - - edited About the numbers above (once stated where the differences should happen in my previous comment)... I really would expect both 26_STABLE and master to have the same number of calls (rendering the course page of the same course, so I assume the differences there are because a different course was used). And about differences with 25_STABLE, for sure it had tons more that anyone else, because it's when the domain/secret identifiers were added and, also, because for that version, every make() call was reinstantiating the whole cache configs, surely causing identifiers and keys to be called way more times (that was one of the improvements done for 2.6). Finally, 2.4, surely a lower number of calls may be justified, although I'd say it should be, more or less like 2.5. In any case, again: Any comparison has to be done with the same course. I'd not expect any difference in the number of calls to those 2 methods. I'd expect a quicker execution of those to methods. Note that profiling do not show those methods by default, aka, they are not in the top-100 list of consuming methods... so the performance gain is really small (unless the course is very-vey-big). Hope this helps to understand the numbers and the expected results a bit better. Surely Sam Hemelryk / Russell Smith can confirm those points. Ciao
          Hide
          Mark Nelson added a comment -

          Thanks for the thorough explanation Eloy.

          When you say any comparison has to be done on the same course, do you mean that all the branches should be tested on a course with the same amount of activities etc? If I had known this I would have done so, but the testing instructions simply state 'Review a profile of a course page and confirm that generate_single_key_prefix does not make function calls in the numbers that approach the number of calls being made to set_identifiers.' So, I viewed a course in each branch that required testing and compared the two numbers. I did not know, as you stated, that the patch does not make any change to the number of calls to both set_identifiers() and generate_single_key_prefix().

          Cheers!

          Please, Sam Hemelryk, if all looks good you can set this as passed.

          Show
          Mark Nelson added a comment - Thanks for the thorough explanation Eloy. When you say any comparison has to be done on the same course, do you mean that all the branches should be tested on a course with the same amount of activities etc? If I had known this I would have done so, but the testing instructions simply state 'Review a profile of a course page and confirm that generate_single_key_prefix does not make function calls in the numbers that approach the number of calls being made to set_identifiers.' So, I viewed a course in each branch that required testing and compared the two numbers. I did not know, as you stated, that the patch does not make any change to the number of calls to both set_identifiers() and generate_single_key_prefix(). Cheers! Please, Sam Hemelryk , if all looks good you can set this as passed.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Yeah, Mark. To make the profiling runs comparable (between branches!) all them should be running the same course. Anyway, the point is to compare within the same branch the before and after results (with the same course, too, obviously).

          In my verifications yesterday I saw that the number of calls to both functions was exactly the same before and after. Just the execution times were smaller with the patch applied because a bunch of loops are avoided by the new detection of already existing definitions.

          If that's what Russell was trying to explain in the testing instructions or no, well, that's another story. Your English is far better than mine, LOL. It would be great to get a confirmation from Sam or Russell about those being the expected results (from a performance POV):

          • Same number of calls before/after.
          • Quicker execution of the methods after.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Yeah, Mark. To make the profiling runs comparable (between branches!) all them should be running the same course. Anyway, the point is to compare within the same branch the before and after results (with the same course, too, obviously). In my verifications yesterday I saw that the number of calls to both functions was exactly the same before and after. Just the execution times were smaller with the patch applied because a bunch of loops are avoided by the new detection of already existing definitions. If that's what Russell was trying to explain in the testing instructions or no, well, that's another story. Your English is far better than mine, LOL. It would be great to get a confirmation from Sam or Russell about those being the expected results (from a performance POV): Same number of calls before/after. Quicker execution of the methods after. Ciao
          Hide
          Sam Hemelryk added a comment -

          Hiya,

          Profiling wise you would have had to watch the number of times prefix was actually set, not just the number of times generate_single_key_prefix was called.
          The purpose of that profiling was that before this change when set_identifiers was called the key prefixes we reset, and then upon the next interaction with the cache the prefix would have been regenerated.
          generate_single_key_prefix only regenerates if the prefix is null, if its already set that function does nothing.
          Russells change avoids reseting those keys if the identifiers have been set as they were.

          I've just tested this change myself now, and am confident is functioning as expected.

          Mark - as you're the tester its up to you, either pass it knowing I've tested, or have a play yourself as follows:

          1. Add a debug line to the set_identifiers call
          2. Add a debug line within the generate_single_key_prefix function after === null check.
          3. Count the number of each when you view a page.

          Cheers
          Sam

          Show
          Sam Hemelryk added a comment - Hiya, Profiling wise you would have had to watch the number of times prefix was actually set, not just the number of times generate_single_key_prefix was called. The purpose of that profiling was that before this change when set_identifiers was called the key prefixes we reset, and then upon the next interaction with the cache the prefix would have been regenerated. generate_single_key_prefix only regenerates if the prefix is null, if its already set that function does nothing. Russells change avoids reseting those keys if the identifiers have been set as they were. I've just tested this change myself now, and am confident is functioning as expected. Mark - as you're the tester its up to you, either pass it knowing I've tested, or have a play yourself as follows: Add a debug line to the set_identifiers call Add a debug line within the generate_single_key_prefix function after === null check. Count the number of each when you view a page. Cheers Sam
          Hide
          Mark Nelson added a comment -

          Hi Sam, sorry, I wasn't able to work out what I was expected to do via the testing instructions. Thanks for clarifying. I did not want to add any extra work for you and am happy if you tested it and consider it working. Also, thanks to Russel for helping to improve Moodle's performance.

          Show
          Mark Nelson added a comment - Hi Sam, sorry, I wasn't able to work out what I was expected to do via the testing instructions. Thanks for clarifying. I did not want to add any extra work for you and am happy if you tested it and consider it working. Also, thanks to Russel for helping to improve Moodle's performance.
          Hide
          Sam Hemelryk added a comment -

          No probs at all aye, performance once can be tricky to test... or really prove, as was the case here.

          Show
          Sam Hemelryk added a comment - No probs at all aye, performance once can be tricky to test... or really prove, as was the case here.
          Hide
          Russell Smith added a comment -

          Sorry for the dodgy testing instructions. All the discussion has helped me with writing clearer testing instructions for performance related issues.

          Show
          Russell Smith added a comment - Sorry for the dodgy testing instructions. All the discussion has helped me with writing clearer testing instructions for performance related issues.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Aha, pretty well explained by Sam, indeed. I was trying to say the same with my point above "Quicker execution of the methods after". Given the identifiers have not changed, they are not recalculated, nor the prefix is reset (null), so both set_identifiers() and generate_single_key_prefix() are lighter.

          Injecting debugging / counts in critical places is an awesome good idea, yes. It makes verifications far easier.

          Ciao

          Show
          Eloy Lafuente (stronk7) added a comment - Aha, pretty well explained by Sam, indeed. I was trying to say the same with my point above "Quicker execution of the methods after". Given the identifiers have not changed, they are not recalculated, nor the prefix is reset (null), so both set_identifiers() and generate_single_key_prefix() are lighter. Injecting debugging / counts in critical places is an awesome good idea, yes. It makes verifications far easier. Ciao
          Hide
          Damyon Wiese added a comment -

          Twas the week before Christmas,
          And all though HQ
          Devs were scrambling to finish peer review.
          They sent all their issues,
          and rushed out the door -
          "To the beach!" someone heard them roar!

          This issue has been released upstream. Thanks!

          Show
          Damyon Wiese added a comment - Twas the week before Christmas, And all though HQ Devs were scrambling to finish peer review. They sent all their issues, and rushed out the door - "To the beach!" someone heard them roar! This issue has been released upstream. Thanks!

            People

            • Votes:
              0 Vote for this issue
              Watchers:
              4 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved: