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)

Answer 1

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.

Answer 2

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