phpxdebugxdebug-profilerfpm

php-fpm access log request time and xdebug timings doesn't match

php-fpm access log request time and xdebug timings doesn't match.

Why does xdebug profiling shows 100ms for request and php-fpm access log showing 700ms+ 7x or even more difference?

Is xdebug missing/skipping something on the way or does fpm is doing something between actual php processing?

Xdebug logging autoload/includes/require timings as well? Database connections etc?

Is there a way to look deeper into the timings that php-fpm is logging into access.log?

Solution

  • I would suspect that php-fpm logs the time required to setup/teardown the actual php file loadup and cleanout at the end of processing. Xdebug can only become 'self aware' after the call setup, and fawns out when php-fpm starts to cleanup after the php execution completes. I think. I observe the same without php-fpm (from the extended apache logs).

    from apache : 

     192.168.1.54 - - [19/Aug/2016:10:35:17 -0400] "POST /idm/feed/do.php HTTP/1.1" 200 2186 0/128868 I:252 O:2434

    from the php process :

    2016-08-19T10:35:17-04:00 -api.idm.feed.Servlet          DEBUG /idm/feed[detail] processed in 12.8 ms. , 3 MB

    same call ! Apache 128 ms, php 12.8 ms.

    If you are using apache, load the extra modules and use this log format to have the end-to-end time and IO as above :

    load :

    LoadModule log_config_module libexec/mod_log_config.so

    log format : 

    LogFormat "%h %l %u %t \"%r\" %>s %b %T/%D I:%I O:%O"  common