MySQLで低速クエリを特定する

完全なプロセスリストの表示

MySQLの処理スレッドが実行しているすべての現在の操作を表示するには、次のように入力します

SHOW FULL PROCESSLIST;

 +----+-----------------+-----------+------+---------+---------+------------------------+-----------------------+
 | Id | User            | Host      | db   | Command | Time    | State                  | Info                  |
 +----+-----------------+-----------+------+---------+---------+------------------------+-----------------------+
 |  5 | event_scheduler | localhost | NULL | Daemon  | 1834441 | Waiting on empty queue | NULL                  |
 | 50 | root            | localhost | NULL | Query   |       0 | init                   | show full processlist |
 +----+-----------------+-----------+------+---------+---------+------------------------+-----------------------+
 2 rows in set (0.00 sec)

上記の出力は、アイドル状態のサーバーで、私たちのクエリと長時間実行されているイベントリスナーのみが表示されています。アクティブなサーバーでは、より多くのプロセスが表示され、その中には長時間実行されているものもあるかもしれません。FULL修飾子がない場合、このコマンドは最初の100プロセスのみを表示し、サーバーのアクティビティによっては結果が切り捨てられる可能性があります。

TimeとStateの列が特に重要です。Time列は、スレッドが記載されているStateにあった秒数を数えます。特定の操作に対する期待と一致しないTime値のプロセスを見つけた場合、さらに調査する時かもしれません。

ストレージエンジンの状態確認

もう1つ確認する場所は、実際のストレージエンジンの状態です。

特定のテーブルに関連付けられているストレージエンジンは、次のように入力して見つけることができます。

SHOW CREATE TABLE <database>.<table>\G

たとえば、mysql.time_zoneテーブルが使用しているストレージエンジンを表示するには、次のように入力します。

