とある日

自分がDBAだとして、たった一つだけ監視できるなら何？ってなった時の話をDBRE本の輪読会でしていた。
— あわっち (@_awache) 2021年6月8日

リプに、知らない監視方法があったので調べてみます。

今回は、3つほどピックアップして調べて見ます。

slowquery
SHOW FULL PROCESSLIST
SHOW ENGINE INNODB STATUS

はじめに

検証環境

Windows 10 Home
Docker Desktop for Windows
Debian GNU/Linux
MySQL 8.0.24

基本的に、MySQLをもとに内容を作成しています。

元ツイート補足

ツイート内容の、DBRE本と輪読会について補足情報を記述します。

データベースリライアビリティエンジニアリング ――回復力のあるデータベースシステムの設計と運用

DBRE本と言われていた、オライリー・ジャパンから出ているそ書籍で、最近日本語化して発売しました。

データベースリライアビリティエンジニアリング ―回復力のあるデータベースシステムの設計と運用

Amazon

まだ二章しか読んでないですが、DBをより深く広く考えるようときに参考になる良い書籍だと思います。

DBRE

DBREについて気になるかはご参考にして下さい。

Database Reliability Engineering (DBRE) 日本語にすると「データベース信頼性エンジニアリング」となります。

DBREJP

DBRE本の輪読会についての情報はこのSlackのワークスペースでやりとりされています。

自分は参加したことないですが、過去の記録とかもありますのでご興味のある方はご覧ください。

DBRE本読書メモ

Database Reliability Engineering Japan
DBREJP、始動します！
これからDBをやってみたいな、という方。
DBA長年やってるけど、REってどんなことするのかな？という方。
広く、浅く、そしてゆるーく！
みんなで「DBREって何をするのか」考える会、気軽に参加してください♬https://t.co/9XYZkn4Q76
— tomo 𖠚ᐝ (@tomomo1015) 2020年8月10日

slowquery

ちなみに僕はslowqueryでした。
理由は色々あるんですが
- DBの死活はサービスの死活で気づきやすいけど、ユーザーの使いづらさ的なものは分からない
って思っているからなんだろうな、とか
— あわっち (@_awache) 2021年6月9日

自分も一番最初は、slowqueryが出てきました。

概要

遅いSQLにフォーカスして監視することができます。

5.4.5 スロークエリーログ

スロークエリーログは、実行に long_query_time 秒を超える時間がかかり、少なくとも min_examined_row_limit 行を検査する必要がある SQL ステートメントで構成されます。スロークエリーログは、実行に長い時間がかかっているため最適化の候補となるクエリーを見つけるために使用できます。

MySQLチューニングの基本「スロークエリログ」を知ろう！ |

検証

擬似的に遅いSQLを実行してスロークエリとしてログが残っているかを確認します。

slowquery設定

MySQLだとデフォルトだと設定がオフになっているのでオンにしてスロークエリログを残します。

mysql> show variables like 'slow_query%';
+---------------------+--------------------------------------+
+---------------------+--------------------------------------+
| slow_query_log      | OFF                                  |
+---------------------+--------------------------------------+

mysql>  show variables like 'long%';
+-----------------+-----------+
| Variable_name   | Value     |
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.01 sec)

mysql> set global slow_query_log_file='/tmp/slow.log';
Query OK, 0 rows affected (0.01 sec)

mysql> set global long_query_time=1;
Query OK, 0 rows affected (0.00 sec)

mysql> exit
Bye
root@6438500bc2d7:/# vi /etc/mysql/my.cnf
root@6438500bc2d7:/# tail -n 3 /etc/mysql/my.cnf
slow_query_log=1
slow_query_log_file=/tmp/slow.log
long_query_time=1
root@6438500bc2d7:/# exit
exit

Docker再起動。

SQL実行確認

設定したスロークエリログファイルにselect sleep(3);が記録されているかを確認。

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.01 sec)

mysql> exit
Bye
root@6438500bc2d7:/# cat /tmp/slow.log
/usr/sbin/mysqld, Version: 8.0.24 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
/usr/sbin/mysqld, Version: 8.0.24 (MySQL Community Server - GPL). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2021-06-09T22:38:37.046822Z
# User@Host: root[root] @ localhost []  Id:     8
# Query_time: 3.008698  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1623278314;
select sleep(3);

SHOW FULL PROCESSLIST

俺はSHOW FULL PROCESSLISTですかね。「今」を観測したいので！
— yoku0825 (@yoku0825) 2021年6月9日

接続をしっぱなしにしているとここの記録に残ってる。

なんか接続できないなと思ったときには、このコマンドで確認している。

確かに、今を監視するのに丁度いい監視方法だと思いました。

SHOW PROCESSLIST ステートメントは、「接続が多すぎます」というエラーメッセージが表示されるために、何が発生しているかを突き止めたい場合に非常に役立ちます。

概要

プロセスにフォーカスした監視ができます。

13.7.7.29 SHOW PROCESSLIST ステートメント

sql SHOW [FULL] PROCESSLIST

