What happens at the end of a PHP script?

November 4, 2015 8:18 AM

I have a PHP script that I'm monitoring with New Relic. This doesn't happen often, the average is still 400ms for the page but sometimes the script takes over 60 seconds. But in new relic the delay appears to be happening after all the code has run.

New Relic shows template::render listed at 0.118s. $template->render() is the last line of the script in question.
There are 2 entries below that:
Application code in index.php - with a timestamp of 0.168s - indicating a time of 0.05s for the template rendering
Then a database query that is called by the session write function (we're using database storage for sessions) with a timestamp of 60.59s meaning something is happening between the end of the template rendering (ie the last line of code in the script) and the session being written to, that is taking over 60s!

What could that be? and what can I do about it!

posted by missmagenta to Computers & Internet (10 answers total)

Is the PHP max execution time 60 seconds? Perhaps there is some recursion, inescapable loop, etc.
posted by axismundi at 9:43 AM on November 4, 2015

Are you saying the 60.59s timestamp is before you do any database work, or after?

If it's after, I'd guess you've got a concurrency problem. Since you mention PHP, you're likely using MySQL, and if you're using MyISAM tables you're going to get table-level locks when someone does a write to the table-- perhaps someone's doing a long update/terrible query and it's just totally locking down the table.

If that's the case, identify the long running query, and find out what's wrong with it, or flip over to InnoDB tables, so you at least get row-level locks.
posted by Static Vagabond at 9:53 AM on November 4, 2015

Response by poster: The "code" that is taking 60s (isn't always 60s, I've seen one that was 140s, some that were 4.5s) is AFTER the last line of code in the script. The only thing logged after that is a database query to write to the session. That query takes 0.001 seconds and is to an InnoDB table. The problem also was occurring before we moved to using database sessions .

So the last line of code is logged as finishing at 0.168s
The New Relic logs "Application code (in /index.php)" which finishes at 60.226 seconds.

There is something happening after the last line of code that is taking 60 seconds
posted by missmagenta at 11:43 AM on November 4, 2015

Your database transaction is being commited after the write, then your HTTP connection is being closed, and then whatever New Relic does for each probe. Add logging to New Relic and your PHP script to find out.
posted by gorcha at 12:28 PM on November 4, 2015

Response by poster: How? Whatever is happening is happening after the code has finished executing - what can I log and how?
posted by missmagenta at 12:32 PM on November 4, 2015

Is there a shutdown function registered for the script?

That code would be executed after your script exits.

Another thing that can happen after your code is done is destructors being called.
posted by dweingart at 1:27 PM on November 4, 2015

Response by poster: No shutdown function. We're using a custom session class so we do have custom session functions defined ie:
session_set_save_handler(
array($this, "_open"),
array($this, "_close"),
array($this, "_read"),
array($this, "_write"),
array($this, "_destroy"),
array($this, "_gc")
);
which does run after the code has finished but there's minimal code in there and the delay happens before _write, can't think which others would run before that. No destructors either.... I did wonder if it was due to the number of objects but its happening even on scripts that have very few objects (maybe 5 or 6)
posted by missmagenta at 2:03 PM on November 4, 2015

All "delays in code" happen while code is running. Otherwise, there would be no code to cause the delay. New Relic isn't telling you where exactly the slowdown is occuring, bit it's telling you a lot about where it isn't. You need to dig deeper to isolate it. Ideas:

- Run in a debugger with breakpoints set in various places, observing when they hit.
- Log timestamps liberally and look for big time gaps.
- Check PHP/web server log files for clues.
- Execute the same query in a MySQL client to see if it's the query itself that is slow.
- Remove code by trial-and-error. First, remove the entire session handler. Does that fix it? Good, add back just a little. Still OK? Good, add a little more, etc.
- Go on google and look into all the PHP "magic" functionality that would enable code to run in after-hooks, shutdown functions, whatever.
posted by panem_et_circenses at 4:17 PM on November 4, 2015

I don't know PHP in particular, but maybe it's waiting to let go of some resource that it expects to clean itself up before exiting? A database handle, an input or output pipe (to the client, to a file, who knows), etc
posted by RustyBrooks at 4:27 PM on November 4, 2015

Response by poster: I am 100% certain that the "delay in code" is happening after the last line of code in my script. I know this for a fact as I have logging in place that would alert me if that script took longer than 1 second to to get from the first line to the end of the last line. It has triggered only once (with a time of 1.1s during the period when our backups are running)

As I have already stated, it was happening before we put in the custom session handler and the query itself takes 0.001 seconds (or less)

New relic is already logging timestamps as evidenced by the timestamps stated in my original post.

I know that PHP does stuff after the script has finished, such as destructors, shutdown functions and session write close. What I'm looking for is insight as to what those other things are since we're not using destructors or shutdown functions
posted by missmagenta at 1:12 AM on November 5, 2015