パフォーマンスの問題は、MySQLデータベースを管理する際の一般的な問題です。実際、これらの問題はクエリが遅いことが原因である場合があります。このブログでは、遅いクエリとそれらを識別する方法を扱います。
MySQLには、遅いクエリをフィルタリングしてログに記録する機能があります。これらを調査するにはさまざまな方法がありますが、最も一般的で効率的な方法は、低速のクエリログを使用することです。
最初に、低速クエリログが有効になっているかどうかを確認する必要があります。これに対処するには、サーバーにアクセスして次の変数をクエリします。
MariaDB [(none)]> show global variables like 'slow%log%';
+---------------------+-------------------------------+
| Variable_name | Value |
+---------------------+-------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /var/log/mysql/mysql-slow.log |
+---------------------+-------------------------------+
2 rows in set (0.001 sec)変数slow_query_logがONに設定されていることを確認する必要があります。一方、slow_query_log_fileは、低速クエリログを配置する必要があるパスを決定します。この変数が設定されていない場合、MySQLデータディレクトリのDATA_DIRが使用されます。
slow_query_log変数には、遅いクエリログの動作に影響を与えるlong_query_timeとmin_examined_row_limitが伴います。基本的に、低速のクエリログはSQLステートメントとして機能し、実行にlong_query_time秒以上かかり、少なくともmin_examined_row_limit行を検査する必要があります。実行に時間がかかり、最適化の候補となるクエリを見つけるために使用できます。次に、外部ツールを使用してレポートを取得できます。これについては後で説明します。
デフォルトでは、管理ステートメント（ALTER TABLE、ANALYZE TABLE、CHECK TABLE、CREATE INDEX、DROP INDEX、OPTIMIZE TABLE、およびREPAIR TABLE）は遅いクエリログに分類されません。これを行うには、変数log_slow_admin_statementsを有効にする必要があります。
通常のDBAルーチンでは、この手順は、パフォーマンスの低下を引き起こす長時間実行クエリまたはアクティブ実行クエリを特定するための最も一般的な方法です。実行中のクエリでカバーされているロックが原因で、サーバーがスタックし、キューが積み重なってゆっくりと増加する場合もあります。実行するだけです
SHOW [FULL] PROCESSLIST;SHOW ENGINE INNODB STATUS \G ClusterControlを使用している場合は、
または
遅いクエリログには、前述のシステム変数の指定された値に基づいて、遅いと識別されたクエリのリストが表示されます。遅いクエリの定義は、10秒のクエリでも受け入れられ、それでも遅くない場合があるため、場合によって異なる場合があります。ただし、アプリケーションがOLTPの場合、10秒または5秒のクエリが問題になるか、データベースのパフォーマンスが低下することがよくあります。 MySQLクエリログはこれに役立ちますが、ログファイルを開くだけでは不十分です。これらのクエリの概要、実行方法、および発生頻度が提供されないためです。したがって、サードパーティのツールがこれらを支援します。
pt-query-digest
最も一般的なDBAツールと言えるPerconaToolkitの使用は、pt-query-digestを使用することです。 pt-query-digestは、遅いクエリログからの特定のレポートの概要を提供します。たとえば、この特定のレポートは、特定のノードの低速クエリレポートを理解するための明確な視点を示しています。
# A software update is available:
# 100ms user time, 100ms system time, 29.12M rss, 242.41M vsz
# Current date: Mon Feb 3 20:26:11 2020
# Hostname: testnode7
# Files: /var/log/mysql/mysql-slow.log
# Overall: 24 total, 14 unique, 0.00 QPS, 0.02x concurrency ______________
# Time range: 2019-12-12T10:01:16 to 2019-12-12T15:31:46
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 345s 1s 98s 14s 30s 19s 7s
# Lock time 1s 0 1s 58ms 24ms 252ms 786us
# Rows sent 5.72M 0 1.91M 244.14k 1.86M 629.44k 0
# Rows examine 15.26M 0 1.91M 651.23k 1.86M 710.58k 961.27k
# Rows affecte 9.54M 0 1.91M 406.90k 961.27k 546.96k 0
# Bytes sent 305.81M 11 124.83M 12.74M 87.73M 33.48M 56.92
# Query size 1.20k 25 244 51.17 59.77 40.60 38.53
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== ================================ ============= ===== ======= =====
# 1 0x00C8412332B2795DADF0E55C163... 98.0337 28.4% 1 98.0337 0.00 UPDATE sbtest?
# 2 0xDEF289292EA9B2602DC12F70C7A... 74.1314 21.5% 3 24.7105 6.34 ALTER TABLE sbtest? sbtest3
# 3 0x148D575F62575A20AB9E67E41C3... 37.3039 10.8% 6 6.2173 0.23 INSERT SELECT sbtest? sbtest
# 4 0xD76A930681F1B4CC9F748B4398B... 32.8019 9.5% 3 10.9340 4.24 SELECT sbtest?
# 5 0x7B9A47FF6967FD905289042DD3B... 20.6685 6.0% 1 20.6685 0.00 ALTER TABLE sbtest? sbtest3
# 6 0xD1834E96EEFF8AC871D51192D8F... 19.0787 5.5% 1 19.0787 0.00 CREATE
# 7 0x2112E77F825903ED18028C7EA76... 18.7133 5.4% 1 18.7133 0.00 ALTER TABLE sbtest? sbtest3
# 8 0xC37F2569578627487D948026820... 15.0177 4.3% 2 7.5088 0.00 INSERT SELECT sbtest? sbtest
# 9 0xDE43B2066A66AFA881D6D45C188... 13.7180 4.0% 1 13.7180 0.00 ALTER TABLE sbtest? sbtest3
# MISC 0xMISC 15.8605 4.6% 5 3.1721 0.0 <5 ITEMS>
# Query 1: 0 QPS, 0x concurrency, ID 0x00C8412332B2795DADF0E55C1631626D at byte 5319
# Scores: V/M = 0.00
# Time range: all events occurred at 2019-12-12T13:23:15
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 4 1
# Exec time 28 98s 98s 98s 98s 98s 0 98s
# Lock time 1 25ms 25ms 25ms 25ms 25ms 0 25ms
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 12 1.91M 1.91M 1.91M 1.91M 1.91M 0 1.91M
# Rows affecte 20 1.91M 1.91M 1.91M 1.91M 1.91M 0 1.91M
# Bytes sent 0 67 67 67 67 67 0 67
# Query size 7 89 89 89 89 89 0 89
# String:
# Databases test
# Hosts localhost
# Last errno 0
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'sbtest3'\G
# SHOW CREATE TABLE `test`.`sbtest3`\G
update sbtest3 set c=substring(MD5(RAND()), -16), pad=substring(MD5(RAND()), -16) where 1\G
# Converted for EXPLAIN
# EXPLAIN /*!50100 PARTITIONS*/
select c=substring(MD5(RAND()), -16), pad=substring(MD5(RAND()), -16) from sbtest3 where 1\G
# Query 2: 0.00 QPS, 0.01x concurrency, ID 0xDEF289292EA9B2602DC12F70C7A041A9 at byte 3775
# Scores: V/M = 6.34
# Time range: 2019-12-12T12:41:47 to 2019-12-12T15:25:14
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 12 3
# Exec time 21 74s 6s 36s 25s 35s 13s 30s
# Lock time 0 13ms 1ms 8ms 4ms 8ms 3ms 3ms
# Rows sent 0 0 0 0 0 0 0 0
# Rows examine 0 0 0 0 0 0 0 0
# Rows affecte 0 0 0 0 0 0 0 0
# Bytes sent 0 144 44 50 48 49.17 3 49.17
# Query size 8 99 33 33 33 33 0 33
# String:
# Databases test
# Hosts localhost
# Last errno 0 (2/66%), 1317 (1/33%)
# Users root
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS FROM `test` LIKE 'sbtest3'\G
# SHOW CREATE TABLE `test`.`sbtest3`\G
ALTER TABLE sbtest3 ENGINE=INNODB\Gperformance_schemaの使用
RDSを使用したり、Google CloudSQLやAzureSQLなどのフルマネージドデータベースサービスを使用したりするなど、ファイルに直接アクセスできない場合は、クエリログが遅いことが問題になる可能性があります。これらの機能を有効にするにはいくつかの変数が必要になる場合がありますが、システムにログインしているクエリをクエリするときに便利です。部分的な結果を取得するために、標準のSQLステートメントを使用して注文できます。たとえば、
mysql> SELECT SCHEMA_NAME, DIGEST, DIGEST_TEXT, COUNT_STAR, SUM_TIMER_WAIT/1000000000000 SUM_TIMER_WAIT_SEC, MIN_TIMER_WAIT/1000000000000 MIN_TIMER_WAIT_SEC, AVG_TIMER_WAIT/1000000000000 AVG_TIMER_WAIT_SEC, MAX_TIMER_WAIT/1000000000000 MAX_TIMER_WAIT_SEC, SUM_LOCK_TIME/1000000000000 SUM_LOCK_TIME_SEC, FIRST_SEEN, LAST_SEEN FROM events_statements_summary_by_digest;
+--------------------+----------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+--------------------+--------------------+--------------------+--------------------+-------------------+---------------------+---------------------+
| SCHEMA_NAME | DIGEST | DIGEST_TEXT | COUNT_STAR | SUM_TIMER_WAIT_SEC | MIN_TIMER_WAIT_SEC | AVG_TIMER_WAIT_SEC | MAX_TIMER_WAIT_SEC | SUM_LOCK_TIME_SEC | FIRST_SEEN | LAST_SEEN |
+--------------------+----------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------+--------------------+--------------------+--------------------+--------------------+-------------------+---------------------+---------------------+
| NULL | 390669f3d1f72317dab6deb40322d119 | SELECT @@`skip_networking` , @@`skip_name_resolve` , @@`have_ssl` = ? , @@`ssl_key` , @@`ssl_ca` , @@`ssl_capath` , @@`ssl_cert` , @@`ssl_cipher` , @@`ssl_crl` , @@`ssl_crlpath` , @@`tls_version` | 1 | 0.0373 | 0.0373 | 0.0373 | 0.0373 | 0.0000 | 2020-02-03 20:22:54 | 2020-02-03 20:22:54 |
| NULL | fba95d44e3d0a9802dd534c782314352 | SELECT `UNIX_TIMESTAMP` ( ) | 2 | 0.0002 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 18c649da485456d6cdf12e4e6b0350e9 | SELECT @@GLOBAL . `SERVER_ID` | 2 | 0.0001 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | dd356b8a5a6ed0d7aee2abd939cdb6c9 | SET @? = ? | 6 | 0.0003 | 0.0000 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 1c5ae643e930af6d069845d74729760d | SET @? = @@GLOBAL . `binlog_checksum` | 2 | 0.0001 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | ad5208ffa004a6ad7e26011b73cbfb4c | SELECT @? | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | ed0d1eb982c106d4231b816539652907 | SELECT @@GLOBAL . `GTID_MODE` | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | cb47e22372fdd4441486b02c133fb94f | SELECT @@GLOBAL . `SERVER_UUID` | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0001 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 73301368c301db5d2e3db5626a21b647 | SELECT @@GLOBAL . `rpl_semi_sync_master_enabled` | 2 | 0.0001 | 0.0000 | 0.0000 | 0.0000 | 0.0000 | 2020-02-03 20:22:57 | 2020-02-03 20:23:00 |
| NULL | 0ff7375c5f076ba5c040e78a9250a659 | SELECT @@`version_comment` LIMIT ? | 1 | 0.0001 | 0.0001 | 0.0001 | 0.0001 | 0.0000 | 2020-02-03 20:45:59 | 2020-02-03 20:45:59 |
| NULL | 5820f411e67a393f987c6be5d81a011d | SHOW TABLES FROM `performance_schema` | 1 | 0.0008 | 0.0008 | 0.0008 | 0.0008 | 0.0002 | 2020-02-03 20:46:11 | 2020-02-03 20:46:11 |
| NULL | a022a0ab966c51eb820da1521349c7ef | SELECT SCHEMA ( ) | 1 | 0.0005 | 0.0005 | 0.0005 | 0.0005 | 0.0000 | 2020-02-03 20:46:29 | 2020-02-03 20:46:29 |
| performance_schema | e4833a7c1365b0b4492e9a514f7b3bd4 | SHOW SCHEMAS | 1 | 0.1167 | 0.1167 | 0.1167 | 0.1167 | 0.0001 | 2020-02-03 20:46:29 | 2020-02-03 20:46:29 |
| performance_schema | 1107f048fe6d970cb6a553bd4727a1b4 | SHOW TABLES | 1 | 0.0002 | 0.0002 | 0.0002 | 0.0002 | 0.0000 | 2020-02-03 20:46:29 | 2020-02-03 20:46:29 |
...待機時間の列（SUM_TIMER_WAIT、MIN_TIMER_WAIT_SEC、AVG_TIMER_WAIT_SEC）を分割する必要がある理由がわからない場合は、これらの列はピコ秒を使用しているため、計算または切り上げを行う必要があります。読みやすくなります。
ClusterControlを使用した低速クエリの分析
ClusterControlを使用している場合、これに対処するさまざまな方法があります。たとえば、以下のMariaDBクラスターでは、次のタブ（クエリモニター）とドロップダウンアイテム（トップクエリ、実行中のクエリ、クエリの外れ値）が表示されます：
- 上位のクエリ-データベースクラスタのすべてのノードで実行されているすべての上位のクエリの集計リスト
- 実行中のクエリ-MySQLのSHOWFULLPROCESSLISTコマンドと同様に、データベースクラスターで現在実行中のクエリを表示します
さらに、ClusterControlはグラフを使用してクエリのパフォーマンスをキャプチャします。これにより、クエリのパフォーマンスに関連してデータベースシステムのパフォーマンスをすばやく確認できます。以下を参照してください
待って、まだ終わっていません。 ClusterControlは、Prometheusを使用した高解像度のメトリックも提供し、非常に詳細なメトリックを表示し、サーバーからリアルタイムの統計をキャプチャします。これについては、ブログの2つのパートシリーズに分かれている以前のブログで説明しました。パート1をチェックしてから、パート2のブログをチェックしてください。遅いクエリだけでなく、MySQL、MariaDB、またはPerconaデータベースサーバーの全体的なパフォーマンスを効率的に監視する方法を提供します。
ClusterControlには、遅いクエリログによってまだ発生またはキャプチャされていない場合でも、クエリのパフォーマンスを低下させる可能性のあるポインタとヒントを提供する他のツールもあります。以下に示すように、[パフォーマンス]タブを確認してください。
これらのアイテムは、次のものを提供します。
- Advisors-ClusterControlで作成されたスケジュールされたアドバイザの結果のリスト>管理>ClusterControlDSLを使用したDeveloperStudio。
- DBステータス-DBステータスは、SHOW STATUSステートメントと同様に、すべてのデータベースノードにわたるMySQLステータスの概要を提供します。
- DB変数-DB変数は、SHOW GLOBAL VARIABLESステートメントと同様に、すべてのデータベースノードに設定されているMySQL変数の概要を提供します。
- DBの増加-過去30日間のデータベースとテーブルの増加の概要を毎日提供します。
- InnoDB Status-SHOW ENGINE INNODB STATUSコマンドと同様に、選択したホストの現在のInnoDBモニター出力を取得します。
- Schema Analyzer-MyISAMストレージエンジンを使用して、欠落している主キー、冗長なインデックス、およびテーブルについてデータベーススキーマを分析します。
- トランザクションログ-データベースクラスター全体で実行時間の長いトランザクションとデッドロックを一覧表示し、デッドロックの原因となっているトランザクションを簡単に確認できます。デフォルトのクエリ時間のしきい値は30秒です。
MySQLのパフォーマンスの問題を追跡することは、MySQLではそれほど難しくありません。あなたが探している効率と機能を提供するさまざまな外部ツールがあります。最も重要なことは、使いやすく、仕事で生産性を提供できることです。最も未解決の問題を修正するか、特定の災害が発生する前に回避することもできます。