Почему веб сервер стал долго отвечать на запросы?

Question

[Виталий Р]

Доброго времени суток.

Есть веб сервер на виртуальной машине.
Недавно он стал тормозить.

Система ubuntu 12. apache2 + mysql. Так же крутится proftpd, который для проверки я отключал и это не помогло(значит дело не в нём)

На сервере крутится новостной сайт и форум. Посещаемость очень маленькая. До последних выходных сайт отлично работал. Жалоб и нареканий не было.

В понедельник обнаружилось что сайт очень долго отвечает на запросы - больше 10 секунд.

В логах особо ничего нет (скорее всего я просто не понимаю что именно из этих логов можно использовать).

htop показывает что проц и память грузятся не больше 10% (даже редко до 5% доходит).
ifstat так же не показывает какой-то плохой(не обычной) сетевой активности.

Я только только начинаю вникать в строение веб серверов и в то как их мониторить (исследовать), так что прошу объясните пожалуйста поподробней:

Как и где включить такое логирование, которое даст мне необходимые данные?
Куда следует в первую очередь посмотреть ?

Comments

[Виталий Р]

Закрываю вопрос.

Проблема была в корявом модуле джумлы. Обновили джумлу - все сразу заработало. К сожалению что конкретно повышало TTFB до 10 сек, понять так и не удалось.

иногда ответ на поверхности, а я рылся во всяких ifsta`ах и strace`ах

Answer 1

[cybernoob]

1. Включить логирование медленных запросов в MySQL
2. Посмотреть в браузере вкладку Network

Comments

[Виталий Р]

1. Включить логирование медленных запросов в MySQL

Включил, сделал задержку не больше 1 секунды. mariadb-slow.log пустой :(

2. Посмотреть в браузере вкладку Network

Спасибо, не знал такую вещь. Немного в ней полазив, понял что долго отвечают страницы type "document", initiator "other" размер 30-45 кб. У всех страниц примерно одинаковое время 10.02 - 10.80 секунд. Все остальные элементы загружаются как положено (не больше 200 ms). Собственно сервер долго отдаёт саму страницу.

Answer 2

[hOtRush]

openvz?

Comments

[Виталий Р]

Не, vsphere (в центр, кластеры и всё такое)

Answer 3

[Alex McArrow]

iotop - может диски "сыпяться"

Comments

[Виталий Р]

Не, это я сразу глянул. Виртуалка находится на хранилке, вместе с десятками других виртуалок.

iotop показывает всё по нулям (по минимуму).

в моменты открытия страниц, мускуль обращается к диску и запись не превышает 700 k/s, IO - от 0,20 до 0,60% (редко поднимается до 2-3%)
в моменты когда апач обращается к диску эти значения больше, но не на много.

Answer 4

[Виктор Таран]

iotop -oka

Comments

[Виталий Р]

На какие параметры обратить внимание, чтобы понять, что проблема именно в диске ?

[Виктор Таран]

I-o

[Виталий Р]

Всё с ним нормально. Да я это так спросил. Просто сомневался, мало ли туплю чё-то.

Вообще.... На этом сервере 2 virtualhosta: форум и новости.

Форум летает, а вот новости отдают свои страницы по 10 секунд

Answer 5

[Виталий Р]

iotop -oka

в течении 3-5 минут (я обильно открывал страницы сайта) накопил следующее:

spoiler

Total DISK READ: 0.00 K/s | Total DISK WRITE: 0.00 K/s
TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
9125 be/4 mysql 12.00 K 248.00 K 0.00 % 1.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
8653 be/4 mysql 0.00 K 7724.00 K 0.00 % 0.37 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
236 be/3 root 0.00 K 2096.00 K 0.00 % 0.27 % [jbd2/dm-0-8]
8646 be/4 mysql 0.00 K 0.00 K 0.00 % 0.22 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
8644 be/4 mysql 0.00 K 0.00 K 0.00 % 0.21 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
8647 be/4 mysql 0.00 K 0.00 K 0.00 % 0.20 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
8645 be/4 mysql 0.00 K 0.00 K 0.00 % 0.18 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
9066 be/4 mysql 8.00 K 256.00 K 0.00 % 0.12 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
9583 be/4 www-data 8.00 K 136.00 K 0.00 % 0.10 % apache2 -k start
8671 be/4 mysql 16.00 K 248.00 K 0.00 % 0.04 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
8639 be/4 mysql 0.00 K 0.00 K 0.00 % 0.01 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
9600 be/4 www-data 8.00 K 76.00 K 0.00 % 0.01 % apache2 -k start
9568 be/4 www-data 4.00 K 248.00 K 0.00 % 0.01 % apache2 -k start
9571 be/4 www-data 4.00 K 640.00 K 0.00 % 0.00 % apache2 -k start
9422 be/4 www-data 4.00 K 20.00 K 0.00 % 0.00 % apache2 -k start
1728 be/4 root 0.00 K 0.00 K 0.00 % 0.00 % [flush-252:0]
8654 be/4 mysql 0.00 K 4.00 K 0.00 % 0.00 % mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib/mysql/plugin --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --socket=/var/run/mysqld/mysqld.sock --port=3306
9276 be/4 www-data 0.00 K 72.00 K 0.00 % 0.00 % apache2 -k start
9599 be/4 www-data 0.00 K 484.00 K 0.00 % 0.00 % apache2 -k start
1787 be/0 root 0.00 K 8.00 K 0.00 % 0.00 % atop -a -w /var/log/atop.log 600
9566 be/4 www-data 0.00 K 12.00 K 0.00 % 0.00 % apache2 -k start
9570 be/4 www-data 0.00 K 252.00 K 0.00 % 0.00 % apache2 -k start
9601 be/4 www-data 0.00 K 32.00 K 0.00 % 0.00 % apache2 -k start
9625 be/4 www-data 0.00 K 32.00 K 0.00 % 0.00 % apache2 -k start

Куда глянуть то, братики ? какие логи посмотреть ? :(

ЗАБЫЛ УТОЧНИТЬ ВАЖНОЕ:

У апача 2 sites-enabled

Форум - летает без милисекундных задержек.

Новости (набор страниц с инфой и документами) - открывает любую из страниц 10-11 секунд.

Именно апач отдаёт страницы с такой скоростью.

Comments

[hOtRush]

С чего ты взял что именно апач?
Вот ты написал что время загрузки страницы 10 секунд, из этих 10 секунд сколько он ждет и сколько качает ответ. joxi.ru/DmBNQ30swakNZm
Если 10 секунд ожидание - это время генерации твоего контента, тупится код или база, надо профилировать.
Если 10 секунд загрузки - где-то тупится сеть, что маловероятно, так как второй сайт, статика и т.д. отдаются норм.

[Виталий Р]

hOtRush,

С чего ты взял что именно апач?

Я плохо шарю в веб серверах, всего лишь предположил. Пытаюсь зацепиться хоть за что-то.

Если 10 секунд ожидание - это время генерации твоего контента, тупится код или база, надо профилировать.

10 секунд именно "wait" (TTFB)

тупится код или база

В базе в mysql_slow_log редко редко что-то падает. Реже чем идут обращения к сайту, но всё же вот часть слоу-лога:

mysql_slow_log

SET timestamp=1517339410;
SELECT /*!40001 SQL_NO_CACHE */ * FROM `jm_finder_links`;
# Time: 180131 0:10:18
# User@Host: root[root] @ localhost []
# Thread_id: 2876 Schema: wiki QC_hit: No
# Query_time: 2.170463 Lock_time: 0.000038 Rows_sent: 445070 Rows_examined: 445070
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
SET timestamp=1517339418;
SELECT /*!40001 SQL_NO_CACHE */ * FROM `jm_finder_terms`;
# Time: 180131 0:10:21
# User@Host: root[root] @ localhost []
# Thread_id: 2876 Schema: wiki QC_hit: No
# Query_time: 2.815971 Lock_time: 0.000039 Rows_sent: 4929 Rows_examined: 4929
# Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
SET timestamp=1517339421;
SELECT /*!40001 SQL_NO_CACHE */ * FROM `jm_ucm_history`;
# Time: 180131 0:11:30
# User@Host: wiki[wiki] @ localhost []
# Thread_id: 2880 Schema: wiki QC_hit: No
# Query_time: 1.131455 Lock_time: 0.000078 Rows_sent: 0 Rows_examined: 2
SET timestamp=1517339490;
DELETE
FROM `jm_session`
WHERE `time` < '1517332289';
/usr/sbin/mysqld, Version: 5.5.40-MariaDB-1~precise-log (mariadb.org binary distribution). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock

[hOtRush]

ну хотя бы понятно, что дело не в апаче, а дальше сложно угадать, нужно по месту разбираться