Рассмотрим как собрать логи всех запросов который выполняются в MySQL. С помощью этого лога можно не только рассчитать количество запросов, но и проверить как изменилось взаимодействие с БД со стороны программы. Визуально увидеть повторяющиеся по смыслу последовательности запросов или даже провести анализ и explain для особо подозрительных.

Варианты логирования и хранения запросов

Для начала нужно определиться какие запросы нам нужны. Есть два варианта, запросов которые будут записываться сервером MySQL:

  • slow_query_log - это запросы, которые выполняются дольше определенного порогового значения, обычно этот лог включается на продолжительное время или вообще работает на постоянной основе;
  • general_log - это все запросы, которые поступают на сервер. Так как приходится записывать все запросы, а сервер может быть очень нагружен ( сотни, а то и более rps), то такой лог лучше включать локально, в тестовых стендах или прогонах в CI.

Оба лога включаются ТОЛЬКО на глобальном уровне (SET GLOBAL ... или файл конфигурации). Так же ТОЛЬКО на глобальном уровне определяется место хранения лога ( log_output: FILE или TABLE). Можно писать лог сразу в файл и таблицу, если задать значение TABLE,FILE.

Логирование медленных запросов

Это лог, который сохраняет “слишком долго” выполняющиеся запросы. Слишком долго можно определить через переменную long_query_time. При этом в отличие от самого лога, эту переменную можно изменить для сессии.

Если таблицы нет, то ее можно создать. Для этого в MySQL уже есть подготовленная команда, в ней содержится описание схемы таблицы:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17

mysql> SHOW CREATE TABLE mysql.slow_log\G
*************************** 1. row ***************************
       Table: slow_log
Create Table : CREATE TABLE `slow_log` (
  `start_time` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
  `user_host` mediumtext NOT NULL,
  `query_time` time(6) NOT NULL,
  `lock_time` time(6) NOT NULL,
  `rows_sent` int NOT NULL,
  `rows_examined` int NOT NULL,
  `db` varchar(512) NOT NULL,
  `last_insert_id` int NOT NULL,
  `insert_id` int NOT NULL,
  `server_id` int unsigned NOT NULL,
  `sql_text` mediumblob NOT NULL,
  `thread_id` bigint unsigned NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8mb3 COMMENT='Slow log'

По умолчанию таблица создается с ENGINE=CSV, что позволяет хранить данные на диске в виде файла:

1
2

bash-5.1# ls -al /var/lib/mysql/mysql/slow_log.CSV
-rw-r-----. 1 mysql mysql 0 Sep 27 20:19 /var/lib/mysql/mysql/slow_log.CSV

Посмотреть текущие настройки логирования медленных запросов можно так:

1
2
3
4
5
6
7
8
9

mysql> SHOW VARIABLES WHERE Variable_name in ('log_output', 'slow_query_log', 'slow_query_log_file', 'long_query_time');
+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| log_output          | FILE                                 |
| long_query_time     | 10.000000                            |
| slow_query_log      | OFF                                  |
| slow_query_log_file | /var/lib/mysql/f07f97f6ef28-slow.log |
+---------------------+--------------------------------------+

Полный лог запросов

Это лог со ВСЕМИ запросами, которые приходят в MySQL. Тут будут так же запросы на подключение, изменения настроек и прочего. Для хранения потребуется отличаня от slow_log схема таблицы для хранения, ее можно получить так:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11

mysql> SHOW CREATE TABLE mysql.general_log\G
*************************** 1. row ***************************
       Table: general_log
Create Table : CREATE TABLE `general_log` (
  `event_time` timestamp(6) NOT NULL DEFAULT CURRENT_TIMESTAMP(6) ON UPDATE CURRENT_TIMESTAMP(6),
  `user_host` mediumtext NOT NULL,
  `thread_id` bigint unsigned NOT NULL,
  `server_id` int unsigned NOT NULL,
  `command_type` varchar(64) NOT NULL,
  `argument` mediumblob NOT NULL
) ENGINE=CSV DEFAULT CHARSET=utf8mb3 COMMENT='General log'

Так же как и лог медленных запросов, по умолчанию используется CSV движок.

1
2

bash-5.1# ls -al /var/lib/mysql/mysql/general_log.CSV
-rw-r-----. 1 mysql mysql 0 Sep 27 20:19 /var/lib/mysql/mysql/general_log.CSV

Посмотреть текущие настройки полного логирования можно так:

1
2
3
4
5
6
7
8

mysql> SHOW VARIABLES WHERE Variable_name in ('log_output', 'general_log', 'general_log_file');
+------------------+---------------------------------+
| Variable_name    | Value                           |
+------------------+---------------------------------+
| general_log      | OFF                             |
| general_log_file | /var/lib/mysql/f07f97f6ef28.log |
| log_output       | FILE                            |
+------------------+---------------------------------+

Примеры использования

Для тестов будем использовать MySQL 8.4 в виде docker контейнера:

1

docker run --rm --name mysql-test -e MYSQL_ALLOW_EMPTY_PASSWORD=yes mysql:8.4

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

1

docker run -it --rm --net=container:mysql-test mysql:8.4 mysql -h 127.0.0.1 -uroot

Первая важная настройка, включаем хранение логов в таблице. Это самый просто вариант получить логи, если у нас нет доступа к файловой системе удаленного сервера MySQL. Так же это позволи производить манипцуляции с логами на привычном ( если уж мы полезли) языке SQL.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

mysql> SET GLOBAL log_output = 'TABLE', general_log = 'ON', slow_query_log = 'ON';
Query OK, 0 rows affected (0.00 sec)

mysql> SHOW VARIABLES WHERE Variable_name in ('log_output', 'general_log', 'general_log_file', 'slow_query_log', 'slow_query_log_file', 'long_query_time');
+---------------------+--------------------------------------+
| Variable_name       | Value                                |
+---------------------+--------------------------------------+
| general_log         | ON                                   |
| general_log_file    | /var/lib/mysql/f07f97f6ef28.log      |
| log_output          | TABLE                                |
| long_query_time     | 10.000000                            |
| slow_query_log      | ON                                   |
| slow_query_log_file | /var/lib/mysql/f07f97f6ef28-slow.log |
+---------------------+--------------------------------------+

Теперь попробуем выполнить длинный (более 10 секунд) запрос:

1

SELECT SLEEP(12);

После этого подключится вторым клиентом (допустим контейнером, который выполняет тесты приложения) и попробуем получить списко медленых запросов:

1
2
3
4
5
6

mysql> SELECT query_time, sql_text FROM mysql.slow_log;
+-----------------+------------------------------------+
| query_time      | sql_text                           |
+-----------------+------------------------------------+
| 00:00:12.000715 | 0x53454C45435420534C45455028313229 |
+-----------------+------------------------------------+

Действительно, запись попала в лог, но sql текст совершенно не читается. Это связано с тем, что таблица была создана с полем 'sql_text' mediumblob NOT NULL. Придется добавить дополнительную колонку с конвертацией:

1
2
3
4
5
6

mysql> SELECT query_time, CONVERT(sql_text USING utf8) as 'sql' FROM mysql.slow_log;
+-----------------+------------------+
| query_time      | sql              |
+-----------------+------------------+
| 00:00:12.000715 | SELECT SLEEP(12) |
+-----------------+------------------+

А вот что попало в general_log:

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14

mysql> SELECT command_type, CONVERT(argument USING utf8) AS 'sql' FROM mysql.general_log LIMIT 9;
+--------------+-----------------------------------------------------------------------------------------------------------------------------------------------------+
| command_type | sql                                                                                                                                                 |
+--------------+-----------------------------------------------------------------------------------------------------------------------------------------------------+
| Query        | SHOW VARIABLES WHERE Variable_name in ('log_output', 'general_log', 'general_log_file', 'slow_query_log', 'slow_query_log_file', 'long_query_time') |
| Query        | SELECT SLEEP(12)                                                                                                                                    |
| Connect      | [email protected] on  using SSL/TLS                                                                                                                    |
| Query        | select @@version_comment limit 1                                                                                                                    |
| Query        | SELECT * FROM mysql.slow_log                                                                                                                        |
| Query        | SELECT * FROM mysql.slow_log                                                                                                                        |
| Connect      | [email protected] on  using SSL/TLS                                                                                                                   |
| Connect      | Access denied for user 'root'@'172.17.0.1' (using password: YES)                                                                                    |
| Query        | SELECT *, convert(sql_text using utf8) FROM mysql.slow_log                                                                                          |
+--------------+-----------------------------------------------------------------------------------------------------------------------------------------------------+

А вот тут мы видим не только все запросы, которые выполнялись, но и такие события как Connect, в которых видно кто и когда подключался.

Итог

Это неплохой механизм для сбора статистики по запросам, или получения последних несколько запросов, после которыйх упал тест в CI. Так же можно поменять движок хранения для таблиц. Но нужно понимать, что как минимум лог всех запросов сильно ударит по производительности. Мне эта техника помогла разобраться как изменилось взаимодействие приложения с БД, что вызвало рост запросов.