MySQL プロセスリストには、サーバー内で実行されているスレッドのセットによって現在実行されている操作が示されます。 SHOW PROCESSLIST ステートメントは、プロセス情報のソースです。このステートメントと他のソースの比較については、プロセス情報のソースを参照してください。

検証

特に問題のあるスレッドがないので自分の環境だとなにもない。

mysql> SHOW FULL PROCESSLIST\G;
*************************** 1. row ***************************
     Id: 5
   User: event_scheduler
   Host: localhost
     db: NULL
Command: Daemon
   Time: 214
  State: Waiting on empty queue
   Info: NULL
*************************** 2. row ***************************
     Id: 9
   User: root
   Host: localhost
     db: NULL
Command: Query
   Time: 0
  State: init
   Info: SHOW FULL PROCESSLIST
2 rows in set (0.00 sec)

ERROR:
No query specified

SHOW ENGINE INNODB STATUS

SHOW ENGINE INNODB STATUS ...（Q「無人島に１人だけ連れて行くなら誰？」A「ドラえもん！」、みたいな回答
— atsuizo (@atsuizo) 2021年6月9日

SHOW ENGINE INNODB STATUS は元ツイートのDBA監視というところに焦点を当てるならその機能を提供してそうな感じがしている文章がありました。

このステートメントは、さまざまなパフォーマンススキーマオプションがメモリー要件に与える効果について、DBA が理解できるようにすることを目的としています。

概要

エンジンにフォーカスした監視ができます。

13.7.7.15 SHOW ENGINE ステートメント

sql SHOW ENGINE engine_name {STATUS | MUTEX}

SHOW ENGINE は、ストレージエンジンに関する動作情報を表示します。

sql SHOW ENGINE INNODB STATUS SHOW ENGINE INNODB MUTEX SHOW ENGINE PERFORMANCE_SCHEMA STATUS

SHOW ENGINE INNODB STATUS は、InnoDB ストレージエンジンの状態に関する InnoDB 標準モニターからの広範囲にわたる情報を表示します。

検証

見やすい整形したデータが出力されました。

ただ、特に操作していないMySQLなので変わったデータや障害になりそうなポイントは見当たらないと思います。

mysql> SHOW ENGINE INNODB STATUs\G;
*************************** 1. row ***************************
  Type: InnoDB
  Name:
Status:
=====================================
2021-06-17 08:40:18 139996547479296 INNODB MONITOR OUTPUT
=====================================
Per second averages calculated from the last 4 seconds
-----------------
BACKGROUND THREAD
-----------------
srv_master_thread loops: 1 srv_active, 0 srv_shutdown, 28 srv_idle
srv_master_thread log flush and writes: 0
----------
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 14
OS WAIT ARRAY INFO: signal count 14
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 10249
Purge done for trx's n:o < 10246 undo n:o < 0 state: running but idle
History list length 3
LIST OF TRANSACTIONS FOR EACH SESSION:
---TRANSACTION 421471651728792, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421471651727936, not started
0 lock struct(s), heap size 1136, 0 row lock(s)
---TRANSACTION 421471651727080, not started
0 lock struct(s), heap size 1136, 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
1406 OS file reads, 192 OS file writes, 31 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 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 0 buffer(s)
Hash table size 34679, node heap has 1 buffer(s)
Hash table size 34679, node heap has 3 buffer(s)
0.00 hash searches/s, 0.00 non-hash searches/s
---
LOG
---
Log sequence number          29197592
Log buffer assigned up to    29197592
Log buffer completed up to   29197592
Log written up to            29197592
Log flushed up to            29197592
Added dirty pages up to      29197592
Pages flushed up to          29197592
Last checkpoint at           29197592
11 log i/o's done, 0.00 log i/o's/second
----------------------
BUFFER POOL AND MEMORY
----------------------
Total large memory allocated 137035776
Dictionary memory allocated 382389
Buffer pool size   8192
Free buffers       7194
Database pages     994
Old database pages 386
Modified db pages  0
Pending reads      0
Pending writes: LRU 0, flush list 0, single page 0
Pages made young 0, not young 0
0.00 youngs/s, 0.00 non-youngs/s
Pages read 852, created 142, written 155
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: 994, 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=1, Main thread ID=139996175787776 , 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 315, deleted 0, read 4677
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)

〆

アプリケーションが順調に動作しているかを監視する場合はslowqueryをチェックするイメージ。

SQL開発が順調に進んでいるかを監視する場合はSHOW FULL PROCESSLISTをチェックするイメージ。

データベースサーバーが順調に動作しているかを監視する場合はSHOW ENGINE INNODB STATUSをチェックするイメージ。

この3つの中で、まともに使ったことあるのは、SHOW FULL PROCESSLISTぐらいなので、あまり詳しい解説はできませんがこれからもっと勉強しようと思います。

本当ならどれか一つではなく、それらを全てをしっかりと監視するのが一番いいのかなと思いました。

そういった監視のこともDBREの本に書かれていると思うので楽しみです。

今回のツイートは、DBのことを更にしれたのでとても面白かったです。

今日はなにの日。

気になったこと勉強になったことのメモ。

今日は、DBAとしてたった一つだけ監視するならの日。

目次