Moodle
  1. Moodle
  2. MDL-6795

Stats never runs. stats_monthly table gets very full

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: 1.6
    • Fix Version/s: 1.7.1, 1.8
    • Component/s: Administration
    • Labels:
      None
    • Environment:
      All
    • Database:
      Any
    • Affected Branches:
      MOODLE_16_STABLE
    • Fixed Branches:
      MOODLE_17_STABLE, MOODLE_18_STABLE
    • Rank:
      28059

      Description

      I'm trying to get the stats to work on a 1.6.1+ install (also 1.6.2). It seems to run away and never return. I set the stats settings so that it only went back a week, but it still never seems to end.

      Info:
      1. Site has about 125 courses.
      2. 800 users.
      3. Stats settings are set to look one week back and run no longer than an hour.
      4. After running for more than an hour, the 'stats_monthly' table has 2,344,571 records in it (it started empty), 'stats_daily', 'stats_user_daily' and 'stats_user_monthly' are empty, 'stats_user_weekly' has 195 records, and 'stats_weekly' has 136 records.
      5. If I access the stats functions, I get the message "There is no available data to display, sorry".

      After running some tests we discovered that the run ends up in an infinite loop in the 'stats_cron_monthly' function. In particular, the iterator of the loop, function stats_get_next_monthend, never increments the value. It stays the same.

      The function stats_get_next_monthend is doing some funky stuff with timestamps. The code reads:

      function stats_get_next_monthend($lastmonth) {
      return stats_getmidnight(strtotime(date('1-M-Y',$lastmonth).' +1 month'));
      }

        Issue Links

          Activity

          Hide
          Mike Churchward added a comment -

          More information/comments from a partners post:

          At the risk of saying something dumb, I will put in my 2 cents worth smile. I think there are some other issues. May just be my lack of understanding of the code but here are two issues I can't account for

          1) In daily stats nextmidnight is assigned to
          $nextmidnight = stats_get_next_dayend($timestart);

          I believe stats_get_next_dayend adds one day to the $timestart and then makes a call to some time zone handling code. However $timestart is prevously assigned a value that is normalized to the time zone. If the intension to actually increment the value by one day that adjusting for time zone a second time would produce an incorrect result. This value would be off variably depending on any differences between the time zone of the server and the defined time zone in Moodle. In our case on my test server, the above line actually results in $nextmidnight being assigned the same value as $timestart, which caused the daily processing loop to never start since if fails the $timestart < $nextmidnight clause.

          Honestly I haven't quite digested the time zone adjustment code, so maybe I am off base, but it it works as it seems it should then it must be getting called too often.

          2) The month routine shows a similar issue

          return stats_getmidnight(strtotime(date('1-M-Y',$lastmonth).' +1 month'));

          Always returns the same value for us when called from the monthly processing loop.

          $timestart = $nextmonthend;
          $nextmonthend = stats_get_next_monthend($timestart);

          If I change the value function to read

          return stats_getmidnight(strtotime('+1 month',$lastmonth));

          Then it solves the infinite loop problem. I haven't checked the exact values to see if this gets me exactly one month advanced. My guess is this suffers from the same problem as above where we would get about one month difference give or take the time zone difference of some hours. Probably not enough to easily be detected as an issue.

          Finally I wonder if there is some difference in how php versions process some of these string conversions. Is that possible? Our test VM is php 4.3.9, Cent OS 4.3. Our production system is running cPanel 4.4.2 and seems to have the same problems (haven't dug in as deep since it is production but has the infinite monthly loop).

          Show
          Mike Churchward added a comment - More information/comments from a partners post: At the risk of saying something dumb, I will put in my 2 cents worth smile. I think there are some other issues. May just be my lack of understanding of the code but here are two issues I can't account for 1) In daily stats nextmidnight is assigned to $nextmidnight = stats_get_next_dayend($timestart); I believe stats_get_next_dayend adds one day to the $timestart and then makes a call to some time zone handling code. However $timestart is prevously assigned a value that is normalized to the time zone. If the intension to actually increment the value by one day that adjusting for time zone a second time would produce an incorrect result. This value would be off variably depending on any differences between the time zone of the server and the defined time zone in Moodle. In our case on my test server, the above line actually results in $nextmidnight being assigned the same value as $timestart, which caused the daily processing loop to never start since if fails the $timestart < $nextmidnight clause. Honestly I haven't quite digested the time zone adjustment code, so maybe I am off base, but it it works as it seems it should then it must be getting called too often. 2) The month routine shows a similar issue return stats_getmidnight(strtotime(date('1-M-Y',$lastmonth).' +1 month')); Always returns the same value for us when called from the monthly processing loop. $timestart = $nextmonthend; $nextmonthend = stats_get_next_monthend($timestart); If I change the value function to read return stats_getmidnight(strtotime('+1 month',$lastmonth)); Then it solves the infinite loop problem. I haven't checked the exact values to see if this gets me exactly one month advanced. My guess is this suffers from the same problem as above where we would get about one month difference give or take the time zone difference of some hours. Probably not enough to easily be detected as an issue. Finally I wonder if there is some difference in how php versions process some of these string conversions. Is that possible? Our test VM is php 4.3.9, Cent OS 4.3. Our production system is running cPanel 4.4.2 and seems to have the same problems (haven't dug in as deep since it is production but has the infinite monthly loop).
          Hide
          Martin Dougiamas added a comment -

          Hi, Penny, you know this code best - does something jump out for you?

          The patch today apparently was not the answer.

          Show
          Martin Dougiamas added a comment - Hi, Penny, you know this code best - does something jump out for you? The patch today apparently was not the answer.
          Hide
          Martin Dougiamas added a comment -

          After reading closer the timezone seems like a likely culprit. It might explain why many servers have no problems with the same code.

          Show
          Martin Dougiamas added a comment - After reading closer the timezone seems like a likely culprit. It might explain why many servers have no problems with the same code.
          Hide
          Jonathan Moore added a comment -

          I am wondering what the status is on this. There are a lot of hosting clients that are impacted by this. Anyone that needs to set a different timezone than the base server cannot utilize this feature. We confirmed with a client today that putting the time zone to server default in admin and clearing out the stats tables and config, does get it working, so this seems to be 100% related to the time zone code. We have several other clients that are needing to use stats package data to meet accreditation. Is there an ETA on a fix.

          Show
          Jonathan Moore added a comment - I am wondering what the status is on this. There are a lot of hosting clients that are impacted by this. Anyone that needs to set a different timezone than the base server cannot utilize this feature. We confirmed with a client today that putting the time zone to server default in admin and clearing out the stats tables and config, does get it working, so this seems to be 100% related to the time zone code. We have several other clients that are needing to use stats package data to meet accreditation. Is there an ETA on a fix.
          Hide
          Martín Langhoff added a comment -

          Hola! Just been though the code with Penny and I think we have a problem with the TZ handling that may or may not be the cause ofthe infinite loop. To actually debug the infinite loop, we'd like to see an installation that shows it – we haven't had any luck reproducing this :-/

          The problem we are seeing is that those calles to date() and strtotime() are bogus, We cannot really use date() and we can only use strtotime() in very specific cases in Moodle because we are not using PHP's standard date/time functions, and instead we have our home-brewed TZ stuff that doesn't quite cover what strtotime() does. date() isn't such a problem, but strtotime() is very rich in what it does...

          Targetting 1.8 the fix would be to go back to PHP's native date/time functions as described in MDL-7272 (linked now). For 1.7 we can

          • Set $ENV[TZ] to get strtotime() to use our timezone
          • Rewrite the logic to find a way to suss out the 1st of each month without strtotime() – or at least without forcing it to guess a tz
          • Or we could write our own strtotime() implementation.

          Again – I don't know if this TZ problem is the cause of the bug.

          Show
          Martín Langhoff added a comment - Hola! Just been though the code with Penny and I think we have a problem with the TZ handling that may or may not be the cause ofthe infinite loop. To actually debug the infinite loop, we'd like to see an installation that shows it – we haven't had any luck reproducing this :-/ The problem we are seeing is that those calles to date() and strtotime() are bogus, We cannot really use date() and we can only use strtotime() in very specific cases in Moodle because we are not using PHP's standard date/time functions, and instead we have our home-brewed TZ stuff that doesn't quite cover what strtotime() does. date() isn't such a problem, but strtotime() is very rich in what it does... Targetting 1.8 the fix would be to go back to PHP's native date/time functions as described in MDL-7272 (linked now). For 1.7 we can Set $ENV [TZ] to get strtotime() to use our timezone Rewrite the logic to find a way to suss out the 1st of each month without strtotime() – or at least without forcing it to guess a tz Or we could write our own strtotime() implementation. Again – I don't know if this TZ problem is the cause of the bug.
          Hide
          Martín Langhoff added a comment -

          Repost (as Jira doesn't seem to email out if you post it as a comment to a link action):

          Hola! Just been though the code with Penny and I think we have a problem with the TZ handling that may or may not be the cause ofthe infinite loop. To actually debug the infinite loop, we'd like to see an installation that shows it – we haven't had any luck reproducing this :-/

          The problem we are seeing is that those calles to date() and strtotime() are bogus, We cannot really use date() and we can only use strtotime() in very specific cases in Moodle because we are not using PHP's standard date/time functions, and instead we have our home-brewed TZ stuff that doesn't quite cover what strtotime() does. date() isn't such a problem, but strtotime() is very rich in what it does...

          Targetting 1.8 the fix would be to go back to PHP's native date/time functions as described in MDL-7272 (linked now). For 1.7 we can

          • Set $ENV[TZ] to get strtotime() to use our timezone
          • Rewrite the logic to find a way to suss out the 1st of each month without strtotime() – or at least without forcing it to guess a tz
          • Or we could write our own strtotime() implementation.

          Again – I don't know if this TZ problem is the cause of the bug.

          Show
          Martín Langhoff added a comment - Repost (as Jira doesn't seem to email out if you post it as a comment to a link action): Hola! Just been though the code with Penny and I think we have a problem with the TZ handling that may or may not be the cause ofthe infinite loop. To actually debug the infinite loop, we'd like to see an installation that shows it – we haven't had any luck reproducing this :-/ The problem we are seeing is that those calles to date() and strtotime() are bogus, We cannot really use date() and we can only use strtotime() in very specific cases in Moodle because we are not using PHP's standard date/time functions, and instead we have our home-brewed TZ stuff that doesn't quite cover what strtotime() does. date() isn't such a problem, but strtotime() is very rich in what it does... Targetting 1.8 the fix would be to go back to PHP's native date/time functions as described in MDL-7272 (linked now). For 1.7 we can Set $ENV [TZ] to get strtotime() to use our timezone Rewrite the logic to find a way to suss out the 1st of each month without strtotime() – or at least without forcing it to guess a tz Or we could write our own strtotime() implementation. Again – I don't know if this TZ problem is the cause of the bug.
          Hide
          Jonathan Moore added a comment -

          I have setup a test account for you that should reproduce the issue. Please contact me via email for login credentials. jonathan@remote-learner.net. OS is CentOS 4.3. Based on past performance you should be able to reproduce simply by assigning a time zone value other than server default and then activating stats. And it should "fix" by clearing mdl_stats dbs and stats config entries and setting time zone to server default. I believe I even saw one of these trigger yesterday with the TZ set to the same as the server EST, but set as -5gmt instead of server default.

          Show
          Jonathan Moore added a comment - I have setup a test account for you that should reproduce the issue. Please contact me via email for login credentials. jonathan@remote-learner.net. OS is CentOS 4.3. Based on past performance you should be able to reproduce simply by assigning a time zone value other than server default and then activating stats. And it should "fix" by clearing mdl_stats dbs and stats config entries and setting time zone to server default. I believe I even saw one of these trigger yesterday with the TZ set to the same as the server EST, but set as -5gmt instead of server default.
          Hide
          Martin Dougiamas added a comment -

          I thought this was fixed?!?! Is the problem still occurring on the latest 1.7 and 1.8 ?

          Show
          Martin Dougiamas added a comment - I thought this was fixed?!?! Is the problem still occurring on the latest 1.7 and 1.8 ?
          Hide
          Sam Roche added a comment -

          I seem to have been hit with the same problem... I've turned on Stats for our Moodle instance because I thought they would be nice, and now have a 4GB stats_monthly table.

          I've now turned off the stats feature, as it's not a necessity at the moment, but would like to know if there are any implications for clearing this table?

          I'm running 1.6, and am avoiding upgrading to 1.7/1.8, as we're using Active Directory authentication and a colleague of mine who is much more familiar with the system has mentioned that there have been a lot of posts in the forum about upgrading..

          Show
          Sam Roche added a comment - I seem to have been hit with the same problem... I've turned on Stats for our Moodle instance because I thought they would be nice, and now have a 4GB stats_monthly table. I've now turned off the stats feature, as it's not a necessity at the moment, but would like to know if there are any implications for clearing this table? I'm running 1.6, and am avoiding upgrading to 1.7/1.8, as we're using Active Directory authentication and a colleague of mine who is much more familiar with the system has mentioned that there have been a lot of posts in the forum about upgrading..
          Hide
          Jonathan Moore added a comment -

          Just another follow up. We really need this fixed in the 1.6 tree. I just had another new client messed up by this bug and yesterday I found 10 GB of wasted mysql queries due to the bug. 1.7/1.8 present their own unique challenges to our user base, so we need a fix for this, it really messes a server up if you get even one or two moodle instances running in this infinite loop.

          Show
          Jonathan Moore added a comment - Just another follow up. We really need this fixed in the 1.6 tree. I just had another new client messed up by this bug and yesterday I found 10 GB of wasted mysql queries due to the bug. 1.7/1.8 present their own unique challenges to our user base, so we need a fix for this, it really messes a server up if you get even one or two moodle instances running in this infinite loop.
          Hide
          Mike Churchward added a comment -

          Penny (or whoever is working on this):

          I think I know what the problem is. The culprit is in the function 'stats_getmidnight'. This function intends to get the midnight time for the day passed to it.

          I'm not actually sure why, but using the 'stats_getdate' function on it (which I think is intended to apply the timezone to it so that 'make_timestamp' can un-apply the timezone) seems to cause the problem. I replaced it with the PHP standard 'getdate', and it always seems to work, no matter what I configure the site timezone to.

          I think the problem is that 'make_timezone' doesn't actually return a GMT timestamp like it says in its comments. It returns a timestamp in the selected timezone. So, that when 'stats_getdate' applies the timezone, the effect is to get it applied twice.

          Show
          Mike Churchward added a comment - Penny (or whoever is working on this): I think I know what the problem is. The culprit is in the function 'stats_getmidnight'. This function intends to get the midnight time for the day passed to it. I'm not actually sure why, but using the 'stats_getdate' function on it (which I think is intended to apply the timezone to it so that 'make_timestamp' can un-apply the timezone) seems to cause the problem. I replaced it with the PHP standard 'getdate', and it always seems to work, no matter what I configure the site timezone to. I think the problem is that 'make_timezone' doesn't actually return a GMT timestamp like it says in its comments. It returns a timestamp in the selected timezone. So, that when 'stats_getdate' applies the timezone, the effect is to get it applied twice.
          Hide
          Martín Langhoff added a comment -

          Mike - I think your analysis is correct, and that

          Index: lib/statslib.php
          ===================================================================
          RCS file: /cvsroot/moodle/moodle/lib/statslib.php,v
          retrieving revision 1.50
          diff -u -r1.50 statslib.php
          — lib/statslib.php 26 Feb 2007 00:18:19 -0000 1.50
          +++ lib/statslib.php 28 Feb 2007 02:37:06 -0000
          @@ -1100,7 +1100,7 @@
          // copied from usergetmidnight, but we ignore dst
          function stats_getmidnight($date, $timezone=99)

          { $timezone = get_user_timezone_offset($timezone); - $userdate = stats_getdate($date, $timezone); + $userdate = getdate($date); return make_timestamp($userdate['year'], $userdate['mon'], $userdate['mday'], 0, 0, 0, $timezone,false ); // ignore dst for this. }

          should fix it.

          PHP's date/time handling s a bit muddy, and our Moodle layer over it is really bad. I can't wait to get rid of it. We set out to workaround one bug and introduced a thousand.

          Show
          Martín Langhoff added a comment - Mike - I think your analysis is correct, and that Index: lib/statslib.php =================================================================== RCS file: /cvsroot/moodle/moodle/lib/statslib.php,v retrieving revision 1.50 diff -u -r1.50 statslib.php — lib/statslib.php 26 Feb 2007 00:18:19 -0000 1.50 +++ lib/statslib.php 28 Feb 2007 02:37:06 -0000 @@ -1100,7 +1100,7 @@ // copied from usergetmidnight, but we ignore dst function stats_getmidnight($date, $timezone=99) { $timezone = get_user_timezone_offset($timezone); - $userdate = stats_getdate($date, $timezone); + $userdate = getdate($date); return make_timestamp($userdate['year'], $userdate['mon'], $userdate['mday'], 0, 0, 0, $timezone,false ); // ignore dst for this. } should fix it. PHP's date/time handling s a bit muddy, and our Moodle layer over it is really bad. I can't wait to get rid of it. We set out to workaround one bug and introduced a thousand.
          Hide
          Martín Langhoff added a comment -

          Tentative fix applied to 17_STABLE, 18_STABLE and HEAD.

          Show
          Martín Langhoff added a comment - Tentative fix applied to 17_STABLE, 18_STABLE and HEAD.
          Hide
          Anthony Borrow added a comment -

          Martin - Is there any reason why the tentative fix was not applied to 1.6? I still occasionally notice that my stats are in catchup mode and have been surprised the MDL-7983 has not been addressed and wonder if this might address it. The patch I had found in the forum did not seem to address it or at least an issue remains. Peace.

          Show
          Anthony Borrow added a comment - Martin - Is there any reason why the tentative fix was not applied to 1.6? I still occasionally notice that my stats are in catchup mode and have been surprised the MDL-7983 has not been addressed and wonder if this might address it. The patch I had found in the forum did not seem to address it or at least an issue remains. Peace.

            People

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

              Dates

              • Created:
                Updated:
                Resolved: