Эта статья является продолжением цикла статей с конспектом касательно различных аспектов производительности сервера MySQL. Эта публикация посвящена тому, как можно выполнить профилирование нагрузки сервера MySQL.
Эта публикация сугубо мой конспект прочитанной литературы. Информация может быть не очень структурирована и удобочитаема. Материал публикации предоставляется без каких-либо гарантий со стороны автора.
Список первоисточников
- O’Reilly High Performance MySQL 3rd Edition.
Определение списка медленных запросов
Сначала включаем профилирование на сервере MySQL:
SET profiling = 1;
Для примера я выполню запрос к таблице с одним миллионом записей:
select * from sbtest1;
Проверим информацию об этом запросе в профилировании:
SHOW PROFILES;
+----------+------------+---------------------------+
| Query_ID | Duration | Query |
+----------+------------+---------------------------+
| 1 | 1.78114550 | select * from sbtest1 |
| 2 | 0.00179025 | sho profiles |
| 3 | 0.00022900 | show profiles for query 1 |
+----------+------------+---------------------------+
3 rows in set, 1 warning (0.00 sec)

Запрос выполнялся почти две секунды.
Разложим запрос по шагам его выполнения:
SHOW PROFILE FOR QUERY 1;
mysql> show profile for query 1;
+--------------------------------+----------+
| Status | Duration |
+--------------------------------+----------+
| starting | 0.000306 |
| Executing hook on transaction | 0.000028 |
| starting | 0.000054 |
| checking permissions | 0.000036 |
| Opening tables | 0.000360 |
| init | 0.000031 |
| System lock | 0.000065 |
| optimizing | 0.000017 |
| statistics | 0.000092 |
| preparing | 0.000035 |
| executing | 1.779383 |
| end | 0.000176 |
| query end | 0.000049 |
| waiting for handler commit | 0.000138 |
| closing tables | 0.000111 |
| freeing items | 0.000093 |
| cleaning up | 0.000175 |
+--------------------------------+----------+
17 rows in set, 1 warning (0.01 sec)

Из вывода понятно, что большая часть времени была потрачены на непосредственное выполнение запроса.
Более того, эту информацию можно получить еще немного более детально и упорядочено по наиболее затратным шагам:
SET @query_id = 1;
SELECT STATE, SUM(DURATION) AS Total_R,
ROUND(
100 * SUM(DURATION) /
(SELECT SUM(DURATION)
FROM INFORMATION_SCHEMA.PROFILING
WHERE QUERY_ID = @query_id
), 2) AS Pct_R,
COUNT(*) AS Calls,
SUM(DURATION) / COUNT(*) AS "R/Call"
FROM INFORMATION_SCHEMA.PROFILING
WHERE QUERY_ID = @query_id
GROUP BY STATE
ORDER BY Total_R DESC;
+--------------------------------+----------+-------+-------+--------------+
| STATE | Total_R | Pct_R | Calls | R/Call |
+--------------------------------+----------+-------+-------+--------------+
| executing | 1.779383 | 99.90 | 1 | 1.7793830000 |
| starting | 0.000360 | 0.02 | 2 | 0.0001800000 |
| Opening tables | 0.000360 | 0.02 | 1 | 0.0003600000 |
| end | 0.000176 | 0.01 | 1 | 0.0001760000 |
| cleaning up | 0.000175 | 0.01 | 1 | 0.0001750000 |
| waiting for handler commit | 0.000138 | 0.01 | 1 | 0.0001380000 |
| closing tables | 0.000111 | 0.01 | 1 | 0.0001110000 |
| freeing items | 0.000093 | 0.01 | 1 | 0.0000930000 |
| statistics | 0.000092 | 0.01 | 1 | 0.0000920000 |
| System lock | 0.000065 | 0.00 | 1 | 0.0000650000 |
| query end | 0.000049 | 0.00 | 1 | 0.0000490000 |
| checking permissions | 0.000036 | 0.00 | 1 | 0.0000360000 |
| preparing | 0.000035 | 0.00 | 1 | 0.0000350000 |
| init | 0.000031 | 0.00 | 1 | 0.0000310000 |
| Executing hook on transaction | 0.000028 | 0.00 | 1 | 0.0000280000 |
| optimizing | 0.000017 | 0.00 | 1 | 0.0000170000 |
+--------------------------------+----------+-------+-------+--------------+
16 rows in set, 2 warnings (0.00 sec)

Прочие полезные запросы
Топ 5 наиболее ожидающих событий:
USE performance_schema;
SELECT event_name, count_star, sum_timer_wait
FROM events_waits_summary_global_by_event_name
ORDER BY sum_timer_wait DESC LIMIT 5;

Просмотр количества и статуса соединений
Пример запроса:
mysql -e 'SHOW PROCESSLIST\G' | grep State: | sort | uniq -c | sort -rn
13 State:
1 State: Statistics
1 State: starting
1 State: Removing tmp table

Просмотр системных вызовов
Пример через использование утилиты strace:
strace -cfp $(ps -aux | grep mysql | sort -n -k2 | head -1 | awk '{print $2}')
% time seconds usecs/call calls errors syscall
------ ------------ ----------- --------- --------- ----------------
85.33 10068.862742 45886 219431 85910 futex
13.78 1626.519545 1936332 840 3 restart_syscall
0.31 36.813443 256 143542 7918 recvfrom
0.24 28.340167 3170 8938 poll
0.15 17.731151 252 70262 sendto
0.09 10.112097 264 38223 write
0.02 2.493544 243 10220 7838 accept4
0.01 1.471888 264 5572 close
0.01 1.229645 247 4967 newfstatat
0.01 1.216571 255 4768 2378 setsockopt
0.01 0.964758 273 3533 openat
0.01 0.771205 247 3111 pwrite64
0.01 0.725829 269 2697 gettid
0.01 0.641206 269 2382 fcntl
0.00 0.569502 268 2124 pread64
0.00 0.558424 263 2120 lseek
0.00 0.408002 288 1412 unlink
0.00 0.384237 272 1412 1412 readlink
0.00 0.191087 270 706 getpid
0.00 0.167809 247 677 677 access
0.00 0.044779 476 94 fdatasync
0.00 0.000393 196 2 sched_yield
0.00 0.000219 219 1 read
0.00 0.000203 50 4 getpeername
0.00 0.000074 74 1 rt_sigprocmask
0.00 0.000047 47 1 madvise
------ ------------ ----------- --------- --------- ----------------
100.00 11800.218567 22389 527040 106136 total

На этом я завершаю конспект того, как выполняется профилирование нагрузки сервера MySQL.
Ссылки на другие статьи этого цикла
Часть 1. Тестирование производительности MySQL.
Часть 3. Базовая конфигурация и оптимизация настроек MySQL.
Часть 4. Признаки проблем с производительностью MySQL
Часть 5. Полезные запросы для MySQL.