Uploaded image for project: 'Moodle'
  1. Moodle
  2. MDL-38212

Cron - do gc_collect_cycles between tasks, and report memory usage

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 2.3.4, 2.4.1
    • Fix Version/s: 2.5
    • Component/s: Libraries
    • Labels:
    • Testing Instructions:
      Hide

      Run cron:

      1. Using the CLI mode.
      2. Throuh the web interface.

      Confirm that it still works, and that the extra information displayed is helpful.

      Show
      Run cron: 1. Using the CLI mode. 2. Throuh the web interface. Confirm that it still works, and that the extra information displayed is helpful.
    • Affected Branches:
      MOODLE_23_STABLE, MOODLE_24_STABLE
    • Fixed Branches:
      MOODLE_25_STABLE
    • Pull from Repository:
    • Pull Master Branch:

      Description

      These are two things we have done at the OU, but they are probably useful to everyone, so putting them up for review.

      1. PHP is not great at garbage collection. We have found in the past that adding calls to gc_collect_cycles() at appropriate places can really help long-running PHP processes, and cron.php falls into that category.

      2. Before and after each chunk of cron, output the current time and current memory usage. Then, when cron gets slow, or uses a lot of memory, you can easily see where the problem might be.

        Gliffy Diagrams

          Attachments

            Activity

            Hide
            poltawski Dan Poltawski added a comment - - edited

            Hi Tim,

            I saw the title and couldn't resist to review it. (bad)

            I think this is a great improvement. On more than one occasion i've edited cron and added my own code on production servers to do this when trying to debug things. But never actually sat down outside of the heat of moment to actually add this to Moodle.

            I would support a backport request for this too as I think it's useful to admins everywhere.

            Show
            poltawski Dan Poltawski added a comment - - edited Hi Tim, I saw the title and couldn't resist to review it. (bad) I think this is a great improvement. On more than one occasion i've edited cron and added my own code on production servers to do this when trying to debug things. But never actually sat down outside of the heat of moment to actually add this to Moodle. I would support a backport request for this too as I think it's useful to admins everywhere.
            Hide
            timhunt Tim Hunt added a comment -

            Thanks, Dan. This was actually done by my colleagues Rod and Derek. I just cleaned up the code and submitted it here.

            Do you want us to wait until this is running on our live servers next week, which is the first time we will really be sure that the gc_collect_cycles bit brings a benefit?

            I agree with back-porting.

            Show
            timhunt Tim Hunt added a comment - Thanks, Dan. This was actually done by my colleagues Rod and Derek. I just cleaned up the code and submitted it here. Do you want us to wait until this is running on our live servers next week, which is the first time we will really be sure that the gc_collect_cycles bit brings a benefit? I agree with back-porting.
            Hide
            poltawski Dan Poltawski added a comment -

            Since you are offering, it will be interesting to see that before integrating.

            Show
            poltawski Dan Poltawski added a comment - Since you are offering, it will be interesting to see that before integrating.
            Hide
            timhunt Tim Hunt added a comment -

            OK, this is now working on our live system. We like the output, it is helpful.

            We are inconclusive whether the gc_collect_cycles makes a difference, but we think it can't possible hurt so should be left in.

            Cherry-picking to 2.3 was not clean. I decided not to deal with the calendar lib conflicts. We will just lack the logging output there in 2.3. Everything else was easy to fix.

            Show
            timhunt Tim Hunt added a comment - OK, this is now working on our live system. We like the output, it is helpful. We are inconclusive whether the gc_collect_cycles makes a difference, but we think it can't possible hurt so should be left in. Cherry-picking to 2.3 was not clean. I decided not to deal with the calendar lib conflicts. We will just lack the logging output there in 2.3. Everything else was easy to fix.
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week.

            TIA and ciao

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - The main moodle.git repository has just been updated with latest weekly modifications. You may wish to rebase your PULL branches to simplify history and avoid any possible merge conflicts. This would also make integrator's life easier next week. TIA and ciao
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            Hi, it looks perfect.. but... one question and one suggestion:

            1) Q: Which version are you running @ OU?

            2) Suggestion: As far as all those calls are always happening after mtrace() calls... wouldn't be really better to have cron_trace_time_and_memory() accepting one string and mtracing it? IMO that would lead to an easier to apply API, and people wouldn't leave missing calls when adding new cron sections in the future.

            Keeping open for some hours.... ciao

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - Hi, it looks perfect.. but... one question and one suggestion: 1) Q: Which version are you running @ OU? 2) Suggestion: As far as all those calls are always happening after mtrace() calls... wouldn't be really better to have cron_trace_time_and_memory() accepting one string and mtracing it? IMO that would lead to an easier to apply API, and people wouldn't leave missing calls when adding new cron sections in the future. Keeping open for some hours.... ciao
            Hide
            timhunt Tim Hunt added a comment -

            We are running 2.3.x. I think x = 3. We will be going to 2.4.1 in June. We are currently actually running a different version of this patch. I cleaned it up before submitting to core.

            I prefer the patch the way it is.

            • cron_trace_time_and_memory() displays time and memory usage.
            • mtrace display progress information.
              These are two separate actions. It is clearer to keep them as separate function calls. (IMO)
            Show
            timhunt Tim Hunt added a comment - We are running 2.3.x. I think x = 3. We will be going to 2.4.1 in June. We are currently actually running a different version of this patch. I cleaned it up before submitting to core. I prefer the patch the way it is. cron_trace_time_and_memory() displays time and memory usage. mtrace display progress information. These are two separate actions. It is clearer to keep them as separate function calls. (IMO)
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            Just hope nobody is calling stuff like stats_clean_old() out from cron execution...

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - Just hope nobody is calling stuff like stats_clean_old() out from cron execution...
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            I'm sorry but I don't think this should land to stables (after thinking about it for a while).

            It may hurt people already parsing output, expecting some results from cron. Or break people using custom code to calculate / clean statistics.

            And being strict, it's only an improvement. So targeting this as master-only.

            Ciao

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - I'm sorry but I don't think this should land to stables (after thinking about it for a while). It may hurt people already parsing output, expecting some results from cron. Or break people using custom code to calculate / clean statistics. And being strict, it's only an improvement. So targeting this as master-only. Ciao
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            Integrated (master only), thanks!

            Note: I've added one extra commit about to document the output change into lib/upgrade.txt (thanks Helen for amending it).

            Ciao

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - Integrated (master only), thanks! Note: I've added one extra commit about to document the output change into lib/upgrade.txt (thanks Helen for amending it). Ciao
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            lol/grrr (phpunit):

            ...
            PHP  15. available_update_checker_test->test_cron_offset_execution() 
            PHP  16. available_update_checker->cron() lib/tests/pluginlib_test.php:150
             
            Fatal error: Call to undefined function cron_trace_time_and_memory() in lib/pluginlib.php on line 812

            Amending...

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - lol/grrr (phpunit): ... PHP 15. available_update_checker_test->test_cron_offset_execution() PHP 16. available_update_checker->cron() lib/tests/pluginlib_test.php:150   Fatal error: Call to undefined function cron_trace_time_and_memory() in lib/pluginlib.php on line 812 Amending...
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            Oki, after looking to it, it seems that the simplest solution is to stop using the new cron_trace_time_and_memory() within pluginlib->cron().

            1) Right now, it's not used always (within cron_execute() ) but only on regular updates.
            2) That leads to inconsistent output (sometimes time&memory is printed, others isn't).
            3) That makes, at the end, not interesting to use Output expectations to verify what's printed out, more yet, when pluginlib testing has its own (empty) cron_mtrace() method.
            4) Updates are not something prone to cause time/memory problems, so it's not critical to have that information there.

            Hence the candidate patch is, simply:

            --- a/lib/pluginlib.php
            +++ b/lib/pluginlib.php
            @@ -809,7 +809,6 @@ class available_update_checker {
                     $start = mktime(1, 0, 0, date('n', $now), date('j', $now), date('Y', $now)); // 01:00 AM today local time
                     if ($now > $start + $offset) {
                         $this->cron_mtrace('Regular daily check for available updates ... ', '');
            -            cron_trace_time_and_memory();
                         $this->cron_execute();
                         return;
                     }

            Anybody against it?

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - Oki, after looking to it, it seems that the simplest solution is to stop using the new cron_trace_time_and_memory() within pluginlib->cron(). 1) Right now, it's not used always (within cron_execute() ) but only on regular updates. 2) That leads to inconsistent output (sometimes time&memory is printed, others isn't). 3) That makes, at the end, not interesting to use Output expectations to verify what's printed out, more yet, when pluginlib testing has its own (empty) cron_mtrace() method. 4) Updates are not something prone to cause time/memory problems, so it's not critical to have that information there. Hence the candidate patch is, simply: --- a/lib/pluginlib.php +++ b/lib/pluginlib.php @@ -809,7 +809,6 @@ class available_update_checker { $start = mktime(1, 0, 0, date('n', $now), date('j', $now), date('Y', $now)); // 01:00 AM today local time if ($now > $start + $offset) { $this->cron_mtrace('Regular daily check for available updates ... ', ''); - cron_trace_time_and_memory(); $this->cron_execute(); return; } Anybody against it?
            Hide
            timhunt Tim Hunt added a comment -

            +1 from me.

            Show
            timhunt Tim Hunt added a comment - +1 from me.
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            Crap, it's causing statslib_test.php to fail too, luckily it seems that simply requiring cronlib at the beginning is enough, as far as it's already ob-capturing output within the tests. Adding the missing require...

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - Crap, it's causing statslib_test.php to fail too, luckily it seems that simply requiring cronlib at the beginning is enough, as far as it's already ob-capturing output within the tests. Adding the missing require...
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            Oki, I've sent this to integration.git:

            http://git.moodle.org/gw?p=integration.git;a=commitdiff;h=613eebfc6ab3160e61bc06650d987cc35416ee91

            all tests are passing here now.

            Ciao

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - Oki, I've sent this to integration.git: http://git.moodle.org/gw?p=integration.git;a=commitdiff;h=613eebfc6ab3160e61bc06650d987cc35416ee91 all tests are passing here now. Ciao
            Hide
            mudrd8mz David Mudrák added a comment -

            +1 thanks Eloy.

            Show
            mudrd8mz David Mudrák added a comment - +1 thanks Eloy.
            Hide
            rwijaya Rossiani Wijaya added a comment -

            This works as expected.

            Tested on master only

            Test passed.

            Show
            rwijaya Rossiani Wijaya added a comment - This works as expected. Tested on master only Test passed.
            Hide
            stronk7 Eloy Lafuente (stronk7) added a comment -

            This issue has been integrated upstream and is now available both via git and cvs (and in some hours, via mirrors and downloads).

            Thanks!

            PS: Yay, legacy template messages. Yes, you're ok, we don't have CVS anymore!

            Show
            stronk7 Eloy Lafuente (stronk7) added a comment - This issue has been integrated upstream and is now available both via git and cvs (and in some hours, via mirrors and downloads). Thanks! PS: Yay, legacy template messages. Yes, you're ok, we don't have CVS anymore!

              People

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

                Dates

                • Created:
                  Updated:
                  Resolved:
                  Fix Release Date:
                  14/May/13