ZuckerReports saves wrong nextrun schedule date after running iReport

[gazza73]

Bug: Zucker Report SCHEDULES running progressively later each day......

My system/versions are described under my signature.

SYMPTOM:

When a scheduled report is run in Sugarcrm CE using ZuckerReports (with JasperReports), the execution of that scheduled report is meant to update the NEXTRUN date for that same report to run next time.

What seems to occur for reports that take a while to run (say a few minutes), the NEXTRUN date (for tomorrow's run of the report) is re-scheduled at a TIME that seems to be calculated by using the ENDtime of today's run, rather than the STARTtime of today's run. (ie: a few minutes later, because of the time taken to execute it today).

IE: Say you want to run a management report every day at exactly 7:00AM, so that it is ready for a staff meeting after you've read it. But say that report takes 5 minutes to prepare the report (as a PDF) and then another 1 minute to EMAIL it to your staff. What we see happening, is the STARTtime of 7:00AM, plus the execution time till 7:05AM (let's call that the ENDtime), causes the cron.php execution of the ZuckerRunnableReport to calculate TOMORROW's scehduled (start) time as 7:05 tomorrow. (instead of the originally desired 7:00AM everday for the future.) The day after tomorrow, it probably won't even start to run until 7:10AM..... the day after that..... 7:15AM and so forth.... getting later every day.

IMPACT:

So after many weeks of losing that 5 minutes a day, (ignore the 1 extra minute for emailing - that doesn't seem to affect the calculation), then the job eventually starts running too late in the day to be useful for business.

What makes things worse, is that if, in my case, where there are almost 80 other reports running each day, there are many jobs that FOLLOW on immediately after the slow one, then all the other subsequent jobs queue up behind the slow one and they too get re-scheduled later and later every day. Thaty's becuase ALL jobs to be run, are serially processed by cron.

What we've experienced over the course of a couple of months, is that all the jobs eventually queue hard up right behind each other (a bit like a traffic jam on a freeway, caused by the slow car up front, and as a result, ALL scheduledjobs end up with their 'nextrun' time getting corrupted (delayed).

RESEARCH:

The closest files I can see that may be causing this usage of the ENDtime rather than using the original STARTtime, is in a file at:

/var/www/sugarcrm/modules/Schedulers/Scheduler.php

and used with

/var/www/sugarcrm/modules/ZuckerRunnableReport/EditView.html

and controlled by

/.../.../pid.php

and driven by

/var/www/sugarcrm/cron.php

One of our problems, was a complex iREPORT (what we use for developing Jasper reports run as Zucker reports) template with sub-reports and many, many tables being read (some without indexes)..... taking up to 10 minutes to execute. We've since re-designed these jobs to run in only 15 seconds, which has avoided part of the real problem described herein. But still, the above described error will eventually add 15 seconds per day per report to the originally scheduled preferred dates/times that management reports are meant to be emailed to staff.

Any known patches to this, for the version I'm running (see specs below signature)?


MONITORING:

To monitor how reports are made by ZuckerRunnableReports with cron, you can plot use mysql to plot the latest entries with the following command:

#mysql
mysql> connect sugarcrm
mysql> select date_modified item_summary from tracker where
date_modified > "2010-11-02 00:00:00"
and module_name >= "Zucker"
and action="save"
order by date_modified ;

[gazza73]

Still having this problem.

It seems that if many jobs are scheduled for very close to the same time (within say 30 seconds of each other) and such reports take more than say 30 seconds to run, then these jobs collide with each other.

Another side affect of this, is that if CRON is run say every 2 minutes, and if any of the scheduled jobs take LONGER than that same 2 minute interval to prepare and run, then CRON picks the same job(s) AGAIN, and you end up with multiple occurences of the same job being processed. Iin our case, we see 3 jobs running twice, yielding 6 PDF reports being emailed.

So I am curious if slowing down CRON to only test for the presence of a group of scheduled jobs being ready to say every 5 minutes instead of 2 minutes, will only select a tight group ONCE, instead of multiple times. It seems to only affect situations where there are multiple jobs queued for almost the same time, OR jobs that take a period of time to run, that finds such jobs still running when CRON is scheduled to run itself again.

/var/www/sugarcrm/modules/ZuckerRunnableReport/RunnableReport.php contains some code that appears to want to write away the nextrun date/time as the ENDdate of finishing the job.... rather than adding an INTERVAL to the originally desired STARTdate of the job.


function run($update_nextrun_time = false) {
global $timedate;

$parameter_values = unserialize(html_entity_decode($this->settings));

foreach ($parameter_values as $key=>$value) {
$_REQUEST[$key] = $value;
}
$_REQUEST["reportname"] = $this->name;
$_REQUEST["is_scheduler"] = "true";
$_REQUEST["run"] = "true";
ob_start();
include("modules/ZuckerReports/ReportOnDemand.php");
$this->lastlog = ob_get_clean();

if ($update_nextrun_time) {
$this->nextrun = date($timedate->get_date_time_format(), time() + $this->schedule_interval);
}
$this->save();



I'm not sure if this is the right approach, but the suspicious line:
$this->nextrun = date($timedate->get_date_time_format(), time() + $this->schedule_interval);
seems to deal with time() (which is NOW, (after the job has run for a few minutes potentially, RATHER THAN retaining the originally desired STARTtime chosen by the user in the first place.

Any clues on whether this is the area to suggest an enhancement to?

Gaz