重要

現在表示されているページは、TiDBのアーカイブされたドキュメント (非更新) です。TiDBをご利用の場合、最新のLTS (Long Term Support) バージョンの使用を推奨します。

重要

このページは英語版のページを機械翻訳しています。原文はこちらからご覧ください。

遅いクエリを特定する

ユーザーが遅いクエリを特定し、SQL 実行のパフォーマンスを分析および改善するのに役立つように、TiDB は実行時間が低速しきい値 (デフォルト値は 300 ミリ秒) からスロークエリファイル (デフォルト値は「tidb-slow.log」) を超えるステートメントを出力します。

TiDB はデフォルトでスロークエリログを有効にします。構成を変更することで、この機能を有効または無効にすることができますenable-slow-log 。

使用例

# Time: 2019-08-14T09:26:59.487776265+08:00
# Txn_start_ts: 410450924122144769
# User@Host: root[root] @ localhost [127.0.0.1]
# Conn_ID: 3086
# Exec_retry_time: 5.1 Exec_retry_count: 3
# Query_time: 1.527627037
# Parse_time: 0.000054933
# Compile_time: 0.000129729
# Rewrite_time: 0.000000003 Preproc_subqueries: 2 Preproc_subqueries_time: 0.000000002
# Process_time: 0.07 Request_count: 1 Total_keys: 131073 Process_keys: 131072 Prewrite_time: 0.335415029 Commit_time: 0.032175429 Get_commit_ts_time: 0.000177098 Local_latch_wait_time: 0.106869448 Write_keys: 131072 Write_size: 3538944 Prewrite_region: 1
# DB: test
# Is_internal: false
# Digest: 50a2e32d2abbd6c1764b1b7f2058d428ef2712b029282b776beb9506a365c0f1
# Stats: t:pseudo
# Num_cop_tasks: 1
# Cop_proc_avg: 0.07 Cop_proc_p90: 0.07 Cop_proc_max: 0.07 Cop_proc_addr: 172.16.5.87:20171
# Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr: 172.16.5.87:20171
# Cop_backoff_regionMiss_total_times: 200 Cop_backoff_regionMiss_total_time: 0.2 Cop_backoff_regionMiss_max_time: 0.2 Cop_backoff_regionMiss_max_addr: 127.0.0.1 Cop_backoff_regionMiss_avg_time: 0.2 Cop_backoff_regionMiss_p90_time: 0.2
# Cop_backoff_rpcPD_total_times: 200 Cop_backoff_rpcPD_total_time: 0.2 Cop_backoff_rpcPD_max_time: 0.2 Cop_backoff_rpcPD_max_addr: 127.0.0.1 Cop_backoff_rpcPD_avg_time: 0.2 Cop_backoff_rpcPD_p90_time: 0.2
# Cop_backoff_rpcTiKV_total_times: 200 Cop_backoff_rpcTiKV_total_time: 0.2 Cop_backoff_rpcTiKV_max_time: 0.2 Cop_backoff_rpcTiKV_max_addr: 127.0.0.1 Cop_backoff_rpcTiKV_avg_time: 0.2 Cop_backoff_rpcTiKV_p90_time: 0.2
# Mem_max: 525211
# Disk_max: 65536
# Prepared: false
# Plan_from_cache: false
# Succ: true
# Plan: tidb_decode_plan('ZJAwCTMyXzcJMAkyMAlkYXRhOlRhYmxlU2Nhbl82CjEJMTBfNgkxAR0AdAEY1Dp0LCByYW5nZTpbLWluZiwraW5mXSwga2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvCg==')
use test;
insert into t select * from t;

フィールドの説明

ノート：
スロークエリログの次のすべての時間フィールドの単位は「秒」です。

スロークエリの基本:

Time : ログの印刷時間。
Query_time : ステートメントの実行時間。
Parse_time : ステートメントの解析時間。
Compile_time : クエリの最適化の期間。
Query : SQL ステートメント。 Queryはスローログには出力されませんが、スローログがメモリテーブルにマップされた後、対応するフィールドはQueryと呼ばれます。
Digest : SQL ステートメントのフィンガープリント。
Txn_start_ts : トランザクションの開始タイムスタンプと一意の ID。この値を使用して、トランザクション関連のログを検索できます。
Is_internal : SQL ステートメントが TiDB 内部であるかどうか。 trueは SQL ステートメントが TiDB 内部で実行されることを示し、 falseは SQL ステートメントがユーザーによって実行されることを示します。
Index_ids : ステートメントに含まれるインデックスの ID。
Succ : ステートメントが正常に実行されたかどうか。
Backoff_time : 文で再試行が必要なエラーが発生した場合の再試行までの待機時間。一般的なエラーには、 lock occurs 、 Region split 、およびtikv server is busyが含まれます。
Plan : ステートメントの実行計画。 SELECT tidb_decode_plan('xxx...')ステートメントを実行して、特定の実行計画を解析します。
Binary_plan : バイナリエンコードされたステートメントの実行計画。 SELECT tidb_decode_binary_plan('xxx...')ステートメントを実行して、特定の実行計画を解析します。 PlanフィールドとBinary_planフィールドには同じ情報が含まれます。ただし、2 つのフィールドから解析される実行計画の形式は異なります。
Prepared : このステートメントがPrepareまたはExecuteの要求であるかどうか。
Plan_from_cache : このステートメントが実行プランのキャッシュにヒットするかどうか。
Rewrite_time : このステートメントのクエリを書き換えるのにかかった時間。
Preproc_subqueries : 事前に実行される (ステートメント内の) サブクエリの数。たとえば、 where id in (select if from t)番目のサブクエリが事前に実行される場合があります。
Preproc_subqueries_time : このステートメントのサブクエリを事前に実行するのにかかった時間。
Exec_retry_count : このステートメントの再試行回数。このフィールドは通常、ロックが失敗したときにステートメントが再試行される悲観的トランザクション用です。
Exec_retry_time : このステートメントの実行再試行期間。たとえば、ステートメントが合計 3 回実行された場合 (最初の 2 回は失敗)、 Exec_retry_timeは最初の 2 回の実行の合計期間を意味します。最後の実行の期間はQuery_time - Exec_retry_timeです。

次のフィールドは、トランザクションの実行に関連しています。

Prewrite_time : 2 フェーズトランザクションコミットの最初のフェーズ (事前書き込み) の期間。
Commit_time : 2 フェーズトランザクションコミットの第 2 フェーズ (コミット) の期間。
Get_commit_ts_time : 2 フェーズトランザクションコミットの第 2 フェーズ (コミット) でcommit_tsを取得するのにかかった時間。
Local_latch_wait_time : 2 フェーズトランザクションコミットの第 2 フェーズ (コミット) の前に、TiDB がロックの待機に費やす時間。
Write_keys : トランザクションが TiKV の書き込み CF に書き込むキーの数。
Write_size : トランザクションのコミット時に書き込まれるキーまたは値の合計サイズ。
Prewrite_region : 2 フェーズトランザクションコミットの最初のフェーズ (事前書き込み) に含まれる TiKV リージョンの数。各リージョンは、リモートプロシージャコールをトリガーします。

メモリ使用量フィールド:

Mem_max : SQL文の実行期間中に使用される最大メモリ領域(単位はバイト)。

ハードディスクフィールド:

Disk_max : SQL文の実行期間中に使用される最大ディスク容量(単位はバイト)。

ユーザーフィールド:

User : このステートメントを実行するユーザーの名前。
Conn_ID : 接続 ID (セッション ID)。たとえば、キーワードcon:3を使用して、セッション ID が3のログを検索できます。
DB : 現在のデータベース。

TiKV コプロセッサタスクフィールド:

Request_count : ステートメントが送信するコプロセッサー要求の数。
Total_keys : コプロセッサーがスキャンしたキーの数。
Process_time : TiKV での SQL ステートメントの合計処理時間。データは TiKV に同時に送信されるため、この値はQuery_timeを超える可能性があります。
Wait_time : TiKV でのステートメントの合計待機時間。 TiKV のコプロセッサは限られた数のスレッドを実行するため、コプロセッサのすべてのスレッドが動作しているときにリクエストがキューに入ることがあります。キュー内のリクエストの処理に時間がかかると、後続のリクエストの待ち時間が長くなります。
Process_keys : コプロセッサーが処理したキーの数。 total_keysと比較して、 processed_keysには古いバージョンの MVCC が含まれていません。 processed_keysとtotal_keysの大きな違いは、多くの古いバージョンが存在することを示しています。
Cop_proc_avg : RocksDB のミューテックスなど、カウントできない待機時間を含む、警官タスクの平均実行時間。
Cop_proc_p90 : 警官タスクの P90 実行時間。
Cop_proc_max : 警官タスクの最大実行時間。
Cop_proc_addr : 実行時間が最も長い cop-task のアドレス。
Cop_wait_avg : 要求のキューイングとスナップショットの取得の時間を含む、警官タスクの平均待機時間。
Cop_wait_p90 : 警官タスクの P90 待機時間。
Cop_wait_max : 警官タスクの最大待機時間。
Cop_wait_addr : 待機時間が最も長い cop-task のアドレス。
Cop_backoff_{backoff-type}_total_times : エラーによるバックオフの合計回数。
Cop_backoff_{backoff-type}_total_time : エラーによるバックオフの合計時間。
Cop_backoff_{backoff-type}_max_time : エラーによるバックオフの最長時間。
Cop_backoff_{backoff-type}_max_addr : エラーによって発生したバックオフ時間が最長の警官タスクのアドレス。
Cop_backoff_{backoff-type}_avg_time : エラーによるバックオフの平均時間。
Cop_backoff_{backoff-type}_p90_time : エラーが原因で発生した P90 パーセンタイルバックオフ時間。

tidb_slow_log_threshold : スローログのしきい値を設定します。スローログには、実行時間がこの閾値を超えたSQL文が記録されます。デフォルト値は 300 (ミリ秒) です。
tidb_query_log_max_len : スローログに記録される SQL ステートメントの最大長を設定します。デフォルト値は 4096 (バイト) です。
tidb_redact_log : スローログに記録された SQL ステートメントで?を使用して、ユーザーデータの感度を下げるかどうかを決定します。デフォルト値は0で、これは機能を無効にすることを意味します。

tidb_enable_collect_execution_info : 各オペレーターの物理実行情報を実行計画に記録するかどうかを決定します。デフォルト値は1です。この機能は、パフォーマンスに約 3% 影響します。この機能を有効にすると、次のようにPlanの情報を表示できます。

