Jump to content

4.1.4 Exceeding max execution times


Recommended Posts

I just upgraded my server to PHP 7.1 from 5.4 so was now required to upgrade Revive (I'd tried previously but couldn't do this upgrade due to my PHP version being too low).  So I upgraded from 3.0.2 to 4.1.4.  All seemed to go OK in the upgrade and my ads are appearing.  But now I see that I'm seeing  a few errors daily about exceeding max execution times (my max set at 250 seconds) in www/delivery/alocal.php  The lines where this occurs seems to vary, here are  the messages from yesterday that i see in my PHP error log:

[01-Aug-2018 21:46:06 UTC] PHP Fatal error:  Maximum execution time of 250 seconds exceeded in /home/xyz/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 3911
[01-Aug-2018 21:48:28 UTC] PHP Fatal error:  Maximum execution time of 250 seconds exceeded in /home/xyz/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 4241
[01-Aug-2018 22:13:01 UTC] PHP Fatal error:  Maximum execution time of 250 seconds exceeded in /home/xyz/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 4238
[01-Aug-2018 22:36:46 UTC] PHP Fatal error:  Maximum execution time of 250 seconds exceeded in /home/xyz/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 3911
[01-Aug-2018 22:37:20 UTC] PHP Fatal error:  Maximum execution time of 250 seconds exceeded in /home/xyz/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 4240

Any ideas as to how to fix this or at least debug it?

Link to comment
Share on other sites

2 hours ago, andrewatfornax said:

Take a look in your PHP, webserver and database logs as well, and check your server's performance monitoring information.

Thanks for getting back to me.  There's nothing indicating problems in the PHP, webserver or RevAds debug.log.   My MySQL DB does not have logging turned on and there are no indications of server performance problems at any times. All other DB operations (non-RevAds) are running smoothly.

I get about ~6 of these messages in my PHP logs every day (this is day 3, so not lots of data points here) and the timing  has them about 1/hour for a few hours until the next day.  From the debug.log, these do not happen during maintenance times.  

Note that I have only 10 or so html ads running on the server and our traffic is low volume, and the server pretty beefy for what we're doing.

Any other ideas?

Thanks,Dave

Link to comment
Share on other sites

 

On 8/3/2018 at 6:44 PM, andrewatfornax said:

Two other thoughts:

1. Turn on MySQL logging and/or turn up the logging level in PHP and the web server, so that you can get more information; or

2. Don't worry about it if it's not a big problem ?

Andrew,  Thanks.   I'm reluctant to turn on MySQL logging for fear of slowing down other processes since I'd have to leave it on a full day in order to catch some errors.  But you're right, it doesn't seem to be a big problem tho the multiple busting's of the 4-minute execution time limits are a concern.  

But before I abandon this quest, wondering if you have any thoughts on the  the code that's breaking.  It's getting these errors (according to the PHP error reporting system) in code that is very simple and not something likely to run away.  For example it was reported for today's errors:

[04-Aug-2018 06:00:32 UTC] PHP Fatal error:  Maximum execution time of 250 seconds exceeded in /home/seabelow/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 4240

and also on lines 4239 and 4247, all in the function _adSelectBuildContextArray.  And here's the code around there:

for ($i=0; $i < $cContext; $i++) {
reset($context[$i]);
list ($key, $value) = each($context[$i]); #  This is line 4239
$valueArray = explode(':', $value);  #  This is line 4240
if (count($valueArray) == 1) {
list($value) = $valueArray;
$type = "";
} else {
list($type, $value) = $valueArray;
}
if (empty($value)) { #  This is line 4247
continue;
}

I don't see how that's possible to be stuck executing at those lines. All other such I've looked at are similar innocuous code that should never exceed the time.  Or maybe the reported lines are way off relative to what PHP is reporting???  I've seen a line or 2 diff in what's reported with reality but not many lines different.

Anyhow let me know if you have any ideas on this.  If not,  I'll just live with this puzzling problem.

Thanks,
Dave

Interestingly I tried to lower the max_execution_time to 100 in my .htaccess for the revive directory, so at least it wouldn't hammer my server so badly.  But I'm still getting messages about exceeding 250 seconds.  My .htaccess is just

php_value max_execution_time 100

but it's being ignored.  So is some process spawned by Rev Ads not honoring the .htacess?  Or is there a  way to lower that limit that will work just for the Rev Ads directory?

Thanks,

Dave

Link to comment
Share on other sites

Andrew,

Thanks, I'll look into doing that.

One thing I'd like to do is cut down the max time spent with these queries, but somehow the process is using the max_execution_time set in my home directory as opposed to that I set (via .htaccess) in the RevAds directory.  Unclear to me how this is happening since the process should be spawned in the RevAds directory (I don't have any cron jobs running RevAds processes).  I verified via phpinfo() that the one set in my RevAds directory is much lower.  Anyhow do you know of a way to control that timeout option, so I can at least prevent the server from getting hammered by these queries?

