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';