> select tidb_decode_plan('jAOIMAk1XzE3CTAJMQlmdW5jczpjb3VudChDb2x1bW4jNyktPkMJC/BMNQkxCXRpbWU6MTAuOTMxNTA1bXMsIGxvb3BzOjIJMzcyIEJ5dGVzCU4vQQoxCTMyXzE4CTAJMQlpbmRleDpTdHJlYW1BZ2dfOQkxCXQRSAwyNzY4LkgALCwgcnBjIG51bTogMQkMEXMQODg0MzUFK0hwcm9jIGtleXM6MjUwMDcJMjA2HXsIMgk1BWM2zwAAMRnIADcVyAAxHcEQNQlOL0EBBPBbCjMJMTNfMTYJMQkzMTI4MS44NTc4MTk5MDUyMTcJdGFibGU6dCwgaW5kZXg6aWR4KGEpLCByYW5nZTpbLWluZiw1MDAwMCksIGtlZXAgb3JkZXI6ZmFsc2UJMjUBrgnQVnsA');
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| tidb_decode_plan('jAOIMAk1XzE3CTAJMQlmdW5jczpjb3VudChDb2x1bW4jNyktPkMJC/BMNQkxCXRpbWU6MTAuOTMxNTA1bXMsIGxvb3BzOjIJMzcyIEJ5dGVzCU4vQQoxCTMyXzE4CTAJMQlpbmRleDpTdHJlYW1BZ2dfOQkxCXQRSAwyNzY4LkgALCwgcnBjIG51bTogMQkMEXMQODg0MzUFK0hwcm9jIGtleXM6MjUwMDcJMjA2HXsIMg |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
|     id                    task    estRows               operator info                                                  actRows    execution info                                                                  memory       disk                              |
|     StreamAgg_17          root    1                     funcs:count(Column#7)->Column#5                                1          time:10.931505ms, loops:2                                                       372 Bytes    N/A                               |
|     └─IndexReader_18      root    1                     index:StreamAgg_9                                              1          time:10.927685ms, loops:2, rpc num: 1, rpc time:10.884355ms, proc keys:25007    206 Bytes    N/A                               |
|       └─StreamAgg_9       cop     1                     funcs:count(1)->Column#7                                       1          time:11ms, loops:25                                                             N/A          N/A                               |
|         └─IndexScan_16    cop     31281.857819905217    table:t, index:idx(a), range:[-inf,50000), keep order:false    25007      time:11ms, loops:25                                                             N/A          N/A                               |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

パフォーマンステストを実施している場合は、オペレーターの実行情報を自動的に収集する機能を無効にすることができます。

set @@tidb_enable_collect_execution_info=0;

Planフィールドの返される結果は、 EXPLAINまたはEXPLAIN ANALYZEとほぼ同じ形式です。実行計画の詳細については、 EXPLAINまたはEXPLAIN ANALYZEを参照してください。

詳細については、 TiDB 固有の変数と構文を参照してください。

スローログでのメモリマッピング

INFORMATION_SCHEMA.SLOW_QUERYテーブルに対してクエリを実行することで、スロークエリログの内容をクエリできます。テーブル内の各列名は、スローログ内の 1 つのフィールド名に対応しています。テーブル構造については、情報スキーマのSLOW_QUERYテーブルの紹介を参照してください。

ノート：
SLOW_QUERYのテーブルにクエリを実行するたびに、TiDB は現在のスロークエリログを読み取って解析します。

TiDB 4.0 の場合、 SLOW_QUERYはローテーションされたスローログファイルを含む、任意の期間のスローログのクエリをサポートします。解析する必要があるスローログファイルを見つけるには、 TIMEの範囲を指定する必要があります。 TIMEの範囲を指定しない場合、TiDB は現在のスローログファイルのみを解析します。例えば：

時間範囲を指定しない場合、TiDB は、TiDB がスローログファイルに書き込んでいるスロークエリデータのみを解析します。

select count(*),
      min(time),
      max(time)
from slow_query;

+----------+----------------------------+----------------------------+
| count(*) | min(time)                  | max(time)                  |
+----------+----------------------------+----------------------------+
| 122492   | 2020-03-11 23:35:20.908574 | 2020-03-25 19:16:38.229035 |
+----------+----------------------------+----------------------------+

たとえば、 2020-03-10 00:00:00から2020-03-11 00:00:00までの時間範囲を指定すると、TiDB はまず指定された時間範囲のスローログファイルを見つけてから、スロークエリ情報を解析します。

select count(*),
      min(time),
      max(time)
from slow_query
where time > '2020-03-10 00:00:00'
  and time < '2020-03-11 00:00:00';

+----------+----------------------------+----------------------------+
| count(*) | min(time)                  | max(time)                  |
+----------+----------------------------+----------------------------+
| 2618049  | 2020-03-10 00:00:00.427138 | 2020-03-10 23:00:22.716728 |
+----------+----------------------------+----------------------------+

ノート：
指定された時間範囲のスローログファイルが削除された場合、またはスロークエリがない場合、クエリは NULL を返します。

TiDB 4.0 では、すべての TiDB ノードのスロークエリ情報をクエリするためのCLUSTER_SLOW_QUERYのシステムテーブルが追加されています。 CLUSTER_SLOW_QUERYテーブルのテーブルスキーマは、 INSTANCEカラムがCLUSTER_SLOW_QUERYに追加されているという点で、 SLOW_QUERYテーブルのテーブルスキーマとは異なります。 INSTANCE列目はスロークエリの行情報のTiDBノードアドレスです。 SLOW_QUERYと同じようにCLUSTER_SLOW_QUERYを使用できます。

CLUSTER_SLOW_QUERYのテーブルにクエリを実行すると、TiDB は、他のノードからすべてのスロークエリ情報を取得して 1 つの TiDB ノードで操作を実行する代わりに、計算と判断を他のノードにプッシュします。

`SLOW_QUERY` / `CLUSTER_SLOW_QUERY`使用例

トップ N スロークエリ

ユーザーの上位 2 つの遅いクエリをクエリします。 Is_internal=falseは、TiDB 内のスロークエリを除外し、ユーザーのスロークエリのみをクエリすることを意味します。

select query_time, query
from information_schema.slow_query
where is_internal = false
order by query_time desc
limit 2;

出力例:

+--------------+------------------------------------------------------------------+
| query_time   | query                                                            |
+--------------+------------------------------------------------------------------+
| 12.77583857  | select * from t_slim, t_wide where t_slim.c0=t_wide.c0;          |
|  0.734982725 | select t0.c0, t1.c1 from t_slim t0, t_wide t1 where t0.c0=t1.c0; |
+--------------+------------------------------------------------------------------+

`test`ユーザーのトップ N スロークエリをクエリします。

次の例では、 test人のユーザーによって実行されたスロークエリがクエリされ、最初の 2 つの結果が実行時間の逆順に表示されます。

select query_time, query, user
from information_schema.slow_query
where is_internal = false
  and user = "test"
order by query_time desc
limit 2;

出力例:

+-------------+------------------------------------------------------------------+----------------+
| Query_time  | query                                                            | user           |
+-------------+------------------------------------------------------------------+----------------+
| 0.676408014 | select t0.c0, t1.c1 from t_slim t0, t_wide t1 where t0.c0=t1.c1; | test           |
+-------------+------------------------------------------------------------------+----------------+

同じ SQL フィンガープリントで同様の遅いクエリをクエリする

トップ N の SQL ステートメントをクエリした後、同じフィンガープリントを使用して同様の遅いクエリをクエリし続けます。

トップ N スロークエリと対応する SQL フィンガープリントを取得します。

select query_time, query, digest
from information_schema.slow_query
where is_internal = false
order by query_time desc
limit 1;

出力例:

+-------------+-----------------------------+------------------------------------------------------------------+
| query_time  | query                       | digest                                                           |
+-------------+-----------------------------+------------------------------------------------------------------+
| 0.302558006 | select * from t1 where a=1; | 4751cb6008fda383e22dacb601fde85425dc8f8cf669338d55d944bafb46a6fa |
+-------------+-----------------------------+------------------------------------------------------------------+

フィンガープリントを使用して、同様の遅いクエリをクエリします。

select query, query_time
from information_schema.slow_query
where digest = "4751cb6008fda383e22dacb601fde85425dc8f8cf669338d55d944bafb46a6fa";

出力例:

+-----------------------------+-------------+
| query                       | query_time  |
+-----------------------------+-------------+
| select * from t1 where a=1; | 0.302558006 |
| select * from t1 where a=2; | 0.401313532 |
+-----------------------------+-------------+

疑似`stats`を使用して遅いクエリをクエリする

select query, query_time, stats
from information_schema.slow_query
where is_internal = false
  and stats like '%pseudo%';

出力例:

+-----------------------------+-------------+---------------------------------+
| query                       | query_time  | stats                           |
+-----------------------------+-------------+---------------------------------+
| select * from t1 where a=1; | 0.302558006 | t1:pseudo                       |
| select * from t1 where a=2; | 0.401313532 | t1:pseudo                       |
| select * from t1 where a>2; | 0.602011247 | t1:pseudo                       |
| select * from t1 where a>3; | 0.50077719  | t1:pseudo                       |
| select * from t1 join t2;   | 0.931260518 | t1:407872303825682445,t2:pseudo |
+-----------------------------+-------------+---------------------------------+

実行計画が変更された遅いクエリをクエリする

同じカテゴリの SQL ステートメントの実行計画が変更されると、統計が古くなっているか、統計が実際のデータ分布を反映するほど正確ではないため、実行速度が低下します。次の SQL ステートメントを使用して、さまざまな実行プランで SQL ステートメントを照会できます。

select count(distinct plan_digest) as count,
       digest,
       min(query)
from cluster_slow_query
group by digest
having count > 1
limit 3\G

出力例:

***************************[ 1. row ]***************************
count      | 2
digest     | 17b4518fde82e32021877878bec2bb309619d384fca944106fcaf9c93b536e94
min(query) | SELECT DISTINCT c FROM sbtest25 WHERE id BETWEEN ? AND ? ORDER BY c [arguments: (291638, 291737)];
***************************[ 2. row ]***************************
count      | 2
digest     | 9337865f3e2ee71c1c2e740e773b6dd85f23ad00f8fa1f11a795e62e15fc9b23
min(query) | SELECT DISTINCT c FROM sbtest22 WHERE id BETWEEN ? AND ? ORDER BY c [arguments: (215420, 215519)];
***************************[ 3. row ]***************************
count      | 2
digest     | db705c89ca2dfc1d39d10e0f30f285cbbadec7e24da4f15af461b148d8ffb020
min(query) | SELECT DISTINCT c FROM sbtest11 WHERE id BETWEEN ? AND ? ORDER BY c [arguments: (303359, 303458)];

次に、上記のクエリ結果の SQL フィンガープリントを使用して、さまざまなプランをクエリできます。

select min(plan),
       plan_digest
from cluster_slow_query
where digest='17b4518fde82e32021877878bec2bb309619d384fca944106fcaf9c93b536e94'
group by plan_digest\G

出力例:

*************************** 1. row ***************************
  min(plan):    Sort_6                  root    100.00131380758702      sbtest.sbtest25.c:asc
        └─HashAgg_10            root    100.00131380758702      group by:sbtest.sbtest25.c, funcs:firstrow(sbtest.sbtest25.c)->sbtest.sbtest25.c
          └─TableReader_15      root    100.00131380758702      data:TableRangeScan_14
            └─TableScan_14      cop     100.00131380758702      table:sbtest25, range:[502791,502890], keep order:false
plan_digest: 6afbbd21f60ca6c6fdf3d3cd94f7c7a49dd93c00fcf8774646da492e50e204ee
*************************** 2. row ***************************
  min(plan):    Sort_6                  root    1                       sbtest.sbtest25.c:asc
        └─HashAgg_12            root    1                       group by:sbtest.sbtest25.c, funcs:firstrow(sbtest.sbtest25.c)->sbtest.sbtest25.c
          └─TableReader_13      root    1                       data:HashAgg_8
            └─HashAgg_8         cop     1                       group by:sbtest.sbtest25.c,
              └─TableScan_11    cop     1.2440069558121831      table:sbtest25, range:[472745,472844], keep order:false

クラスター内の各 TiDB ノードのスロークエリの数を照会する

select instance, count(*) from information_schema.cluster_slow_query where time >= "2020-03-06 00:00:00" and time < now() group by instance;

出力例:

+---------------+----------+
| instance      | count(*) |
+---------------+----------+
| 0.0.0.0:10081 | 124      |
| 0.0.0.0:10080 | 119771   |
+---------------+----------+

異常な期間にのみ発生するスローログをクエリする

2020-03-10 13:24:00から2020-03-10 13:27:00までの期間に QPS の低下やレイテンシーの増加などの問題が見つかった場合は、大きなクエリが発生したことが原因である可能性があります。次の SQL ステートメントを実行して、異常な期間にのみ発生するスローログをクエリします。 2020-03-10 13:20:00から2020-03-10 13:23:00までの時間範囲は、通常の期間を指します。

SELECT * FROM
    (SELECT /*+ AGG_TO_COP(), HASH_AGG() */ count(*),
         min(time),
         sum(query_time) AS sum_query_time,
         sum(Process_time) AS sum_process_time,
         sum(Wait_time) AS sum_wait_time,
         sum(Commit_time),
         sum(Request_count),
         sum(process_keys),
         sum(Write_keys),
         max(Cop_proc_max),
         min(query),min(prev_stmt),
         digest
    FROM information_schema.CLUSTER_SLOW_QUERY
    WHERE time >= '2020-03-10 13:24:00'
            AND time < '2020-03-10 13:27:00'
            AND Is_internal = false
    GROUP BY  digest) AS t1
WHERE t1.digest NOT IN
    (SELECT /*+ AGG_TO_COP(), HASH_AGG() */ digest
    FROM information_schema.CLUSTER_SLOW_QUERY
    WHERE time >= '2020-03-10 13:20:00'
            AND time < '2020-03-10 13:23:00'
    GROUP BY  digest)
ORDER BY  t1.sum_query_time DESC limit 10\G

出力例:

***************************[ 1. row ]***************************
count(*)           | 200
min(time)          | 2020-03-10 13:24:27.216186
sum_query_time     | 50.114126194
sum_process_time   | 268.351
sum_wait_time      | 8.476
sum(Commit_time)   | 1.044304306
sum(Request_count) | 6077
sum(process_keys)  | 202871950
sum(Write_keys)    | 319500
max(Cop_proc_max)  | 0.263
min(query)         | delete from test.tcs2 limit 5000;
min(prev_stmt)     |
digest             | 24bd6d8a9b238086c9b8c3d240ad4ef32f79ce94cf5a468c0b8fe1eb5f8d03df

他の TiDB スローログファイルを解析する

TiDB は、セッション変数tidb_slow_query_fileを使用して、クエリを実行するときに読み取って解析するファイルを制御しますINFORMATION_SCHEMA.SLOW_QUERY 。セッション変数の値を変更することで、他のスロークエリログファイルの内容を照会できます。

set tidb_slow_query_file = "/path-to-log/tidb-slow.log"

`pt-query-digest`で TiDB スローログを解析する

TiDB スローログを解析するにはpt-query-digestを使用します。

ノート：
pt-query-digest 3.0.13 以降のバージョンを使用することをお勧めします。

例えば：

pt-query-digest --report tidb-slow.log

出力例:

# 320ms user time, 20ms system time, 27.00M rss, 221.32M vsz
# Current date: Mon Mar 18 13:18:51 2019
# Hostname: localhost.localdomain
# Files: tidb-slow.log
# Overall: 1.02k total, 21 unique, 0 QPS, 0x concurrency _________________
# Time range: 2019-03-18-12:22:16 to 2019-03-18-13:08:52
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time           218s    10ms     13s   213ms    30ms      1s    19ms
# Query size       175.37k       9   2.01k  175.89  158.58  122.36  158.58
# Commit time         46ms     2ms     7ms     3ms     7ms     1ms     3ms
# Conn ID               71       1      16    8.88   15.25    4.06    9.83
# Process keys     581.87k       2 103.15k  596.43  400.73   3.91k  400.73
# Process time         31s     1ms     10s    32ms    19ms   334ms    16ms
# Request coun       1.97k       1      10    2.02    1.96    0.33    1.96
# Total keys       636.43k       2 103.16k  652.35  793.42   3.97k  400.73
# Txn start ts     374.38E       0  16.00E 375.48P   1.25P  89.05T   1.25P
# Wait time          943ms     1ms    19ms     1ms     2ms     1ms   972us
.
.
.

問題のある SQL ステートメントを特定する

SLOW_QUERYステートメントのすべてに問題があるわけではありません。 process_timeが非常に大きいものだけが、クラスター全体への圧力を高めます。

wait_timeが非常に大きく、 process_timeが非常に小さいステートメントは、通常は問題になりません。これは、問題のある実際のステートメントによってステートメントがブロックされ、実行キューで待機する必要があり、応答時間が大幅に長くなるためです。

`admin show slow`コマンド

TiDB ログファイルに加えて、次のadmin show slowコマンドを実行して低速クエリを特定できます。

admin show slow recent N
admin show slow top [internal | all] N

recent Nは、最近の N 個のスロークエリレコードを示します。次に例を示します。

admin show slow recent 10

top Nは、最近 (数日以内) に最も遅い N 個のクエリレコードを示します。 internalオプションが指定されている場合、返される結果はシステムによって実行される内部 SQL になります。 allオプションが指定されている場合、返される結果は内部 SQL と結合されたユーザーの SQL になります。それ以外の場合、このコマンドはユーザーの SQL からスロークエリレコードのみを返します。

admin show slow top 3
admin show slow top internal 3
admin show slow top all 5

メモリが限られているため、TiDB は限られた数のスロークエリレコードしか保存しません。クエリコマンドの値Nがレコード数より大きい場合、返されるレコード数はN未満になります。

次の表に、出力の詳細を示します。

カラム名	説明
始める	SQL実行の開始時刻
間隔	SQL 実行の期間
詳細	SQL実行の詳細
成功	SQL ステートメントが正常に実行されたかどうか。 `1`は成功、 `0`は失敗を意味します。
conn_id	セッションの接続 ID
transaction_ts	トランザクションコミットの`commit ts`
ユーザー	ステートメントを実行するためのユーザー名
デシベル	ステートメントの実行時に関係するデータベース
テーブル ID	SQL ステートメントの実行時に関係するテーブルの ID
インデックス ID	SQL ステートメントの実行時に含まれるインデックスの ID
内部	これは TiDB の内部 SQL ステートメントです。
ダイジェスト	SQL ステートメントのフィンガープリント
SQL	実行中または実行済みのSQL文

遅いクエリを特定する

使用例

フィールドの説明

関連するシステム変数

スローログでのメモリ マッピング

SLOW_QUERY / CLUSTER_SLOW_QUERY使用例

トップ N スロー クエリ

testユーザーのトップ N スロー クエリをクエリします。

同じ SQL フィンガープリントで同様の遅いクエリをクエリする

疑似statsを使用して遅いクエリをクエリする

実行計画が変更された遅いクエリをクエリする

クラスター内の各 TiDB ノードのスロー クエリの数を照会する

異常な期間にのみ発生するスローログをクエリする

他の TiDB スロー ログ ファイルを解析する

pt-query-digestで TiDB スローログを解析する

問題のある SQL ステートメントを特定する

admin show slowコマンド

スローログでのメモリマッピング

`SLOW_QUERY` / `CLUSTER_SLOW_QUERY`使用例

トップ N スロークエリ

`test`ユーザーのトップ N スロークエリをクエリします。

疑似`stats`を使用して遅いクエリをクエリする

クラスター内の各 TiDB ノードのスロークエリの数を照会する

他の TiDB スローログファイルを解析する

`pt-query-digest`で TiDB スローログを解析する

`admin show slow`コマンド