Moodle
  1. Moodle
  2. MDL-38212

Cron - do gc_collect_cycles between tasks, and report memory usage

    Details

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

      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.

        Activity

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

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

        Show
        Dan Poltawski added a comment - Since you are offering, it will be interesting to see that before integrating.
        Hide
        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
        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
        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
        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
        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
        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
        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
        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
        Eloy Lafuente (stronk7) added a comment -

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

        Show
        Eloy Lafuente (stronk7) added a comment - Just hope nobody is calling stuff like stats_clean_old() out from cron execution...
        Hide
        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
        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
        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
        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
        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
        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
        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
        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
        Tim Hunt added a comment -

        +1 from me.

        Show
        Tim Hunt added a comment - +1 from me.
        Hide
        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
        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
        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
        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
        David Mudrak added a comment -

        +1 thanks Eloy.

        Show
        David Mudrak added a comment - +1 thanks Eloy.
        Hide
        Rossiani Wijaya added a comment -

        This works as expected.

        Tested on master only

        Test passed.

        Show
        Rossiani Wijaya added a comment - This works as expected. Tested on master only Test passed.
        Hide
        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
        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: