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

      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

        Gliffy Diagrams

        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: