docker yiisoftware/yii2-php и непонятные задержки в register_shutdown_function

Обсуждаем разработку фреймворка: дизайн компонентов, API, пакеты
Ответить
mj4444
Сообщения: 41
Зарегистрирован: 2015.06.08, 19:56

docker yiisoftware/yii2-php и непонятные задержки в register_shutdown_function

Сообщение mj4444 » 2019.12.04, 04:50

Запускаю окружение докера yiisoftware/yii2-php:7.3-apache

Началось с всё с теста сравнения быстродействия yii3 с другими фреймворками.

Я обнаружил непонятные задержки с ответом и в следствии этого появился такой простой тест (на самом деле аналогичная конструкция используется в логере yii3).

Код: Выделить всё

<?php

$time_start = microtime(true);

// Code

$time_end = microtime(true);

\register_shutdown_function(function () {
    $time_finish = microtime(true);
    $time1 = round($GLOBALS['time_start'] - $_SERVER["REQUEST_TIME_FLOAT"], 3) * 1000;
    $time2 = round($GLOBALS['time_end'] - $GLOBALS['time_start'], 3) * 1000;
    $time3 = round($time_finish - $GLOBALS['time_end'], 3) * 1000;
    $time = round($time_finish - $_SERVER["REQUEST_TIME_FLOAT"], 3) * 1000;
    $timer = round($time_finish - $GLOBALS['time_start'], 3) * 1000;
    echo "\n$timer = $time2 + $time3";
    \register_shutdown_function(function () {
        $time_finish = microtime(true);
        $time1 = round($GLOBALS['time_start'] - $_SERVER["REQUEST_TIME_FLOAT"], 3) * 1000;
        $time2 = round($GLOBALS['time_end'] - $GLOBALS['time_start'], 3) * 1000;
        $time3 = round($time_finish - $GLOBALS['time_end'], 3) * 1000;
        $time = round($time_finish - $_SERVER["REQUEST_TIME_FLOAT"], 3) * 1000;
        $timer = round($time_finish - $GLOBALS['time_start'], 3) * 1000;
        echo "\n$timer = $time2 + $time3";
    });
});
Я получил в среднем вот такой результат:

Код: Выделить всё

16 = 0 + 16
30 = 0 + 30
Тут мы видим что затраты на 1 вызов register_shutdown_function в среднем порядка 15мс.
Я некоторое время поковырялся и случайно заметил следующее:
Если добавить в конец скрипта вызов функции "exit();", то мы получаем результат:

Код: Выделить всё

0 = 0 + 0
0 = 0 + 0
Очень странно и это всё не на какой то там непонятной конфигурации, а на образе докера yiisoftware (у меня Ubuntu 18.4).

Добавил exit в конец index.php у приложения "github.com/yiisoft/yii-demo". Время генерации страницы сократилось со 100 до 50 мс (значения средние).

Добавил exit в конец index.php у приложения "github.com/yiisoft/yii2-app-basic". Время генерации страницы сократилось с 90 до 40 мс (значения средние).

Кстати тест показал что yii2-app-basic на 20% быстрее yii-demo (оба в prod режиме без каких либо модификаций) и это не радует.

Собственно предложение: добавить на всякий случай в конец index.php строчку

mj4444
Сообщения: 41
Зарегистрирован: 2015.06.08, 19:56

Re: docker yiisoftware/yii2-php и непонятные задержки в register_shutdown_function

Сообщение mj4444 » 2019.12.09, 22:19

На докер образе php:7.4-apache Yii2 (2.0.30) такая же картина.

Стандартный index.php

21 = 2 + 19
38 = 2 + 36
(общее время = время работы основного кода + время затраченное на shutdown функции)

Если добавить exit();

2 = 2 + 0
2 = 2 + 0
(общее время = время работы основного кода + время затраченное на shutdown функции)

На сервере apache + php-fpm такого эффекта не наблюдается...

Аватара пользователя
samdark
Администратор
Сообщения: 9201
Зарегистрирован: 2009.04.02, 13:46
Откуда: Воронеж
Контактная информация:

Re: docker yiisoftware/yii2-php и непонятные задержки в register_shutdown_function

Сообщение samdark » 2019.12.09, 23:37

Интересно. А можно как-то поподробнее попрофайлить, что именно тормозит?

mj4444
Сообщения: 41
Зарегистрирован: 2015.06.08, 19:56

Re: docker yiisoftware/yii2-php и непонятные задержки в register_shutdown_function

Сообщение mj4444 » 2019.12.10, 01:29

При вызове register_shutdown_function стабильно есть задержка и внутри выполняемого там кода, остальное не понятно где.

Минимальный код:

Код: Выделить всё

<?php
register_shutdown_function(function () {
    echo round(microtime(true) - $GLOBALS['time_start'], 3) * 1000 . "\n";
    register_shutdown_function(function () {
        echo round(microtime(true) - $GLOBALS['time_start'], 3) * 1000 . "\n";
    });
});
$time_start = microtime(true);
PHP 7.3 (без exit) yiisoftware/yii2-php:7.3-apache
6 12
PHP 7.4 (без exit) php:7.4-apache
3 6
PHP 7.3 & 7.4 (с exit)
0 0
Понятное дело что на хостингах обычно fpm версия работает и по быстрому слепленное приложение будет тормозить значительно больше чем задержки от этого бага, но у меня например приложение отдаёт за 2мс контент, а задержка от этой штуки ещё 30мс... Трудно не заметить разницы...

Вообще что то припоминаю что php когда работает как модуль при вызове register_shutdown_function можем менять каталог и обращаться зачем то обратно к апачу. Возможно он этого не делает при вызове метода exit(); (просто предположение как возможный вариант).

Ответить