Оптимизация MySQL сервера. Часть 2. Профилирование нагрузки сервера MySQL

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

Эта публикация сугубо мой конспект прочитанной литературы. Информация может быть не очень структурирована и удобочитаема. Материал публикации предоставляется без каких-либо гарантий со стороны автора.

Список первоисточников

  1. 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.

Часть 6. Нюансы настройки репликации MySQL.

Часть 7. Резервное копирование MySQL.

Добавить комментарий

Ваш адрес email не будет опубликован. Обязательные поля помечены *