Moodle
  1. Moodle
  2. MDL-25191

Possible memory leakage in modinfo cache

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 2.0
    • Fix Version/s: 2.0.4
    • Component/s: My home
    • Labels:
      None
    • Testing Instructions:
      Hide

      (sorry this is a crap test, but since I'm not able to reproduce it at the moment...)

      Difficulty: EASY

      1. Visit any course page. Make sure it appears without errors.
      2. Visit the /my/ page. Make sure it appears without errors

      Show
      (sorry this is a crap test, but since I'm not able to reproduce it at the moment...) Difficulty: EASY 1. Visit any course page. Make sure it appears without errors. 2. Visit the /my/ page. Make sure it appears without errors
    • Affected Branches:
      MOODLE_20_STABLE
    • Fixed Branches:
      MOODLE_20_STABLE
    • Pull Master Branch:
      MDL-25191-master
    • Rank:
      2701

      Description

      Hi, sorry I don't have reproduce steps but I get this error when I go to /my/ as admin in a Moodle 2 test install.

      The test install is not that big, 238 courses which mostly pretty much seem to just have a few assignments on each (I think these were automatically created by some manic unit test which maybe still exists? that would be a separate bug). Obviously as admin I do have access to all courses, but don't have a specific role on more than a few dozen.

      I could increase memory limit but it seems to me that (a) except on a really big site, users shouldn't need to do that, the default should be enough, and (b) it's possible that something inefficient is happening here that is causing it to blow the limit. So just filing this in case anyone wants to look at the trace.

      Fatal error: Allowed memory size of 134217728 bytes exhausted (tried to allocate 32 bytes) in /fs2/www/html/sm449/coremoodle/lib/dml/pgsql_native_moodle_database.php on line 681

      Call Stack:
      0.0003 676280 1.

      {main}

      () /fs2/www/html/sm449/coremoodle/my/index.php:0
      0.4880 13677512 2. core_renderer->blocks_for_region() /fs2/www/html/sm449/coremoodle/my/index.php:148
      0.4881 13677512 3. block_manager->get_content_for_region() /fs2/www/html/sm449/coremoodle/lib/outputrenderers.php:899
      0.4881 13677512 4. block_manager->ensure_content_created() /fs2/www/html/sm449/coremoodle/lib/blocklib.php:304
      0.4881 13677728 5. block_manager->create_block_contents() /fs2/www/html/sm449/coremoodle/lib/blocklib.php:934
      0.4881 13678344 6. block_base->get_content_for_output() /fs2/www/html/sm449/coremoodle/lib/blocklib.php:882
      0.4882 13680376 7. block_base->formatted_contents() /fs2/www/html/sm449/coremoodle/blocks/moodleblock.class.php:232
      0.4882 13680376 8. block_course_overview->get_content() /fs2/www/html/sm449/coremoodle/blocks/moodleblock.class.php:279
      0.4910 13743560 9. print_overview() /fs2/www/html/sm449/coremoodle/blocks/course_overview/block_course_overview.php:96
      0.4998 13945816 10. forum_print_overview() /fs2/www/html/sm449/coremoodle/course/lib.php:856
      0.4998 13945896 11. get_all_instances_in_courses() /fs2/www/html/sm449/coremoodle/mod/forum/lib.php:1199
      0.5031 14030800 12. get_fast_modinfo() /fs2/www/html/sm449/coremoodle/lib/datalib.php:1481
      0.5033 14040048 13. rebuild_course_cache() /fs2/www/html/sm449/coremoodle/lib/moodlelib.php:3041
      0.5040 14042296 14. get_array_of_activities() /fs2/www/html/sm449/coremoodle/course/lib.php:1738
      0.5055 14063352 15. moodle_database->get_records() /fs2/www/html/sm449/coremoodle/course/lib.php:1061
      0.5055 14063976 16. moodle_database->get_records_select() /fs2/www/html/sm449/coremoodle/lib/dml/moodle_database.php:1024
      0.5055 14064288 17. pgsql_native_moodle_database->get_records_sql() /fs2/www/html/sm449/coremoodle/lib/dml/moodle_database.php:1075
      1.0376 14065656 18. pg_fetch_all() /fs2/www/html/sm449/coremoodle/lib/dml/pgsql_native_moodle_database.php:681

      1. silly.php
        0.6 kB
        Sam Marshall
      2. silly.php
        0.6 kB
        Sam Marshall

        Issue Links

          Activity

          Hide
          Adam Olley added a comment -

          This appears to be an issue with get_fast_modinfo. The function uses a static cache variable. When that cache exceeds its permitted size, it unset's the first element of its array. The problem is, with static variables, unset'ting elements of it only unset's it for the remainder of the functions call, the data is actually removed/set as free for subsequent calls.

          So if your my moodle page is set to display more than the 10 courses the cache will hold, for certain courses that have a lot of assignments/quizzes/other modinfo that'd be displayed on my moodle, the memory usage jumps by about 30MB per mod it checks as it's doubling up on the cache each time.

          I'll put up a pull link for a fix to this in a moment.

          Show
          Adam Olley added a comment - This appears to be an issue with get_fast_modinfo. The function uses a static cache variable. When that cache exceeds its permitted size, it unset's the first element of its array. The problem is, with static variables, unset'ting elements of it only unset's it for the remainder of the functions call, the data is actually removed/set as free for subsequent calls. So if your my moodle page is set to display more than the 10 courses the cache will hold, for certain courses that have a lot of assignments/quizzes/other modinfo that'd be displayed on my moodle, the memory usage jumps by about 30MB per mod it checks as it's doubling up on the cache each time. I'll put up a pull link for a fix to this in a moment.
          Show
          Adam Olley added a comment - Code to fix this: https://github.com/aolley/moodle/commit/6cb892f7eafd0fdf3f81e8acfd1b134b78f385b3
          Hide
          Sam Marshall added a comment -

          Adam, thank you for this. Interesting behaviour. But are you sure this is the problem?

          I see what you mean about the odd behaviour regarding static caches not being freed until end of the function, however the function that contains the static already has ended (i.e. it is called, it returns one single modinfo & removes one from the cache, it exits). So it seems to me this should not cause the problem.

          I have attached a standalone silly.php to demonstrate the same pattern. This has a function which returns one value, adds one to array, removes one using unset if there are more than 10, and returns. This is done 1024 times and it prints memory usage after each time. The results I see are:

          1294976
          1950624
          2606144
          3261664
          3917184
          4572704
          5228224
          5883744
          6539328
          7194848
          7194848
          7194848
          7194848
          ...

          (i.e. memory increases 10 times, then stops increasing)

          Show
          Sam Marshall added a comment - Adam, thank you for this. Interesting behaviour. But are you sure this is the problem? I see what you mean about the odd behaviour regarding static caches not being freed until end of the function, however the function that contains the static already has ended (i.e. it is called, it returns one single modinfo & removes one from the cache, it exits). So it seems to me this should not cause the problem. I have attached a standalone silly.php to demonstrate the same pattern. This has a function which returns one value, adds one to array, removes one using unset if there are more than 10, and returns. This is done 1024 times and it prints memory usage after each time. The results I see are: 1294976 1950624 2606144 3261664 3917184 4572704 5228224 5883744 6539328 7194848 7194848 7194848 7194848 ... (i.e. memory increases 10 times, then stops increasing)
          Hide
          Sam Marshall added a comment -

          (well, I did attach it, but Jira decided otherwise - here is silly.php)

          Show
          Sam Marshall added a comment - (well, I did attach it, but Jira decided otherwise - here is silly.php)
          Hide
          Adam Olley added a comment -

          Looks like it has something to do with the cache elements being set to new course_modinfo, as in testing if I change that to be something else (like a huge hunk of random data like in your example), its successfully unset. Perhaps also the fact that the calling function uses some variables from the returned data.

          Show
          Adam Olley added a comment - Looks like it has something to do with the cache elements being set to new course_modinfo, as in testing if I change that to be something else (like a huge hunk of random data like in your example), its successfully unset. Perhaps also the fact that the calling function uses some variables from the returned data.
          Hide
          Adam Olley added a comment -

          I've got a better solution for this now, it appears to be related to the cache entries having classes assigned to itself.
          So if just before you unset($cache[$key]); you do the following:

          unset($cache[$key]->instances);
          unset($cache[$key]->cms);

          And THEN unset $cache[$key], it all gets properly destroyed (set as free memory).

          Show
          Adam Olley added a comment - I've got a better solution for this now, it appears to be related to the cache entries having classes assigned to itself. So if just before you unset($cache [$key] ); you do the following: unset($cache [$key] ->instances); unset($cache [$key] ->cms); And THEN unset $cache [$key] , it all gets properly destroyed (set as free memory).
          Show
          Adam Olley added a comment - Git for the above: https://github.com/aolley/moodle/commit/8d7aa26014cab44bd6b8984e6f037efd80b61a64
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Hi Sam, any comment / update about this? Those circulars really need proper destroy under PHP 5.2, I remember myself adding them to the highly-circular backup stuff in order to be able to execute the scheduled backups because mem was getting full with a few backup instances.

          Show
          Eloy Lafuente (stronk7) added a comment - Hi Sam, any comment / update about this? Those circulars really need proper destroy under PHP 5.2, I remember myself adding them to the highly-circular backup stuff in order to be able to execute the scheduled backups because mem was getting full with a few backup instances.
          Hide
          Sam Marshall added a comment -

          Hi Eloy,

          1) I can't reproduce the original bug any more

          2) The proposed patch looks good - I don't really like 'pandering' to the garbage collector but I guess this is preferable (in performance terms) compared to calling gc_collect_cycles.

          I will import the patch into my repo based on latest and submit for integration, in a minute.

          Show
          Sam Marshall added a comment - Hi Eloy, 1) I can't reproduce the original bug any more 2) The proposed patch looks good - I don't really like 'pandering' to the garbage collector but I guess this is preferable (in performance terms) compared to calling gc_collect_cycles. I will import the patch into my repo based on latest and submit for integration, in a minute.
          Hide
          Sam Marshall added a comment -

          OK, submitting for integration - I rebased the change onto my master and 2.0 branches.

          Show
          Sam Marshall added a comment - OK, submitting for integration - I rebased the change onto my master and 2.0 branches.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          This has been integrated. It is really ugly, but if helps...

          One curiosity Adam, did you reproduce the problem under PHP 5.2 or 5.3 ?

          Show
          Eloy Lafuente (stronk7) added a comment - This has been integrated. It is really ugly, but if helps... One curiosity Adam, did you reproduce the problem under PHP 5.2 or 5.3 ?
          Hide
          Adam Olley added a comment -

          It was under PHP 5.3.

          Show
          Adam Olley added a comment - It was under PHP 5.3.
          Hide
          Sam Marshall added a comment -

          thanks eloy, adam.

          For info I recently saw an unrelated out-of-memory issue on our live 1.9 system under php 5.3 (in custom OU code) where there does not appear to be an 'actual' leak but there may be similar circular references. In that case there was no performance concern so I added gc_collect_cycles calls in a convenient place, which appears to have resolved it, although we are not yet certain of this yet.

          So um basically I think the php 5.3 automatic GC is probably still broken, if that is in question...

          Show
          Sam Marshall added a comment - thanks eloy, adam. For info I recently saw an unrelated out-of-memory issue on our live 1.9 system under php 5.3 (in custom OU code) where there does not appear to be an 'actual' leak but there may be similar circular references. In that case there was no performance concern so I added gc_collect_cycles calls in a convenient place, which appears to have resolved it, although we are not yet certain of this yet. So um basically I think the php 5.3 automatic GC is probably still broken, if that is in question...
          Hide
          Sam Hemelryk added a comment -

          Thanks guys - everything looks good.

          Show
          Sam Hemelryk added a comment - Thanks guys - everything looks good.
          Hide
          Eloy Lafuente (stronk7) added a comment -

          Blame PHP gc, blame PHP gc... sent upstream! Thanks!

          Show
          Eloy Lafuente (stronk7) added a comment - Blame PHP gc, blame PHP gc... sent upstream! Thanks!
          Hide
          Ruslan Kabalin added a comment -

          I have created a record for related issue we have been struggling with: MDL-40947

          Show
          Ruslan Kabalin added a comment - I have created a record for related issue we have been struggling with: MDL-40947

            People

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

              Dates

              • Created:
                Updated:
                Resolved: