PHP profiling delay before shutdown function

Question

// VERY BEGIN OF SCRIPT
$_SERVER['HX_startTime'] = microtime(true);

...

// MY SHUTDOWN FUNCTION
register_shutdown_function('HX_shutdownFn');
function HX_shutdownFn()
{
    // formatTimeSpan is simple time to string conversion function
    var_dump(formatTimeSpan(microtime(true) - $_SERVER['HX_startTime']));
}


...

// VERY END OF SCRIPT
var_dump(formatTimeSpan(microtime(true) - $_SERVER['HX_startTime']));

I've got 0.0005s. at end of script and 1.1s. at shutdown function. Is it normal? Where 1 second is lost?

Script is pure php, does not use db connection, etc. Testing on WAMP server (php v 5.3.9, apache 2.2.21)

What happens if you explicitly call `exit()` at the very end of the script (after last `var_dump`)? — Mike Brant, Feb 23 '13 at 00:54
where your sessions are saved? maybe on DB? you overwrite the session handler? — Oden, Feb 23 '13 at 01:23
Are you sure you didn't register more shutdown functions? Do a search in your project for `register_shutdown_function()`. I have also tested with your code and get figures of 0.0003 and 0.0004, So you must have something doing more work on shutdown. — Bram Gerritsen, Feb 23 '13 at 23:56
You should use some more advanced benchmark script/class, which is able to measure the time for different blocks of your script(s)/project. — djot, Feb 24 '13 at 16:49
Run the script from CLI so you can eliminate any apache options/addons that may interfere with the execution ..no other idea ..maybe an application logger or header display/read like firephp ? — BG Adrian, Feb 28 '13 at 16:36
Please have a look at Xhproff for more advanced debugging. http://techportal.inviqa.com/2009/12/01/profiling-with-xhprof/ — GreenRover, Mar 03 '13 at 07:13

score 1 · Answer 1 · answered Aug 01 '13 at 13:46

A shutdown function will run out of the normal stack after some connection would be closed and cleanup is done. A delay will always occur as its kind of nature of this function, depending what you have done before or try to do in this function.

The manual does not tell but it is a DEBUGGING function and should also be treated so.

On normal operation you should never use it. There is no advantage. You may call your shutdown function on end of the script manually and leave a handler for unexpected shutdowns.

score 1 · Answer 2 · answered Aug 07 '13 at 19:57

As others have mentioned, there may be other shutdown functions. Additionally, there are the destructors of objects that are called when they go out of scope (if in the global scope).

You can see all of this in glorious detail with the XDebug module (http://xdebug.org/), particularly when using the trace files. Once you have XDebug installed and configured, you can append ?XDEBUG_TRACE=1 to your url and see a full call stack for the entire execution of your page, including timing information for each line.

With appropriate options, you can also see allocations, names and values of parameters, returned values, and assignments. It's a very powerful and useful tool.

These are the settings I use for XDebug:

xdebug.default_enable=1
xdebug.profiler_enable=0
xdebug.profiler_enable_trigger=1
xdebug.profiler_append=On
xdebug.auto_trace=Off
xdebug.show_mem_delta=On
xdebug.collect_return=On
xdebug.collect_params=4
xdebug.profiler_output_dir = /tmp
xdebug.profiler_output_name = profile.%H.%t.%p
xdebug.var_display_max_children = 999
xdebug.var_display_max_data = 99999
xdebug.var_display_max_depth = 100
xdebug.remote_enable=1
xdebug.cli_color=1
xdebug.show_local_vars=1    
xdebug.show_mem_delta=1
xdebug.collect_return=1
xdebug.collect_assignments=1
xdebug.collect_params=4
xdebug.collect_includes=1
xdebug.trace_enable_trigger=1
xdebug.trace_output_dir=/tmp
xdebug.trace_output_name=trace.%t.%R.%p

score 0 · Answer 3 · answered Mar 04 '13 at 11:39

I'm assuming there's more code to this than you posted - in that case if you're transferring any output to the client, the script won't shutdown until it's been sent.

There may also be additional shutdown functions registered which you might be unaware of as mentioned by the comments.

If all else fails, try isolating this script (so ONLY the lines you posted, even without whatever substitutes the ...) and compare running it from command line and your web server. There might be some server-specific overhead involved.

PHP profiling delay before shutdown function

3 Answers3

Linked