php.net |  support |  documentation |  report a bug |  advanced search |  search howto |  statistics |  random bug |  login
Request #53434 More details for slow requests
Submitted: 2010-12-01 15:38 UTC Modified: 2011-01-29 12:48 UTC
Votes:4
Avg. Score:4.0 ± 1.0
Reproduced:3 of 3 (100.0%)
Same Version:2 (66.7%)
Same OS:2 (66.7%)
From: webmaster_apc at colnect dot com Assigned: fat
Status: Closed Package: FPM related
PHP Version: 5.3.1RC1 OS: gentoo linux
Private report: No CVE-ID:
 [2010-12-01 15:38 UTC] webmaster_apc at colnect dot com
Description:
------------
Seeing the following messages in php-fpm log file:

[WARNING] [pool www] child 21540, script '/var/www/web/file.php' executing too slow

it's hard to tell which request actually created the slow response as I'm actually using a framework with routing logic. I would like to see an option to include more details such as the entire request URI and possibly some headers (cookies/user-agent/etc.)


Thanks


Patches

use_full_request_uri_for_slowlog.diff (last revision 2013-01-15 07:00 UTC) by joey dot cai at gmail dot com)

Add a Patch

Pull Requests

Add a Pull Request

History

AllCommentsChangesGit/SVN commitsRelated reports
 [2010-12-01 15:47 UTC] fat@php.net
-Status: Open +Status: Feedback
 [2010-12-01 15:47 UTC] fat@php.net
Not enough information was provided for us to be able
to handle this bug. Please re-read the instructions at
http://bugs.php.net/how-to-report.php

If you can provide more information, feel free to add it
to this bug and change the status back to "Open".

Thank you for your interest in PHP.


which system are you using ?

can you give us the ./configure ... --enable-fpm output ?

It already exists in FPM, maybe your system doesn't have what it needs
(ptrace and stuff)
 [2010-12-01 15:49 UTC] webmaster_apc at colnect dot com
-Status: Feedback +Status: Open
 [2010-12-01 15:49 UTC] webmaster_apc at colnect dot com
This isn't a bug but a feature request hence I believe the details are irrelevant. Thanks
 [2010-12-01 15:51 UTC] webmaster_apc at colnect dot com
Sorry, I didn't read through. You wrote it already exists. Could you please refer me to the relevant documentation? Thanks.
 [2010-12-01 15:53 UTC] fat@php.net
-Status: Open +Status: Feedback
 [2010-12-01 15:53 UTC] fat@php.net
FPM uses ptrace or equivalent to do this.

If it does not work, maybe there a problem at configure. That's why I asked you 
the ./configure output to see if ptrace is detected.
 [2010-12-01 16:02 UTC] webmaster_apc at colnect dot com
-Status: Feedback +Status: Open
 [2010-12-01 16:02 UTC] webmaster_apc at colnect dot com
I'm using Gentoo with PHP5.3.3R1 installed. It include php-fpm 0.6.5

These are the flags for the Gentoo install script

     Installed versions:  5.3.3-r3(5.3)(13:28:35 11/28/10)(berkdb bzip2 cli crypt ctype curl fileinfo filter fpm gd gdbm hash iconv json mysql mysqli mysqlnd nls pcntl pdo phar posix readline session sharedmem simplexml ssl tidy tokenizer truetype unicode xml zlib -adabas -apache2 -bcmath -birdstep -calendar -cdb -cgi -cjk -curlwrappers -db2 -dbmaker -debug -doc -embed -empress -empress-bcs -enchant -esoob -exif -firebird -flatfile -frontbase -ftp -gd-external -gmp -imap -inifile -interbase -intl -iodbc -ipv6 -kerberos -kolab -ldap -ldap-sasl -libedit -mssql -oci8 -oci8-instant-client -odbc -pic -postgres -qdbm -recode -sapdb -sharedext -snmp -soap -sockets -solid -spell -sqlite -sqlite3 -suhosin -sybase-ct -sysvipc -threads -wddx -xmlreader -xmlrpc -xmlwriter -xpm -xsl -zip)



phpinfo() produces the following:


'./configure' '--prefix=/usr' '--build=x86_64-pc-linux-gnu' '--host=x86_64-pc-linux-gnu' '--mandir=/usr/share/man' '--infodir=/usr/share/info' '--datadir=/usr/share' '--sysconfdir=/etc' '--localstatedir=/var/lib' '--prefix=/usr/lib64/php5.3' '--mandir=/usr/lib64/php5.3/man' '--infodir=/usr/lib64/php5.3/info' '--libdir=/usr/lib64/php5.3/lib' '--with-libdir=lib64' '--without-pear' '--disable-maintainer-zts' '--disable-bcmath' '--with-bz2' '--disable-calendar' '--with-curl' '--without-curlwrappers' '--without-enchant' '--disable-exif' '--disable-ftp' '--with-gettext' '--without-gmp' '--disable-intl' '--disable-ipv6' '--without-kerberos' '--enable-mbstring' '--with-mcrypt' '--without-mssql' '--with-onig=/usr' '--with-openssl' '--with-openssl-dir=/usr' '--enable-pcntl' '--without-pgsql' '--without-pspell' '--without-recode' '--enable-shmop' '--without-snmp' '--disable-soap' '--disable-sockets' '--without-sqlite3' '--without-sybase-ct' '--disable-sysvmsg' '--disable-sysvsem' '--disable-sysvshm' '--with-tidy' '--disable-wddx' '--disable-xmlreader' '--disable-xmlwriter' '--without-xmlrpc' '--without-xsl' '--disable-zip' '--with-zlib' '--disable-debug' '--enable-dba' '--without-cdb' '--with-db4' '--disable-flatfile' '--with-gdbm' '--disable-inifile' '--without-qdbm' '--with-freetype-dir=/usr' '--with-t1lib=/usr' '--disable-gd-jis-conv' '--with-jpeg-dir=/usr' '--with-png-dir=/usr' '--without-xpm-dir' '--with-gd' '--without-interbase' '--with-mysql=mysqlnd' '--with-mysql-sock=/var/run/mysqld/mysqld.sock' '--with-mysqli=mysqlnd' '--without-oci8' '--without-pdo-dblib' '--with-pdo-mysql=mysqlnd' '--without-pdo-pgsql' '--without-pdo-sqlite' '--without-pdo-odbc' '--with-readline' '--without-libedit' '--with-mm' '--without-sqlite' '--with-libevent-dir=/usr/lib64' '--with-pcre-regex=/usr' '--with-pcre-dir=/usr' '--with-config-file-path=/etc/php/fpm-php5.3' '--with-config-file-scan-dir=/etc/php/fpm-php5.3/ext-active' '--disable-cli' '--disable-cgi' '--enable-fpm' '--disable-embed' '--without-apxs2' 

Thanks
 [2010-12-02 09:21 UTC] fat@php.net
-Status: Open +Status: Feedback
 [2010-12-02 09:21 UTC] fat@php.net
I need the output of the ./configure, not its arguments.
 [2010-12-02 09:21 UTC] fat@php.net
-Assigned To: +Assigned To: fat
 [2010-12-06 00:39 UTC] webmaster_apc at colnect dot com
-Status: Feedback +Status: Assigned
 [2010-12-06 00:39 UTC] webmaster_apc at colnect dot com
When I try to include the entire output here I get a "Please do not SPAM our bug system." message and I see no place to add an attachment (should I add it as a patch?!).

ptrace is found and responding well
 [2010-12-06 09:06 UTC] fat@php.net
-Status: Assigned +Status: Feedback
 [2010-12-06 09:06 UTC] fat@php.net
What do you have in the file specified by the directive 'slowlog' ?

can you please give your configuration ?
 [2010-12-06 09:21 UTC] webmaster_apc at colnect dot com
-Status: Feedback +Status: Assigned
 [2010-12-06 09:21 UTC] webmaster_apc at colnect dot com
I have more messages in the slow log indicated the script which was running at the time but NOT the HTTP request send. For example:

[0x00007f38694a0b78] flush() /var/xxx/lib/misc/scriptControl.class.php:15
[0x00007f38694a03c8] set_time_limit() /var/xxx/apps/modules/repairs/actions/actions.class.php:68
[0x00007f386949fd00] executeRecreateThumbnails() /var/xxx/cache/prod/config/config_core_compile.yml.php:490
[0x00007f386949fa30] execute() /var/xxx/cache/prod/config/config_core_compile.yml.php:990
[0x00007f386949f6d8] executeAction() /var/xxx/cache/prod/config/config_core_compile.yml.php:985
[0x00007f386949ef80] handleAction() /var/xxx/cache/prod/config/config_core_compile.yml.php:971
[0x00007f386949ea68] execute() /var/xxx/cache/prod/config/config_core_compile.yml.php:1066
[0x00007f386949e400] execute() /var/xxx/lib/vendor/symfony/lib/filter/sfCommonFilter.class.php:29
[0x00007f386949dee8] execute() /var/xxx/cache/prod/config/config_core_compile.yml.php:1066
[0x00007f386949db98] execute() /var/xxx/apps/lib/extraSecurityFilter.class.php:31
[0x00007f386949d680] execute() /var/xxx/cache/prod/config/config_core_compile.yml.php:1066
[0x00007f386949d3e0] execute() /var/xxx/cache/prod/config/config_core_compile.yml.php:1033


I don't know how to include my configuration. The output of ./configure is too long to be pasted here.
 [2010-12-06 09:25 UTC] webmaster_apc at colnect dot com
This may help. In the normal log I get:

Dec 06 08:03:36.147792 [WARNING] [pool www] child 23560, script '/var/xxx/web/index.php' executing too slow (30.069499 sec), logging
Dec 06 08:03:36.147904 [NOTICE] child 23560 stopped for tracing
Dec 06 08:03:36.147911 [NOTICE] about to trace 23560
Dec 06 08:03:36.148064 [ERROR] ptrace(PEEKDATA) failed: Input/output error (5)
Dec 06 08:03:36.148127 [NOTICE] finished trace of 23560
 [2010-12-06 09:26 UTC] fat@php.net
-Status: Assigned +Status: Analyzed
 [2010-12-06 09:26 UTC] fat@php.net
Oh hell yes ... I did not understand your need.

I'll see how complicated this is to add the request which triggers the slowlog 
entries.
 [2011-01-29 12:38 UTC] fat@php.net
Automatic comment from SVN on behalf of fat
Revision: http://svn.php.net/viewvc/?view=revision&revision=307842
Log: - Fixed bug #53434 (php-fpm slowlog now also logs the original request).
 [2011-01-29 12:41 UTC] fat@php.net
Automatic comment from SVN on behalf of fat
Revision: http://svn.php.net/viewvc/?view=revision&revision=307843
Log: - Fixed bug #53434 (php-fpm slowlog now also logs the original request).
- Fixed the missing peace of code on revision 307842
 [2011-01-29 12:43 UTC] fat@php.net
-Status: Analyzed +Status: Closed
 [2011-01-29 12:43 UTC] fat@php.net
This bug has been fixed in SVN.

Snapshots of the sources are packaged every three hours; this change
will be in the next snapshot. You can grab the snapshot at
http://snaps.php.net/.
 
Thank you for the report, and for helping us make PHP better.

I've added the request method and the request uri in the slowlog timeout and 
slowlog terminated log message:


[29-Jan-2011 12:41:59.741208] WARNING: pid 32110, fpm_request_check_timed_out(), 
line 147: [pool www_chroot] child 32111, script '/html/test8.php' (request: "GET 
/chroot/test8.php") executing too slow (1.051049 sec), logging


[29-Jan-2011 12:42:00.783410] WARNING: pid 32110, fpm_request_check_timed_out(), 
line 157: [pool www_chroot] child 32111, script '/html/test8.php' (request: "GET 
/chroot/test8.php") execution timed out (2.092626 sec), terminating
 [2011-01-29 12:48 UTC] webmaster_apc at colnect dot com
Thanks for the fix :) I'll be happy to see it when the next PHP version is released on Gentoo. Cheers
 [2013-01-15 06:58 UTC] joey dot cai at gmail dot com
The current slow log records in php-fpm.log log SCRIPT_NAME as the request uri. For webapps built on top of mvc framework such as symfony or zend framework with a front controller and routing enabled (or requests with query strings), this information is not sufficient enough to track down the source of the slow requests easily. A patch will be attached which logs HTTP_HOST and REQUEST_URI of slow requests in php-fpm.log. It might not be the cleanest solution since I'm not a C programmer. But the patch does solve our problem. Please take it look at it. thank you.
 [2013-01-15 07:02 UTC] joey dot cai at gmail dot com
I forgot to mention that the diff was generated against php-5.3.20.
 
PHP Copyright © 2001-2014 The PHP Group
All rights reserved.
Last updated: Sat Apr 19 22:02:16 2014 UTC