Диагностика MySQL 8.4: digest в Performance Schema, sys, slow log, EXPLAIN ANALYZE и INNODB STATUS по разделам

В MySQL нет queryid, но есть его аналог: Performance Schema сворачивает запросы в digest и копит по нему время, прочитанные и отправленные строки, признак «без индекса». Это тот же приём, что в pg_stat_statements, и путь тот же: digest находит запрос, sys и slow log показывают его детали, EXPLAIN ANALYZE называет причину, после индекса счётчики снимают заново. Здесь путь пройден на MySQL 8.4 с запросом по неиндексированному столбцу и сортировкой.

DBA / 01koddo

Где в MySQL считается каждый счётчик

Стенд

Буферный пул по умолчанию (128 МБ), таблица втрое больше. Индекс idx_kind нужен для поиска неиспользуемых индексов и на запрос не влияет:

C=dba-mysql-diagnostics-performance-schema
docker run -d --name $C --memory 1500m -e MYSQL_ROOT_PASSWORD=pg mysql:8.4

CREATE DATABASE shop; USE shop;
CREATE TABLE activity (
  id BIGINT NOT NULL AUTO_INCREMENT PRIMARY KEY,
  user_id INT NOT NULL, kind TINYINT NOT NULL, created DATETIME NOT NULL,
  payload VARCHAR(120) NOT NULL, KEY idx_kind (kind)
) ENGINE=InnoDB;
CREATE TABLE users (id INT PRIMARY KEY, name VARCHAR(40) NOT NULL) ENGINE=InnoDB;
SET SESSION cte_max_recursion_depth = 2000;
CREATE TABLE seq (n INT PRIMARY KEY);
INSERT INTO seq WITH RECURSIVE r(n) AS (SELECT 1 UNION ALL SELECT n+1 FROM r WHERE n<2000) SELECT n FROM r;
INSERT INTO users SELECT n, CONCAT('user', n) FROM seq;

Шесть повторов вставки дали 3 000 000 строк и 427 МБ данных:

INSERT INTO activity (user_id, kind, created, payload)
SELECT 1+FLOOR(RAND()*30000), a.n%10, NOW() - INTERVAL FLOOR(RAND()*365*86400) SECOND,
       REPEAT(CHAR(97+FLOOR(RAND()*26)), 100)
FROM seq a JOIN seq b ON b.n <= 250;

Нагрузка — файлы SQL и шесть параллельных клиентов. Четыре файла bad_N.sql — по 12 запросов по случайному user_id без индекса и с сортировкой; два ok_N.sql — по 1500 точечных запросов по ключу с JOIN и 300 обновлений:

for n in 1 2 3 4; do
  awk -v s=$n 'BEGIN{srand(s); for(i=0;i<12;i++) printf "SELECT id, created, payload FROM activity WHERE user_id = %d ORDER BY created DESC LIMIT 20;\n", 1+int(rand()*30000)}' > bad_$n.sql
done
for n in 1 2; do
  awk -v s=$n 'BEGIN{srand(10+s); for(i=0;i<1500;i++){ printf "SELECT e.id, u.name FROM activity e JOIN users u ON u.id = e.kind WHERE e.id = %d;\n", 1+int(rand()*3000000); if(i%5==0) printf "UPDATE activity SET kind = (kind+1)%%10 WHERE id = %d;\n", 1+int(rand()*3000000)}}' > ok_$n.sql
done
run() {
  for f in bad_{1..4} ok_{1..2}; do docker exec -i $C mysql -uroot -ppg shop -f < $f.sql >/dev/null & done
  wait
}

Перед окном включается медленный журнал с порогом 0,3 с и сбрасывается digest. TRUNCATE заменяет здесь снимок с нуля; на боевой базе счётчики копят в таблицу снимков и читают разность, как для pg_stat_statements:

SET GLOBAL log_slow_extra = ON; SET GLOBAL long_query_time = 0.3; SET GLOBAL slow_query_log = ON;
TRUNCATE performance_schema.events_statements_summary_by_digest;

Опыт 1: digest находит запрос, sys уточняет

run занял 14,4 с. Топ по SUM_TIMER_WAIT; таймеры Performance Schema идут в пикосекундах, поэтому деление на 1e12 даёт секунды, на 1e9 — миллисекунды:

SELECT LEFT(DIGEST_TEXT, 60) AS q, COUNT_STAR AS calls,
       ROUND(SUM_TIMER_WAIT/1e12, 2) AS total_s, ROUND(AVG_TIMER_WAIT/1e9) AS avg_ms,
       SUM_ROWS_EXAMINED AS examined, SUM_ROWS_SENT AS sent, SUM_NO_INDEX_USED AS no_idx,
       SUM_SORT_MERGE_PASSES AS merge_pass, SUM_CREATED_TMP_DISK_TABLES AS tmp_disk
FROM performance_schema.events_statements_summary_by_digest
WHERE SCHEMA_NAME = 'shop' ORDER BY SUM_TIMER_WAIT DESC LIMIT 3;

вывод (три первые строки):

+--------------------------------------------------------------+-------+---------+--------+-----------+------+--------+------------+----------+
| q                                                            | calls | total_s | avg_ms | examined  | sent | no_idx | merge_pass | tmp_disk |
+--------------------------------------------------------------+-------+---------+--------+-----------+------+--------+------------+----------+
| SELECT `id` , `created` , `payload` FROM `activity` WHERE `u |    48 |   57.42 |   1196 | 144000960 |  960 |     48 |          0 |        0 |
| UPDATE `activity` SET `kind` = ( `kind` + ? ) % ? WHERE `id` |   600 |    8.36 |     14 |       572 |    0 |      0 |          0 |        0 |
| SELECT `e` . `id` , `u` . `name` FROM `activity` `e` JOIN `u |  2999 |    2.06 |      1 |      2596 | 2596 |      0 |          0 |        0 |
+--------------------------------------------------------------+-------+---------+--------+-----------+------+--------+------------+----------+

Первая строка: 48 вызовов отняли 57,42 с из 67,84 с трёх строк, по 1196 мс на вызов. Прочитано 144 000 960 строк против 960 отправленных, 150 001 на каждую отправленную; SUM_NO_INDEX_USED = 48 — каждый вызов шёл без индекса. merge_pass и tmp_disk равны нулю: при LIMIT 20 сортировка держит в памяти только 20 строк, вред здесь в чтении, а не в сортировке. Точечные запросы честные: прочитано 2596, отправлено 2596.

Ключ записи — хеш токенов запроса и схема; в DIGEST_TEXT константы заменены на ?. Это find_or_create_digest в mysql-8.4.13 (pfs_digest.cc, строки 267–270); счётчики к записи прибавляет pfs_end_statement_vc по окончании каждого запроса (pfs.cc, строки 7196–7198), так что это точный счёт, а не выборка:

  /* Copy digest hash of the tokens received. */
  memcpy(&hash_key.m_hash, digest_storage->m_hash, DIGEST_HASH_SIZE);
  /* Add the current schema to the key */
  hash_key.m_schema_name.set(schema_name, schema_name_length);

Те же данные уже собраны в представления sys:

SELECT exec_count, no_index_used_pct, rows_sent_avg, rows_examined_avg
FROM sys.statements_with_full_table_scans WHERE db = 'shop'\G

вывод:

        exec_count: 48
 no_index_used_pct: 100
     rows_sent_avg: 20
 rows_examined_avg: 3000020

В представлении только этот запрос, точечные в него не вошли.

Опыт 2: slow log даёт константы

Digest знает тип запроса, но не параметр. С log_slow_extra = ON в журнал попадают счётчики обработчика. Первая из 48 записей дословно:

# Time: 2026-10-28T01:09:35.454714Z
# User@Host: root[root] @ localhost []  Id:    34
# Query_time: 2.996217  Lock_time: 0.000000 Rows_sent: 20  Rows_examined: 3000020 Thread_id: 34 Errno: 0 Killed: 0 Bytes_received: 101 Bytes_sent: 2837 Read_first: 1 Read_last: 0 Read_key: 1 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 3000001 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 20 Sort_scan_count: 1 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2026-10-28T01:09:32.458497Z End: 2026-10-28T01:09:35.454714Z
SET timestamp=1793149772;
SELECT id, created, payload FROM activity WHERE user_id = 22692 ORDER BY created DESC LIMIT 20;

Записей ровно 48, по числу вызовов: UPDATE и точечные запросы порога 0,3 с не достигли. Read_rnd_next: 3000001 — обработчик прошёл таблицу подряд, Sort_scan_count: 1 — сортировка шла по этому проходу. В строке есть то, чего нет в digest: user_id = 22692 и время начала. Первые вызовы четырёх клиентов шли одновременно, поэтому 2,996 с выше среднего по digest (1196 мс) в 2,5 раза.

Опыт 3: EXPLAIN ANALYZE называет причину, индекс её убирает

EXPLAIN ANALYZE выполняет запрос и печатает дерево итераторов с фактическим временем. Строку (actual time=… rows=… loops=…) собирает ExplainPrintCosts (explain_access_path.cc, строки 2179–2189):

      double actual_first_row_ms = GetJSONDouble(obj, "actual_first_row_ms");
      double actual_last_row_ms = GetJSONDouble(obj, "actual_last_row_ms");
      double actual_rows = GetJSONDouble(obj, "actual_rows");
      uint64_t actual_loops =
          down_cast<Json_int *>(obj->get("actual_loops"))->value();

      std::ostringstream stream;
      stream << "(actual time=" << FormatNumberReadably(actual_first_row_ms)
             << ".." << FormatNumberReadably(actual_last_row_ms)
             << " rows=" << FormatNumberReadably(actual_rows)
             << " loops=" << FormatNumberReadably(actual_loops) << ")";

EXPLAIN ANALYZE SELECT id, created, payload FROM activity WHERE user_id = 777 ORDER BY created DESC LIMIT 20\G

вывод:

-> Limit: 20 row(s)  (cost=311501 rows=20) (actual time=1174..1174 rows=20 loops=1)
    -> Sort: activity.created DESC, limit input to 20 row(s) per chunk  (cost=311501 rows=2.9e+6) (actual time=1174..1174 rows=20 loops=1)
        -> Filter: (activity.user_id = 777)  (cost=311501 rows=2.9e+6) (actual time=43.4..1173 rows=113 loops=1)
            -> Table scan on activity  (cost=311501 rows=2.9e+6) (actual time=0.661..1090 rows=3e+6 loops=1)

Дерево читают снизу вверх: Table scan прочитал 3 000 000 строк за 1090 мс, Filter оставил 113, Sort выбрал 20. Оценка rows=2.9e+6 совпала с фактом: статистика в порядке, у запроса нет пути к user_id. Как читать rows × loops на вложенных циклах, разобрано в статье про EXPLAIN; здесь везде loops=1. Индекс (user_id, created) закрывает и фильтр, и сортировку:

ALTER TABLE activity ADD KEY idx_user_created (user_id, created);

Тот же EXPLAIN ANALYZE, вывод:

-> Limit: 20 row(s)  (cost=115 rows=20) (actual time=2.71..4.21 rows=20 loops=1)
    -> Index lookup on activity using idx_user_created (user_id=777) (reverse)  (cost=115 rows=113) (actual time=2.71..4.21 rows=20 loops=1)

Filter и Sort исчезли, Index lookup … (reverse) читает 20 строк с конца индекса. Вторичный индекс хранит первичный ключ (кластерный индекс InnoDB), за payload запрос переходит в таблицу по нему.

Теперь digest-разность: счётчики сброшены, run выполнен снова (2,2 с вместо 14,4). Строка запроса:

| q                                                            | calls | total_s | avg_ms | examined | sent | no_idx | merge_pass | tmp_disk |
| SELECT `id` , `created` , `payload` FROM `activity` WHERE `u |    48 |    0.22 |      5 |      960 |  960 |      0 |          0 |        0 |

Запрос стал третьим по времени: 57,42 → 0,22 с, 1196 → 5 мс на вызов, 144 000 960 → 960 прочитанных строк, SUM_NO_INDEX_USED 48 → 0. Записей в slow log 0.

Опыт 4: неиспользуемый индекс

sys.schema_unused_indexes показывает индексы без единого чтения с момента перезапуска или сброса table_io_waits_summary_by_index_usage; эту таблицу сбрасывали перед окном «до»:

SELECT * FROM sys.schema_unused_indexes WHERE object_schema = 'shop';
SELECT INDEX_NAME, COUNT_READ FROM performance_schema.table_io_waits_summary_by_index_usage
WHERE OBJECT_SCHEMA = 'shop' AND OBJECT_NAME = 'activity';

вывод:

| shop          | activity    | idx_kind   |
| PRIMARY    |       7208 |
| idx_kind   |          0 |
| NULL       |  291000000 |

idx_kind не прочитан ни разу, а строка NULL с 291 000 000 чтений — обращения без индекса, то есть проходы таблицы. «Не читался» верно только для окна: индекс для квартального отчёта в такой выборке тоже выглядит лишним. Перед DROP INDEX его делают невидимым: ALTER TABLE activity ALTER INDEX idx_kind INVISIBLE дал IS_VISIBLE = NO в information_schema.statistics.

Опыт 5: SHOW ENGINE INNODB STATUS по разделам

Отчёт снят через 6 секунд после старта run, когда другая сессия держала открытую транзакцию (UPDATE activity SET kind=kind WHERE id BETWEEN 1 AND 3; DO SLEEP(14)); предыдущий вызов в той же сессии нужен для отсчёта «в секунду». Заголовок: Per second averages calculated from the last 6 seconds.

SEMAPHORES — ожидания латчей InnoDB. В отчёте RW-shared spins 0, rounds 0, OS waits 0 и такие же нули у RW-excl: потоки на латчах не засыпали.

TRANSACTIONS — открытые транзакции и объём истории в undo:

History list length 572
---TRANSACTION 4202, ACTIVE 6 sec
3 lock struct(s), heap size 1128, 3 row lock(s)

History list length — число журналов undo закоммиченных транзакций, которые purge ещё не обработал; оно растёт, пока висит старая транзакция (механика — в MVCC и undo InnoDB). ACTIVE 6 sec и три блокировки строк при запросе DO SLEEP(14) — забытая транзакция.

BUFFER POOL AND MEMORY — состояние буферного пула:

Buffer pool size   8192
Free buffers       0
Buffer pool hit rate 866 / 1000, young-making rate 9 / 1000 not 688 / 1000

8192 страницы по 16 КиБ (innodb_page_size = 16384) — это 128 МБ. Free buffers 0: пул полон, новая страница вытесняет старую. hit rate 866 / 1000: за интервал между вызовами 134 запроса страницы из тысячи ушли мимо пула.

ROW OPERATIONS — сколько строк обработал движок:

4 read views open inside InnoDB
Number of rows inserted 3004000, updated 1716, deleted 0, read 360539223
0.00 inserts/s, 95.32 updates/s, 0.00 deletes/s, 11083422.76 reads/s

read 360539223 против updated 1716: нагрузка почти целиком чтение, 11 млн строк в секунду — скан испорченного запроса. 4 read views open — открытые снимки MVCC; вставлено 3 004 000 строк: три миллиона activity, по 2000 в seq и users.

Опыт 6: hit ratio разностью

Доля попаданий считается из Innodb_buffer_pool_read_requests (все запросы страниц) и Innodb_buffer_pool_reads (те, что не нашлись в пуле): 1 − Δreads / Δread_requests. Показания сняты командой SHOW GLOBAL STATUS WHERE Variable_name IN ('Innodb_buffer_pool_reads', 'Innodb_buffer_pool_read_requests') до и после каждого окна:

Накопительные 99,55 % включают загрузку трёх миллионов строк и не говорят о текущей минуте. После индекса доля попаданий упала до 87,42 %, хотя запрос ускорился в 260 раз (57,42 / 0,22). Запросов страниц стало в 38 раз меньше (2 192 023 → 57 695), а промахи от случайных обращений по ключу остались. Смотреть надо на промахи на единицу работы: 56 575 чтений стали 7 257. В PostgreSQL то же дают shared_blks_read и shared_blks_hit на каждый запрос; у MySQL Innodb_buffer_pool_* общие на сервер, и вклад запроса виден только по его SUM_ROWS_EXAMINED.

Что из этого следует

• Digest — карта: SUM_ROWS_EXAMINED против SUM_ROWS_SENT и SUM_NO_INDEX_USED показывают лишнее чтение; константы берут из slow log, причину — из EXPLAIN ANALYZE.
• Hit ratio смотрят разностью и рядом с объёмом работы: накопительные 99,55 % скрыли окно с 97,42 %, а 87,42 % после ускорения означали не ухудшение, а в 38 раз меньше запросов страниц.
• SHOW ENGINE INNODB STATUS отвечает про движок: History list length и ACTIVE N sec ловят забытую транзакцию, Free buffers 0 и hit rate — давление на пул, OS waits — конкуренцию внутри InnoDB. Про отдельные запросы он молчит.

Чек-лист

1. Включи slow_query_log с log_slow_extra = ON и порогом под свою нагрузку; digest копится по умолчанию, читай разность двух снимков.
2. Сортируй digest по SUM_TIMER_WAIT и сверяй SUM_ROWS_EXAMINED с SUM_ROWS_SENT, SUM_NO_INDEX_USED, SUM_SORT_MERGE_PASSES, SUM_CREATED_TMP_DISK_TABLES; готовые срезы — sys.statements_with_full_table_scans и sys.statements_with_sorting.
3. Проверяй индекс EXPLAIN ANALYZE и тем же digest до и после; кандидатов из sys.schema_unused_indexes сначала делай INVISIBLE.
4. Считай hit ratio как 1 − Δreads / Δread_requests за окно, а не по накопительным значениям.
5. Убери контейнер вместе с томом: docker rm -f -v dba-mysql-diagnostics-performance-schema.