SHOW CREATE TABLE mysql.time_zone`\G

*************************** 1. row ***************************
       Table: time_zone
Create Table: CREATE TABLE `time_zone` (
  `Time_zone_id` int unsigned NOT NULL AUTO_INCREMENT,
  `Use_leap_seconds` enum('Y','N') CHARACTER SET utf8 COLLATE utf8_general_ci NOT NULL DEFAULT 'N',
  PRIMARY KEY (`Time_zone_id`)
) /*!50100 TABLESPACE `mysql` */ ENGINE=InnoDB DEFAULT CHARSET=utf8mb3 STATS_PERSISTENT=0 ROW_FORMAT=DYNAMIC COMMENT='Time zones'
1 row in set (0.01 sec)

ENGINE=InnoDBは、テーブルがInnoDBストレージエンジンを使用していることを示します。これはほとんどの設定でデフォルトのストレージエンジンなので、その状態を確認したいと思うでしょう。

InnoDBエンジンの状態を表示するには、次のように入力します。

SHOW ENGINE INNODB STATUS\G

 *************************** 1. row ***************************
   Type: InnoDB
   Name:
 Status:
 =====================================
 2022-02-26 11:55:52 139992513984256 INNODB MONITOR OUTPUT
 =====================================
 Per second averages calculated from the last 16 seconds
 -----------------
 BACKGROUND THREAD
 -----------------
 srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 1835091 srv_idle
 srv_master_thread log flush and writes: 0
 ----------
 SEMAPHORES
 ----------
 OS WAIT ARRAY INFO: reservation count 555
 OS WAIT ARRAY INFO: signal count 457
 RW-shared spins 0, rounds 0, OS waits 0
 RW-excl spins 0, rounds 0, OS waits 0
 RW-sx spins 0, rounds 0, OS waits 0
 Spin rounds per wait: 0.00 RW-shared, 0.00 RW-excl, 0.00 RW-sx
 ------------
 TRANSACTIONS
 ------------
 Trx id counter 8778
 Purge done for trx's n:o < 8713 undo n:o < 0 state: running but idle
 History list length 0
 LIST OF TRANSACTIONS FOR EACH SESSION:
 ---TRANSACTION 421467955133656, not started
 0 lock struct(s), heap size 1128, 0 row lock(s)
 ---TRANSACTION 421467955132848, not started
 0 lock struct(s), heap size 1128, 0 row lock(s)
 ---TRANSACTION 421467955132040, not started
 0 lock struct(s), heap size 1128, 0 row lock(s)
 --------
 FILE I/O
 --------
 I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
 I/O thread 1 state: waiting for completed aio requests (log thread)
 I/O thread 2 state: waiting for completed aio requests (read thread)
 I/O thread 3 state: waiting for completed aio requests (read thread)
 I/O thread 4 state: waiting for completed aio requests (read thread)
 I/O thread 5 state: waiting for completed aio requests (read thread)
 I/O thread 6 state: waiting for completed aio requests (write thread)
 I/O thread 7 state: waiting for completed aio requests (write thread)
 I/O thread 8 state: waiting for completed aio requests (write thread)
 I/O thread 9 state: waiting for completed aio requests (write thread)
 Pending normal aio reads: [0, 0, 0, 0] , aio writes: [0, 0, 0, 0] ,
  ibuf aio reads:, log i/o's:, sync i/o's:
 Pending flushes (fsync) log: 0; buffer pool: 0
 1779 OS file reads, 3384 OS file writes, 1870 OS fsyncs
 0.00 reads/s, 0 avg bytes/read, 0.00 writes/s, 0.00 fsyncs/s
 -------------------------------------
 INSERT BUFFER AND ADAPTIVE HASH INDEX
 -------------------------------------
 Ibuf: size 1, free list len 0, seg size 2, 0 merges
 merged operations:
  insert 0, delete mark 0, delete 0
 discarded operations:
  insert 0, delete mark 0, delete 0
 Hash table size 34679, node heap has 2 buffer(s)
 Hash table size 34679, node heap has 9 buffer(s)
 Hash table size 34679, node heap has 9 buffer(s)
 Hash table size 34679, node heap has 15 buffer(s)
 Hash table size 34679, node heap has 7 buffer(s)
 Hash table size 34679, node heap has 3 buffer(s)
 Hash table size 34679, node heap has 4 buffer(s)
 Hash table size 34679, node heap has 6 buffer(s)
 0.00 hash searches/s, 0.00 non-hash searches/s
 ---
 LOG
 ---
 Log sequence number          38540718
 Log buffer assigned up to    38540718
 Log buffer completed up to   38540718
 Log written up to            38540718
 Log flushed up to            38540718
 Added dirty pages up to      38540718
 Pages flushed up to          38540718
 Last checkpoint at           38540718
 2197 log i/o's done, 0.00 log i/o's/second
 ----------------------
 BUFFER POOL AND MEMORY
 ----------------------
 Total large memory allocated 0
 Dictionary memory allocated 473011
 Buffer pool size   8192
 Free buffers       6241
 Database pages     1896
 Old database pages 719
 Modified db pages  0
 Pending reads      0
 Pending writes: LRU 0, flush list 0, single page 0
 Pages made young 8, not young 0
 0.00 youngs/s, 0.00 non-youngs/s
 Pages read 1754, created 142, written 926
 0.00 reads/s, 0.00 creates/s, 0.00 writes/s
 No buffer pool page gets since the last printout
 Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 LRU len: 1896, unzip_LRU len: 0
 I/O sum[0]:cur[0], unzip sum[0]:cur[0]
 --------------
 ROW OPERATIONS
 --------------
 0 queries inside InnoDB, 0 queries in queue
 0 read views open inside InnoDB
 Process ID=59529, Main thread ID=139992560166656 , state=sleeping
 Number of rows inserted 0, updated 0, deleted 0, read 0
 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
 Number of system rows inserted 0, updated 317, deleted 0, read 6128
 0.00 inserts/s, 0.00 updates/s, 0.00 deletes/s, 0.00 reads/s
 ----------------------------
 END OF INNODB MONITOR OUTPUT
 ============================

 1 row in set (0.00 sec)

出力には、エンジンが使用しているリソース、実行されているプロセスなど、大量の情報が含まれます。これを使用して、実行にボトルネックがあるかどうか、または競合するプロセスの数がパフォーマンスの問題を引き起こしているかどうかを把握できます。

MySQLが低速クエリをログに記録しているか確認する

最初に行うべきことは、低速クエリロギングの現在の状態を確認することです。低速クエリロギングがすでに有効になっている場合は、何もする必要はありません。

低速クエリロギングが有効になっているかどうかは、次のように入力して確認できます。

SHOW GLOBAL VARIABLES LIKE 'slow_query_log%';

 +---------------------+------------------------------------+
 | Variable_name       | Value                              |
 +---------------------+------------------------------------+
 | slow_query_log      | OFF                                |
 | slow_query_log_file | /var/lib/mysql/mysqlutils-slow.log |
 +---------------------+------------------------------------+
 2 rows in set (0.01 sec)

上記の出力は、機能がオフになっているため、低速クエリが現在ログに記録されていないことを示しています。

低速クエリロギングがオンの場合、出力は次のようになります。

 +---------------------+-------------------------------+
 | Variable_name       | Value                         |
 +---------------------+-------------------------------+
 | slow_query_log      | ON                            |
 | slow_query_log_file | /var/log/mysql/mysql-slow.log |
 +---------------------+-------------------------------+
 2 rows in set (0.02 sec)

現在の状態がわかったので、必要に応じて変更できます。

MySQLが低速クエリをログに記録するように構成する

先に進む前に、低速クエリロギングは非常に便利ですが、追加のパフォーマンス影響をもたらす可能性があることに注意することが重要です。MySQLは、各クエリの時間を測定し、その結果をログに記録するために追加の操作を実行する必要があります。これにより、パフォーマンスに影響を与えたり、予期せずハードディスクのスペースを占有したりする可能性があります。

低速クエリを常にログに記録するのは良い考えではないかもしれません。代わりに、問題を積極的に調査しているときに機能を有効にし、終了したら無効にしてください。

そのことを念頭に置いて、MySQLサーバーの構成ファイルを変更することで低速クエリロギングを構成できます。これらの値を対話的に変更することもできますが、構成で適切なデフォルトを設定しておくと、後で対話的に微調整しやすくなります。

MySQLの構成ファイルを開きます。ほとんどのDebian Linuxベースのシステムでは、構成ファイルは/etc/mysql/mysql.conf.d/mysqld.confにあります。

sudo vim /etc/mysql/mysql.conf.d/mysqld.conf

以下の設定を変更または追加する必要があります。

したがって、たとえば、すべてのオプションロギングをオンにし、少なくとも100行を調べ、実行に2秒以上かかるすべてのステートメントをログに記録したい場合は、これらの設定を使用できます。

; enable MySQL to log slow queries
slow_query_log                  = ON
; query log location
slow_query_log_file             = /var/log/mysql/mysql-slow.log
; amount of seconds that a query must surpass to be logged
long_query_time                 = 2
; minimum number of rows affected for a query to be logged
min_examined_row_limit          = 100

; include administrative commands in the logs
log_slow_admin_statements       = ON
; also log queries that are not using indexes
log_queries_not_using_indexes   = ON
; for MySQL servers version 8.0.14 or later, we can
; get extra information by setting this
log_slow_extra                  = ON
; Also log slow statements that have executed on
; the replica
; This only will log statements if `binlog_format` is
; set to `STATEMENT` or `MIXED` and the statement is
; logged in statement format
; RE: https://dev.mysql.com/doc/refman/8.0/en/replication-options-replica.html#sysvar_log_slow_replica_statements
; This option name depends on your MySQL version:
;   versions >= 8.0.26: log_slow_replica_statements
;   versions < 8.0.26: log_slow_slave_statements
; log_slow_slave_statements   = ON
log_slow_replica_statements   = ON

ファイルを保存して閉じたら、次のように入力して構成の変更を検証できます。

sudo mysqld --validate-config

エラーが返されない場合、MySQLサーバーの構成ファイルは構文的に有効です。次のように入力してMySQLサーバープロセスを再起動できます。

sudo systemctl restart mysql

元の検出クエリを再実行して、低速クエリが有効になっていることを検証できます。

SHOW GLOBAL VARIABLES LIKE 'slow_query_log%';

低速クエリの設定が完了したら、MySQL自体で必要に応じて有効/無効を切り替えることができます。値を調整するための構文は次のようになります。

SET GLOBAL slow_query_log = 'OFF';