помогите локализовать тормоза в fast_cgi_finish_request

[Dovg]

Добрый день!

в php-fpm slow log падает вот такое:

[05-Jun-2012 17:48:06] [pool plus1] pid 15295
script_filename = /var/www/plus1.wapstart.ru/plus1/src/rotator/index.php
[0x0000000001f162e0] fastcgi_finish_request() /var/www/plus1.wapstart.ru/plus1/src/classes/Utils/RotatorFrontController.class.php:202
[0x0000000001f15c40] finishRequest() /var/www/plus1.wapstart.ru/plus1/src/classes/Utils/RotatorFrontController.class.php:112
[0x0000000001f159d8] doPostAction() /var/www/libs/oemlib-dev/Utils/FrontController.class.php:32
[0x0000000001f15678] handleRequest() /var/www/plus1.wapstart.ru/plus1/src/classes/Utils/RotatorFrontController.class.php:34
[0x0000000001f14828] handleRequest() /var/www/plus1.wapstart.ru/plus1/src/rotator/index.php:37

[05-Jun-2012 17:48:06] [pool plus1] pid 15391
script_filename = /var/www/plus1.wapstart.ru/plus1/src/rotator/index.php
[0x0000000001e4b6d0] fastcgi_finish_request() /var/www/plus1.wapstart.ru/plus1/src/classes/Utils/RotatorFrontController.class.php:202
[0x0000000001e4b030] finishRequest() /var/www/plus1.wapstart.ru/plus1/src/classes/Utils/RotatorFrontController.class.php:112
[0x0000000001e4adc8] doPostAction() /var/www/libs/oemlib-dev/Utils/FrontController.class.php:32
[0x0000000001e4aa68] handleRequest() /var/www/plus1.wapstart.ru/plus1/src/classes/Utils/RotatorFrontController.class.php:34
[0x0000000001e49c18] handleRequest() /var/www/plus1.wapstart.ru/plus1/src/rotator/index.php:37

Причем таких достаточно много:

WARNING-PRODUCTION! dovg@atlas:~$ sudo cat /var/log/php-fpm.log.slow | grep fastcgi_finish_request | wc -l
312

Иногда срабатывает и в других местах, но там вполне объяснимо всё архитектурой скрипта.

Я понимаю, что факт срабатывания не означает, что тормозит именно finish_request, но если бы все-таки число "попаданий" настараживает.
Может ли в самой finish_request что-нибудь блокироваться?

Конфигурация:
nginx (freebsd) -> php-fpm (debian).
php из коробки дебиана.

Конфиг fpm

[plus1]

listen = 0.0.0.0:9801

user = nobody
group = nogroup

pm = dynamic
pm.max_children = 64
pm.start_servers = 20
pm.min_spare_servers = 10
pm.max_spare_servers = 20
pm.max_requests = 1000
pm.status_path = /status
ping.path = /ping

 
request_terminate_timeout = 0
request_slowlog_timeout = 1
slowlog = /var/log/php-fpm.log.slow
rlimit_files = 1024
rlimit_core = 0
catch_workers_output = yes
 
env[HOSTNAME] = $HOSTNAME
env[PATH] = /usr/bin:/bin
env[TMP] = /tmp
env[TMPDIR] = /tmp
env[TEMP] = /tmp

php_admin_value[sendmail_path] = /usr/sbin/sendmail -t -i -f [email protected]
php_flag[display_errors] = off
php_admin_value[error_log] = /var/log/fpm-php.log
php_admin_flag[log_errors] = on
php_admin_value[memory_limit] = 128M
php_admin_value[max_execution_time] = 10
php_admin_value[max_input_time] = 60

Подскажите плз куда копать?

 

[fixxxer]

PHP_FUNCTION(fastcgi_finish_request) /* {{{ */
{           
    fcgi_request *request = (fcgi_request*) SG(server_context);
    
    if (request->fd >= 0) {

        php_output_end_all(TSRMLS_C);
        php_header(TSRMLS_C);

        fcgi_flush(request, 1);
        fcgi_close(request, 0, 0);
        RETURN_TRUE;
    }

    RETURN_FALSE;

}
/* }}} */

могу разве что предположить, что включен ob, отдается дофига, и при этом тормозит сеть между nginx и fpm

а расставь таймеры вокруг finish_request

 

[Dovg]

могу разве что предположить, что включен ob, отдается дофига, и при этом тормозит сеть между nginx и fpm

Отдается очень мало, буквально пара килобайт. ob не было. Завтра еще со стороны фронтов померяю, может там что-то найду.

а расставь таймеры вокруг finish_request

Ага, завтра обвешу.

 

[Dovg]

У нас тут на фронтах некоторые проблемы. Как локализуем - отпишусь.

 

[Dovg]

Update - обвесил таймерами, "тормозил" действительно fast_cgi_finish_request. У нас были проблемы с производительность на фронтах. После их исправления все стало хорошо.