Thanks again,

Dave

Link to comment
Share on other sites

Now things are worse after I changed to running maintenance via a cron job every hour -- instead of getting those 6 or so of those execution time exceeded errors/day, I'm getting 40-50! 

So I killed maintenance running altogether (both internal and cron job), AND stopped all ad-serving (so no ads are appearing on my site), but still I'm getting these errors!?!?!  Seems like NOTHING should be going on with the revAds at all now.

And right now (for some reason???) I just had 5 of these in the last 7 minutes:

[13-Aug-2018 02:58:57 UTC] PHP Fatal error:  Maximum execution time of 150 seconds exceeded in /home/seabelow/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 3978
[13-Aug-2018 03:01:10 UTC] PHP Fatal error:  Maximum execution time of 150 seconds exceeded in /home/seabelow/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 4239
[13-Aug-2018 03:03:23 UTC] PHP Fatal error:  Maximum execution time of 150 seconds exceeded in /home/seabelow/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 3911
[13-Aug-2018 03:03:23 UTC] PHP Fatal error:  Maximum execution time of 150 seconds exceeded in /home/seabelow/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 4238
[13-Aug-2018 03:05:35 UTC] PHP Fatal error:  Maximum execution time of 150 seconds exceeded in /home/seabelow/public_html/revive-adserver-4.1.4/www/delivery/alocal.php on line 4240
 

I've turned slow_query_log on mysql now and restarted it,  but nothing yet.

Suggestions/... welcomed.

Link to comment
Share on other sites

At least some more info -- there are no slow queries causing this, so the problem's in the rev Ads code itself and not MySQL.  I have slow_query_log set on and tho I keep getting these max execution time messages, there are NO slow queries (I set the threshold at 20 secs and these timeouts are occurring passing 150 seconds).   It is totally unclear why these processes are running at all since (1) all ad serving is turned off and my code never accesses Rev Ads & (2) no maintenance operations are running since I turned off automatic maintenance and killed my cron job running it.

One possible "clue" (pretty funky one at that) in this mystery is that now the errors are occurring at ~ one hour intervals and near the time that I previously had maintenance scheduled (i.e. scheduled at 1 min past the hour every hour, with errors now occurring at 3:05, 4:05, 5:06, 6:07, 7:08 ).  So perhaps there's some leftover tasks that were spawned from the old maintenance runs and just waking up.  If anyone who understands what's really going on with maintenance scripts, can give me directions, that'd help.

So 2 main objectives now:

  1. what is causing this and how to fix?
  2. if #1 can't be resolved, how to limit the execution time?  I set a lower time limit in the rev ads directory's htaccess (and verified with phpinfo that that is the true max), but the script uses my root folder's limit of 150 seconds.

For #2, perhaps I put some ini_set's in the code to limit the time in some of the functions in alocal.php, but I don't know where they should go.  Any ideas?

 

 

Link to comment
Share on other sites

I went back to a more normal set up with automatic maintenance on and my ads being served.  I'm still getting 30-40 such errors/day (4 days after redoing the set up)  I'd at least like to find a way to stop those -- I can sacrifice statistics if that'll help.  

Other than killing my present installation, and then recreating all clients, campaigns, banners, and channels -- if anyone knows a way to get past this, please speak up.  I do need to get rid of these cpu hogs.  Thanks.

Link to comment
Share on other sites

Does anyone have any ideas on how to overcome this?  I'm now getting more of these timeouts happening (68 such yesterday).  And that's eating my server time (68 * 150 secs CPU).  Again note I'm willing to sacrifice statistics on all ads -- our customers never look at them anyhow.

Link to comment
Share on other sites

1 hour ago, andrewatfornax said:

Have you migrated to InnoDB? Or are you still using MyISAM?

Thanks.  I didn't change to InnoDB since slow-query logging showed no slow queries happening, so I don't think it's a DB issue (could be wrong).  If you still think that's likely the problem, I'll change that for the Rev Ads DB -- just afraid of causing other problems (I'll make a backup first). 

Before I make such a change is there anything I should do with RevAds to "stop" it so as to prevent problems during the change over, e.g. stop serving ads, or ???

 

Link to comment
Share on other sites

It's been a while since I used MyISAM, but I suspect the issue is not slow queries - once the queries get access to the table, they should run quickly enough. The issue will be that while any once process is writing to a table, all other access to the table will be locked at that time.

That could be why you get threads timing out - they just don't get a chance to access the table for their query, as others have the table locked the whole time, and eventually, the thread is timed out.

MyISAM might have a reporting option on locking or queuing that may be more relevant than slow queries - take a look there perhaps before committing to InnoDB?

I would definitely stop your web server and halt all database activity during the backup and migration process!

Link to comment
Share on other sites

OK, I'll change to InnoDB.  Since this RevAds upgrade was simultaneous with moving to PHP 7 and MySQLi (vs MySQL), that might account for the difference (this has never happened before).  So maybe MySQLi calls are i

One concern is that even when I turn off all DB maintenance in RevAds and stop serving ads, I still get Rev Ad code timing out for many hours afterwards -- my PHP error log file shows them occurring.   Either there's a big queue or some processes have been spawned (I don't see them) tho.  Perhaps shutting down Apache will stop these (???).

So I'm not sure how to stop everything to make the change, or I just plow thru it after stopping the server. Any ideas/suggestions?

Link to comment
Share on other sites

OK, I found the problem -- one way out in left-field: the new RevAds no longer returns the same indication from my PHP call, that there are no more ads meeting my criteria. So an obscure page of mine wound up in an infinite loop! I found a new way now to detect a "no more ads" condition (not the same as previous RevAds) and changed the criteria, so that all works OK now.  So no more timeouts in Rev Ads are occurring.

I retrieve ad information via a PHP call to a RevAds fucntion, and all my ads are "local" ads.  This gives me the html needed. which I display.  This code came from many years ago when I first started using OpenX, as it was called then. There's a very brief mention of this I found now on https://documentation.revive-adserver.com/display/DOCS/Tag+Variables
But I didn't find any more documentation on this now, and don't have access to the old OpenX one.  If you know, please tell me where there's more documentation on this available now. 

Anyhow my basic invocation to retrieve ad data has a call to the view_local function defined in alocal.php:

$ad[$i] = view_local('', $zoneNum, 0, 0, '', '', '0', $phpAds_context, '');

And I do this in a loop, bumping $phpAds_context each time I find a valid ad.  Previously in RevAds (last version prior to 4.1.4 I used was 3.0.2) the 'html' array element of this would return an empty value if no more ads met the criteria, and I'd break out of the loop.  My fix now is to check that this element has some sensible value (e.g. there's an 'href=' in it).  It'd be nice to have something more definitive -- let me know if you know of such.

Anyhow all seems to be working OK now.  I'll report back later if something's still amiss.  Thanks again Andrew for all your efforts here, and my apologies for not finding this sooner.   I hope this saves someone else's time.

 

 

Link to comment
Share on other sites

Join the conversation

You can post now and register later. If you have an account, sign in now to post with your account.
Note: Your post will require moderator approval before it will be visible.

Guest
Reply to this topic...

×   Pasted as rich text.   Paste as plain text instead

  Only 75 emoji are allowed.

×   Your link has been automatically embedded.   Display as a link instead

×   Your previous content has been restored.   Clear editor

×   You cannot paste images directly. Upload or insert images from URL.



×
×
  • Create New...