Slow requests with php-fpm - need more info

[Colnector colnect.com]

Using cherokee + php-fpm and at times I can see entries in the slow
log but it's hard to figure out what the user was actually requesting
when these slow requests happened. The address to the .php file itself
isn't good enough as there's routing going on and it actually always
leads to the same .php file.

Is there a way to add the information of the request itself (URL/
cookie/etc.) to the slow log?

In addition, I always see
+++ dump failed
at the end of each such trace so I'm guessing it's not working well or
am I missing anything?

Thanks

[Przemysław Pawliczuk]

Have you an option to install a profiler into PHP instance?

Profiler logs provide such information.

[Adrian von Stechow]

Figuring out the exact reason of slow php execution is unfortunately
really difficult just from the php-fpm logs. I also often see the
trace fail for my setups, but I mostly use the slow.log to guide me in
my search. Common reasons for slow execution are slow calls to other
sites and database calls, so maybe you can correlate the events with
other logs.
Other than that, the logs you see is the best you'll get outside of
adding a profiler, although I've noticed that the dump fails more
often on request_slowlog_timeout than on request_terminate_timeout.

Good luck

2012/1/8 Przemysław Pawliczuk <p.paw...@gmail.com>:

[Colnector colnect.com]

Thank you all for your replies but I was posting it here as I wanted
to know if php-fpm can actually provide with these small yet important
pieces of information for a slow request:
* The exact URL requested by the user.
* Cookie information.

Yes, a profiler is a great thing but it may slow down the production
environment.
The current log entries give me no usable information to work with.

Thanks

On Jan 8, 9:26 pm, Adrian von Stechow <adr...@stechow.org> wrote:
> Figuring out the exact reason of slow php execution is unfortunately
> really difficult just from the php-fpm logs. I also often see the
> trace fail for my setups, but I mostly use the slow.log to guide me in
> my search. Common reasons for slow execution are slow calls to other
> sites and database calls, so maybe you can correlate the events with
> other logs.
> Other than that, the logs you see is the best you'll get outside of
> adding a profiler, although I've noticed that the dump fails more
> often on request_slowlog_timeout than on request_terminate_timeout.
>
> Good luck
>

> 2012/1/8 Przemysław Pawliczuk <p.pawlic...@gmail.com>:

[Joe]

The best way I am aware of is to customize the log format in your access logs.

If you look in your pool config files, there are examples for doing so.

I haven't found this in online documentation, so look in the default pool configuration file.

e.g. you can log the query string, as well as PHP request timestamp, and PHP request total time taken.

HTH

[Colnector colnect.com]

I haven't found anything in php-fpm.conf
Could u plz direct me to the relevant config file and perhaps give a
simple example?

Thanks

[Jérôme Loyet]

see  http://svn.php.net/viewvc/php/php-src/tags/php_5_3_9/sapi/fpm/php-fpm.conf.in?revision=322020&view=markup

the details of the access log options:

; The access log file
; Default: not set
;access.log = log/$pool.access.log

; The access log format.
; The following syntax is allowed
; %%: the '%' character
; %C: %CPU used by the request
; it can accept the following format:
; - %{user}C for user CPU only
; - %{system}C for system CPU only
; - %{total}C for user + system CPU (default)
; %d: time taken to serve the request
; it can accept the following format:
; - %{seconds}d (default)
; - %{miliseconds}d
; - %{mili}d
; - %{microseconds}d
; - %{micro}d
; %e: an environment variable (same as $_ENV or $_SERVER)
; it must be associated with embraces to specify the name of the env
; variable. Some exemples:
; - server specifics like: %{REQUEST_METHOD}e or %{SERVER_PROTOCOL}e
; - HTTP headers like: %{HTTP_HOST}e or %{HTTP_USER_AGENT}e
; %f: script filename
; %l: content-length of the request (for POST request only)
; %m: request method
; %M: peak of memory allocated by PHP
; it can accept the following format:
; - %{bytes}M (default)
; - %{kilobytes}M
; - %{kilo}M
; - %{megabytes}M
; - %{mega}M
; %n: pool name
; %o: ouput header
; it must be associated with embraces to specify the name of the header:
; - %{Content-Type}o
; - %{X-Powered-By}o
; - %{Transfert-Encoding}o
; - ....
; %p: PID of the child that serviced the request
; %P: PID of the parent of the child that serviced the request
; %q: the query string
; %Q: the '?' character if query string exists
; %r: the request URI (without the query string, see %q and %Q)
; %R: remote IP address
; %s: status (response code)
; %t: server time the request was received
; it can accept a strftime(3) format:
; %d/%b/%Y:%H:%M:%S %z (default)
; %T: time the log has been written (the request has finished)
; it can accept a strftime(3) format:
; %d/%b/%Y:%H:%M:%S %z (default)
; %u: remote user
;
; Default: "%R - %u %t \"%m %r\" %s"
;access.format = %R - %u %t "%m %r%Q%q" %s %f %{mili}d %{kilo}M %C%%

2012/1/12 Colnector colnect.com <webm...@colnect.com>

[Colnector colnect.com]

Thank you for that info. However, it does seem like one can format the
access log and not the slow queries log which has a different format.

As a side note, this part of the .conf file is still missing on gentoo
although I've upgraded to the latest PHP (now 5.3.9)

On Jan 12, 1:20 pm, Jérôme Loyet <m...@fatbsd.com> wrote:
> see http://svn.php.net/viewvc/php/php-src/tags/php_5_3_9/sapi/fpm/php-fpm...

> 2012/1/12 Colnector colnect.com <webmas...@colnect.com>

[Joe]

On Friday, 13 January 2012 10:59:30 UTC+11, Colnector colnect.com wrote:

Thank you for that info. However, it does seem like one can format the
access log and not the slow queries log which has a different format.

Correct, but you can configure it to show you the total execution time. 

You could then use what log parsing method you like to find requests with execution times of a given duration.

Perhaps not ideal, but that is the current state of PHP-FPM.

Since you are using request routing, why not produce your own custom log using your controller PHP file?