Есть стандартная схема для работы нескольких сайтов
Начальные данные:
- Site1 открывается приемлемое время, Site2 - долго (4-5 сек).
- В браузере задержка открытия проблемного сайта связана с высоким Waiting TTFB
- Site1 и Site2 запущены на одинаковых движках CMS (wordpress),
- Site1 и Site2 уже имеют готовый контент
- Трафик на оба сайта отсутствует
Если провести быстрой поиск, то окажется, что при запросах напрямую на порт 8080 сайт работает также медленно (т.е. исключаем проблему в reverse proxy), плюс в логах nginx (который выступает в роли веб-сервера) можно увидеть следующее:
"time_local": "26/Apr/2018:09:10:19 +0300","host": "site2","status": "200","remote_user": "-","request": "GET / HTTP/1.1","request_time": "4.152","upstream_response_time": "4.152","body_bytes_sent": "53731","upstream_addr": "127.0.0.1:9001","scheme": ,"request_uri": "/","request_filename": "/home/site2/index.php",
Видим, что upstream_response_time порядка 4 сек. Значит проблема примерно или с php-fpm или с бд. Смотрим далее
Пинг с php-fpm сервера до БД:
ping database PING IP_database 56(84) bytes of data. 64 bytes from IP: icmp_seq=1 ttl=54 time=41.4 ms 64 bytes from IP: icmp_seq=2 ttl=54 time=41.4 ms 64 bytes from IP: icmp_seq=3 ttl=54 time=41.2 ms
Да, мягко говоря, время отклика "не очень". Но как правильно аргументировать, что такое время отклика неприемлемо? Веб-разработчики говорят, что site1, который работает с этой же БД, открывается нормально, а при открытии site2 - нет.
На просторах интернета находим скрипт для профилирования кода php (единственное отличие - флаги -tt и -T для получения точных временных меток)
cat strace.sh
#!/bin/bash
additional_strace_args="$1"
MASTER_PID=$(ps auwx | grep php-fpm | grep -v grep | grep 'master process' | cut -d ' ' -f 6)
while read -r pid;
do
if [[ $pid != $MASTER_PID ]]; then
nohup strace -tt -T -p "$pid" $additional_strace_args >"$pid.trc" 2>&1 &
fi
done < <(pgrep php-fpm)
bash strace.php
На сервере создались файлики с именами, равными child pid php-fpm. Обновляем страничку в браузере для проблемного сайта и смотрим содержимое одного из созданных файлов, нас интересует в частности это:
09:10:15.430307 connect(5, {sa_family=AF_INET, sin_port=htons(3306), sin_addr=inet_addr("IP_database")}, 16) = -1 EINPROGRESS (Operation now in progress) <0.000144>
09:10:15.770563 sendto(5, "H\0\0\0\3SELECT option_name, option_"..., 76, MSG_DONTWAIT, NULL, 0) = 76 <0.000104>
09:10:15.814828 recvfrom(5, "\1\0\0\1\2N\0\0\2\3def\16SITE2", 28, MSG_DONTWAIT, NULL, NULL) = 28 <0.000028>
Если правильно понимаю, то 5 - это файловый дескриптор, который имеет данное сетевое соединение. Смотрим первый столбец, последнее число после точки (770563 и 814828 ), измеряется в микросекундах, разница между числами примерно 40мс (40 000 мкс), т.е. между запросом в БД и ответом прошло примерно 40мс
cat 31753.trc | grep "sendto(5" | wc -l 84 - столько запросов в БД было сделано при открытии одной страницы сайта http://SITE2 (кол-во будет плюс-минус меняться в зависимости от страниц) 84*43мс = 3,6c
Запросы в бд все делаются последовательно, друг за другом => пока все запросы не обработаются, страничка не отдастся.
А почему тогда сайт SITE1быстро открывается? если воспользоваться тем же способом, что и выше:
cat 30457.trc | grep "sendto(6" | wc -l 25 - столько запросов в БД было сделано при открытии одной страницы сайта http://SITE1 25*43мс=1075
По данным результатам уже можно аргументировано говорить с чем именно связана проблема и как ее решить.