После обновления ПО на сервере стал тормозить сайт

Question

[Артем]

Имеется сервер. FreeBSD 8.0, Apache 2.2.23, PHP 5.4.10, MySQL 5.1.67. Понадобилось обновить на нем PHP (до этого был Apache 1.3 с PHP 5.2.4). Стоило обновить Apache и PHP, как страницы сайта стали грузиться по 2-5 секунд. Обновил поосновательнее, со всевозможными зависимостями, оптимизировал/проверил таблицы в MySQL. Тормозит при работе с MySQL (внутри самого ходового скрипта замерял время выполнения разлиных запросов). Притом, тормознутые запросы все время меняются местами в этом скрипте: то один медленно выполнился, то другой, то третий. Уже пробовал выискивать и оптимизировать медленные запросы в логах MySQL, изменять настройки MySQL и Apache. Поставил Nginx вперед. Не помогло…

Хотя в процессах MySQL есть смущающие вещи. Например много запросов со статусом Sleep и NULL вместо имени таблицы, а также много запросов со статусом Locked на одну из самых используемых таблиц проекта. Но запросы в эту таблицы идут нормальные, по первичному ключу преимущественно. Отдельно PHP-скрипты без MySQL, а тем более и статические страницы грузятся быстро. Я понимаю, что все указывает на проблему либо конфигурации MySQL, либо кривых запросов, но ведь до обновления PHP и Apache все было в порядке.

Что можно сделать? Помогите, пожалуйста.

На всякий случай, top

last pid: 45111; load averages: 26.49, 25.19, 23.14 up 1+02:58:21 19:34:52
224 processes: 24 running, 199 sleeping, 1 zombie
CPU: 91.3% user, 0.0% nice, 4.8% system, 0.5% interrupt, 3.4% idle
Mem: 1740M Active, 3971M Inact, 1154M Wired, 125M Cache, 827M Buf, 907M Free
Swap: 4096M Total, 4096M Free

PID USERNAME THR PRI NICE SIZE RES STATE C TIME WCPU COMMAND
34985 mysql 80 44 0 535M 243M CPU0 0 0:13 28.22% mysqld
44953 www 1 101 0 159M 32980K RUN 4 0:14 28.08% httpd
45078 www 1 100 0 158M 31444K RUN 1 0:05 22.85% httpd
44708 www 1 76 0 159M 32608K select 1 0:21 22.75% httpd
44181 root 1 63 0 2740K 800K biowr 7 1:38 15.19% rm
44705 www 1 53 0 159M 32840K RUN 1 0:26 12.70% httpd
45057 www 1 53 0 159M 32572K select 4 0:07 12.50% httpd
45054 www 1 54 0 158M 31436K lockf 5 0:08 9.18% httpd
44119 www 1 55 0 158M 32272K lockf 0 0:53 8.98% httpd
45048 www 1 48 0 159M 31960K CPU2 2 0:09 7.76% httpd
45067 www 1 52 0 159M 32696K lockf 5 0:04 7.76% httpd
44986 www 1 51 0 158M 32012K lockf 4 0:17 7.37% httpd
44626 www 1 51 0 159M 32856K lockf 1 0:30 7.18% httpd
44643 www 1 50 0 159M 32744K RUN 7 0:25 7.18% httpd
45081 www 1 49 0 160M 33100K CPU0 0 0:03 7.08% httpd
44735 www 1 50 0 160M 33128K CPU5 5 0:16 6.98% httpd
45038 www 1 50 0 159M 32680K lockf 1 0:05 6.98% httpd
45047 www 1 50 0 159M 32736K select 3 0:04 6.69% httpd
45037 www 1 50 0 158M 31476K lockf 5 0:04 6.59% httpd
45059 www 1 50 0 159M 32680K lockf 6 0:05 6.49% httpd
44508 www 1 49 0 159M 32776K lockf 4 0:40 6.40% httpd
45084 www 1 50 0 158M 31708K select 4 0:03 6.40% httpd
44962 www 1 49 0 159M 32404K select 6 0:16 6.30% httpd
45062 www 1 50 0 159M 32688K lockf 5 0:04 6.30% httpd
45040 www 1 49 0 158M 31432K select 0 0:05 6.15% httpd
44526 www 1 48 0 159M 32820K select 4 0:37 6.05% httpd
44600 www 1 48 0 160M 33072K CPU7 7 0:27 6.05% httpd
44710 www 1 49 0 160M 33116K lockf 3 0:21 6.05% httpd
44673 www 1 48 0 159M 32864K CPU3 3 0:20 6.05% httpd
44790 www 1 49 0 159M 32864K lockf 6 0:20 6.05% httpd
45065 www 1 48 0 159M 31832K biowr 4 0:08 6.05% httpd
45049 www 1 48 0 159M 31688K biowr 6 0:07 6.05% httpd
45036 www 1 47 0 159M 32504K select 4 0:05 5.96% httpd
45060 www 1 49 0 160M 33048K RUN 6 0:04 5.96% httpd
44647 www 1 48 0 160M 33120K CPU6 6 0:27 5.86% httpd
44967 www 1 49 0 160M 33104K getblk 2 0:11 5.86% httpd
45063 www 1 49 0 160M 33084K lockf 1 0:04 5.86% httpd
45082 www 1 49 0 160M 33100K getblk 0 0:03 5.86% httpd
45103 www 1 48 0 159M 32680K RUN 0 0:03 5.86% httpd
44503 www 1 49 0 159M 33092K select 2 0:38 5.76% httpd
44776 www 1 48 0 159M 32756K select 4 0:19 5.76% httpd
44980 www 1 49 0 160M 33100K lockf 5 0:10 5.76% httpd
45088 www 1 48 0 160M 33056K getblk 3 0:03 5.76% httpd
45098 www 1 49 0 158M 31424K lockf 7 0:03 5.76% httpd
44669 www 1 49 0 159M 32740K lockf 6 0:28 5.66% httpd
44588 www 1 49 0 159M 33176K lockf 0 0:24 5.66% httpd
44990 www 1 48 0 159M 32740K select 7 0:13 5.66% httpd

Answer 1

[dinix]

load averages: 26.49, 25.19, 23.14
Это может быть жуткий перегруз, если ядер проца мало.
Сколько их? sysctl -a | egrep -i 'hw.ncpu'
и кто зомби? 1 zombie

Comments

[Артем]

Сервер с неплохим железом вообще:
# sysctl -a | egrep -i 'hw.ncpu'
hw.ncpu: 8

Зомби вот (у него PID меняется каждую секунду, подолгу не висит т.е.):
# ps aux | grep Z
USER PID %CPU %MEM VSZ RSS TT STAT STARTED TIME COMMAND
www 50922 12,6 0,0 0 0 ?? Z 20:51 0:24,26

[dinix]

Телепатически помочь наверное таки не смогу, извините, но что можно попробовать: проверить, какие ошибки сыпятся в dmesg, логи мускуля и апача, если проблема с модулями апача — должна быть какая-то ругань в логах, проверить свободное место на диске, включить php_error лог, перенаправить его в какой-нибудь файл. Когда выяснится, что сбоит, будет яснее, что лечить.
Ещё при обновлении до 2й версии апача, чтобы получить поведение как 1.3 нужно выбирать prefork: httpd.apache.org/docs/2.0/upgrading.html

[Артем]

Телепатически помочь наверное таки не смогу, извините

Спасибо за любую помощь :)

В остальном: логи апача и пхп и раньше смотрел, ничего интересного там не нашел. А вот в dmesg — да, не заглянул. Сейчас там вижу интересную вещь:
swap_pager_getswapspace(3): failed
swap_pager_getswapspace(16): failed
swap_pager_getswapspace(2): failed
swap_pager_getswapspace(3): failed
swap_pager_getswapspace(4): failed
swap_pager_getswapspace(2): failed
pid 73545 (httpd), uid 80, was killed: out of swap space

При том, что
# swapinfo
Device 1K-blocks Used Avail Capacity
/dev/mirror/gm0s1b 4194304 0 4194304 0%

Что бы это могло значить? Swap у меня никогда не используется, всегда ноль показывает. А тут говорит out of space…

В MySQL-ных логах вроде ничего интересного. Часто встречается
[Warning] Statement may not be safe to log in statement format. Statement: UPDATE table SET f1=ROUND(RAND()*100,0) WHERE f2=11
Но тут вроде ничего страшного нет.

[Артем]

загляните MySQL show processlist

Да-да, я описывал в тексте вопроса наблюдения за этими самыми процессами.

[Артем]

Чуть не забыл. Свободного места на диске — 40%.

[VBart]

swapinfo нужно смотреть в тот момент, когда и случаются тормоза. Это может быть очень короткий интервал времени, за который у вас выбирается вся память, а потом просто убиваются часть процессов и снова чистенько.

[VBart]

Попробуйте заменить Апач на php-fpm.

[Артем]

swapinfo нужно смотреть в тот момент, когда и случаются тормоза

На этот случай есть график из мунина. По нему видно, что своп никогда не используется (см. легенду).

.

Попробуйте заменить Апач на php-fpm.

Спасибо за вариант. Наверное, действительно, придется попробовать, если в этой связке не получится починить.

[nochkin]

swap не используется… А он вообще существует? Очень похоже, что его просто нет.

[dinix]

Есть, см. выше
# swapinfo
Device 1K-blocks Used Avail Capacity
/dev/mirror/gm0s1b 4194304 0 4194304 0%

Вопросы вдогонку: php -m никаких ошибок не выдаёт про потерявшиеся при апгрейде модули php?
Кеширование какое-то было до апгрейда? Сейчас осталось?

[Артем]

Никаких ошибок:

# php -m
[PHP Modules]
bcmath
bz2
calendar
Core
ctype
curl
date
dom
ereg
exif
fileinfo
filter
ftp
gd
hash
iconv
imap
json
libxml
mbstring
mcrypt
mhash
mysql
mysqlnd
pcre
PDO
pdo_sqlite
Phar
posix
Reflection
session
SimpleXML
soap
sockets
SPL
sqlite3
standard
tokenizer
xml
xmlreader
xmlwriter
zip
zlib

[Zend Modules]

Кеширование в скриптах в сложных местах есть. И до апгрейда было, и после осталось.

Answer 2

[SergeyR]

Посмотрите нагрузку на диск gstat
и netstat -n | grep 80| awk '{print $5}' | cut -d. -f 1,2,3,4 | sort | uniq -c | sort -n
может быть ддос.

Comments

[Артем]

# gstat
dT: 1.008s w: 1.000s
L(q) ops/s r/s kBps ms/r w/s kBps ms/w %busy Name
1 24 0 0 0.0 24 587 16.1 30.6| ad4
1 24 0 0 0.0 24 587 16.1 30.6| ad6
1 24 0 0 0.0 24 587 40.9 63.3| mirror/gm0
2 23 0 0 0.0 23 571 47.9 69.2| mirror/gm0s1
2 23 0 0 0.0 23 571 49.5 69.6| mirror/gm0s1a
0 0 0 0 0.0 0 0 0.0 0.0| mirror/gm0s1b

По нетстату вроде все вполне разумно для сайта с пользователями. DDoS вряд ли: статика грузится влет.

Answer 3

[MT]

Возможно, как-то связано с этим изменением в PHP 5.4:

ext/mysql, mysqli and pdo_mysql now use mysqlnd by default.

Comments

[Артем]

Пробовал пересобирать расширение и с включенной галочкой, и с выключенной. Результат один и тот же, к сожалению.

[MT]

Попробуйте при подключении к MySQL указать в качестве хоста не localhost, а IP-адрес 127.0.0.1. (Теоретически это актуально только для Windows, но мало ли.)

Answer 4

[Пума Тайланд]

Из топа видно что весь проц зажран, есть мускул один, и много апача и один rm
Для начала убираем rm
логично что тормоза mysql связаны не с самим мускулом, а с тем что апач зажрал весь проц, если апач зажрал, то тут либо не верный конфиг апача или же не верный конфиг php ну или код php как всегда говно и в новой версии оверлоадид модуль php в апаче.

Comments

[Артем]

Для начала убираем rm

rm уже закончился, это я папку просто очищал.

не верный конфиг php

Он практически дефолтный. Только мелочи вроде short_tags включил.

ну или код php

Отдельно без БД код выполняется быстро.

не верный конфиг апача

Пробовали всячески двигать параметры апача… Абсолютно никакой реакции.

Answer 5

[nochkin]

Если загружен swap, то это серъезная проблема. Надо либо оптимизировать на загрузку памяти (возможно, начать с mysql), либо добавить память на сервер.
Например, можно начать с удалением ненужных модулей и уменьшением количества процессов у apache.

Comments

[Артем]

В том-то и дело, что swap всегда на нуле. То есть, swap всегда свободен, но при этом воспользоваться им никто не может. Видимо, как раз тут и надо что-то делать. А памяти стоит 8 гигов и она практически никогда полностью не используется.

[Артем]

Добавил выше график из мунина, возможно, также будет полезен.

[nochkin]

По графику похоже что swap'а просто на сервере нет. Это действительно так?

[Артем]

Ну, если верить swapinfo, то он занимает 4 гигабайта:
# swapinfo
Device 1K-blocks Used Avail Capacity
/dev/mirror/gm0s1b 4194304 0 4194304 0%

То есть он как бы есть, но его как бы и нет. Или я чего-то не понимаю.

Answer 6

[Алексей Акулович]

А apachetop -f /path/to/apache.access.log показывает ожидаемую ситуацию?