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:
    • 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

          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: