Статьи

Профилирование MySQL-запросов из схемы производительности

[Эта статья была написана Jarvin Real]

При оптимизации запросов и изучении проблем с производительностью MySQL поставляется со встроенной поддержкой профилирования запросов aka SET profiling = 1; , Это уже потрясающе и просто в использовании, но почему альтернатива PERFORMANCE_SCHEMA?

Поскольку профилирование будет скоро удалено (уже не рекомендуется в MySQL 5.6 и 5.7); встроенная возможность профилирования может быть включена только для сеанса. Это означает, что вы не можете получить информацию о профилировании для запросов, выполняемых из других соединений. Если вы используете Percona Server,   опция профилирования для log_slow_verbosity  является хорошей альтернативой, к сожалению, не все используют Percona Server.

Теперь для быстрой демонстрации: я выполняю простой запрос и профилирую его ниже. Обратите внимание, что все эти команды выполняются от одного сеанса до моего тестового экземпляра.

mysql> SHOW PROFILES;
+----------+------------+----------------------------------------+
| Query_ID | Duration   | Query                                  |
+----------+------------+----------------------------------------+
|        1 | 0.00011150 | SELECT * FROM sysbench.sbtest1 LIMIT 1 |
+----------+------------+----------------------------------------+
1 row in set, 1 warning (0.00 sec)
mysql> SHOW PROFILE SOURCE FOR QUERY 1;
+----------------------+----------+-----------------------+------------------+-------------+
| Status               | Duration | Source_function       | Source_file      | Source_line |
+----------------------+----------+-----------------------+------------------+-------------+
| starting             | 0.000017 | NULL                  | NULL             |        NULL |
| checking permissions | 0.000003 | check_access          | sql_parse.cc     |        5797 |
| Opening tables       | 0.000021 | open_tables           | sql_base.cc      |        5156 |
| init                 | 0.000009 | mysql_prepare_select  | sql_select.cc    |        1050 |
| System lock          | 0.000005 | mysql_lock_tables     | lock.cc          |         306 |
| optimizing           | 0.000002 | optimize              | sql_optimizer.cc |         138 |
| statistics           | 0.000006 | optimize              | sql_optimizer.cc |         381 |
| preparing            | 0.000005 | optimize              | sql_optimizer.cc |         504 |
| executing            | 0.000001 | exec                  | sql_executor.cc  |         110 |
| Sending data         | 0.000025 | exec                  | sql_executor.cc  |         190 |
| end                  | 0.000002 | mysql_execute_select  | sql_select.cc    |        1105 |
| query end            | 0.000003 | mysql_execute_command | sql_parse.cc     |        5465 |
| closing tables       | 0.000004 | mysql_execute_command | sql_parse.cc     |        5544 |
| freeing items        | 0.000005 | mysql_parse           | sql_parse.cc     |        6969 |
| cleaning up          | 0.000006 | dispatch_command      | sql_parse.cc     |        1874 |
+----------------------+----------+-----------------------+------------------+-------------+
15 rows in set, 1 warning (0.00 sec)

Чтобы продемонстрировать, как мы можем достичь того же с помощью Performance Schema, мы сначала идентифицируем наш текущий идентификатор соединения. В реальном мире вам может потребоваться получить идентификатор соединения / списка процессов для потока, который вы хотите просмотреть, например, из SHOW PROCESSLIST.

mysql> SELECT THREAD_ID INTO @my_thread_id
    -> FROM threads WHERE PROCESSLIST_ID = CONNECTION_ID();
Query OK, 1 row affected (0.00 sec)

Далее мы идентифицируем ограничивающие EVENT_ID для этапов выписки. Мы будем искать оператор, который мы хотели профилировать, используя запрос ниже из таблицы events_statements_history_long. Предложение LIMIT может варьироваться в зависимости от того, сколько запросов может получать сервер.

mysql> SELECT THREAD_ID, EVENT_ID, END_EVENT_ID, SQL_TEXT, NESTING_EVENT_ID
    -> FROM events_statements_history_long
    -> WHERE THREAD_ID = @my_thread_id
    ->   AND EVENT_NAME = 'statement/sql/select'
    -> ORDER BY EVENT_ID DESC LIMIT 3 G
*************************** 1. row ***************************
       THREAD_ID: 13848
        EVENT_ID: 419
    END_EVENT_ID: 434
        SQL_TEXT: SELECT THREAD_ID INTO @my_thread_id
FROM threads WHERE PROCESSLIST_ID = CONNECTION_ID()
NESTING_EVENT_ID: NULL
*************************** 2. row ***************************
       THREAD_ID: 13848
        EVENT_ID: 374
    END_EVENT_ID: 392
        SQL_TEXT: SELECT * FROM sysbench.sbtest1 LIMIT 1
NESTING_EVENT_ID: NULL
*************************** 3. row ***************************
       THREAD_ID: 13848
        EVENT_ID: 353
    END_EVENT_ID: 364
        SQL_TEXT: select @@version_comment limit 1
NESTING_EVENT_ID: NULL
3 rows in set (0.02 sec)

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

mysql> SELECT EVENT_NAME, SOURCE, (TIMER_END-TIMER_START)/1000000000 as 'DURATION (ms)'
    -> FROM events_stages_history_long
    -> WHERE THREAD_ID = @my_thread_id AND EVENT_ID BETWEEN 374 AND 392;
+--------------------------------+----------------------+---------------+
| EVENT_NAME                     | SOURCE               | DURATION (ms) |
+--------------------------------+----------------------+---------------+
| stage/sql/init                 | mysqld.cc:998        |        0.0214 |
| stage/sql/checking permissions | sql_parse.cc:5797    |        0.0023 |
| stage/sql/Opening tables       | sql_base.cc:5156     |        0.0205 |
| stage/sql/init                 | sql_select.cc:1050   |        0.0089 |
| stage/sql/System lock          | lock.cc:306          |        0.0047 |
| stage/sql/optimizing           | sql_optimizer.cc:138 |        0.0016 |
| stage/sql/statistics           | sql_optimizer.cc:381 |        0.0058 |
| stage/sql/preparing            | sql_optimizer.cc:504 |        0.0044 |
| stage/sql/executing            | sql_executor.cc:110  |        0.0008 |
| stage/sql/Sending data         | sql_executor.cc:190  |        0.0251 |
| stage/sql/end                  | sql_select.cc:1105   |        0.0017 |
| stage/sql/query end            | sql_parse.cc:5465    |        0.0031 |
| stage/sql/closing tables       | sql_parse.cc:5544    |        0.0037 |
| stage/sql/freeing items        | sql_parse.cc:6969    |        0.0056 |
| stage/sql/cleaning up          | sql_parse.cc:1874    |        0.0006 |
+--------------------------------+----------------------+---------------+
15 rows in set (0.01 sec)

Как вы можете видеть, результаты довольно близки, не совсем то же самое, но близко. SHOW PROFILE показывает продолжительность в секундах, а приведенные выше результаты в миллисекундах.

Некоторые ограничения этого метода, хотя:

  • Как мы уже видели, требуется несколько обручей, чтобы собрать нужную нам информацию. Поскольку нам нужно идентифицировать оператор, который мы должны профилировать вручную, эту процедуру может быть нелегко портировать на такие инструменты, как схема sys или pstop.
  • Возможно, только если включена Performance Performance Schema (по умолчанию она включена с MySQL 5.6.6, ууу!)
  • Не охватывает все показатели по сравнению с собственным профилированием, т.е. КОНТЕКСТНЫЕ ПЕРЕКЛЮЧАТЕЛИ, БЛОКИРОВКА, СВОП
  • В зависимости от того, насколько загружен сервер, на котором вы запускаете тесты, размеры таблиц истории могут быть слишком маленькими, поэтому вам придется либо увеличивать, либо терять историю до ранней переменной ieperformance_schema_events_stages_history_long_size. Использование  ps_history  может помочь в этом случае, хотя с небольшой модификацией запросов.
  • Результирующая длительность на событие может варьироваться, я думаю, это может быть связано с дополнительным, как описано в таблице performance_timers. В любом случае мы надеемся  исправить это как результат, когда эта ошибка будет исправлена.