slow transの役割
slow transは、トランザクション実行中にスケジューラー、コーディネーター、パートナーという3つのロールの呼び出しチェーンを記録します。重要なステップの所要時間情報を詳細に統計し、問題のトラブルシューティングに役立ちます。
OceanBaseデータベース3.xおよびそれ以前のバージョンでは、トランザクションタイプは単一パーティショントランザクションと分散トランザクションに分かれており、トランザクションは2段階コミット方式を採用しています。第1段階：パートナーのみがコミットされ、実装面で非常に高度な最適化が施されています。第2段階：スケジューラー、コーディネーター、パートナーの3つのロールがコミットされます。そのうちスケジューラーは各トランザクションに1つずつ存在し、セッションが配置されているマシンと共に動作します。コーディネーターとパートナーは2段階コミットの2つのロールであり、その役割についてはここでは詳しく説明しません。
slow trans解析
scheduler
以下は、スロートランザクションのシナリオでschedulerトランザクションコンテキストが出力するトレースログです。
observer.log:[2021-10-08 11:45:44.313295] TRACE [TRACE]:0 [9382][2334][Y9C4064586A6B-0005CDCF253FBE70] [lt=23] [dc=39] [slow trans] (TRACE=begin_ts=1633664744167732 2021-10-08 03:45:44.167732
[init] u=0 arg1:140542173395392, ctx_type:"scheduler", trans_type:2, trans_id:{hash:7103234888693285108, inc:532846, addr:{ip:"xx.xx.xx.xx", port:40000}, t:1633664744167658}, pkey:{tid:1000, partition_id:1000, part_cnt:1000}, arg1:false, uref:1073741824
[set_stc] u=1 stc:1633664744167733
[start_trans] u=2 ret:0, uref:1073741825
[start_stmt] u=7 ret:0, tenant_id:1003, sql_no:4294967297, phy_plan_type:3, stmt_type:2, sql_id:"AA2155E24549E97", trace_id:Y9C4064586A6B-0005CDCF253FBE70, start_time:1633664744166256, uref:1073741825
[end_stmt] u=30832 ret:0, is_rollback:false, rollback_to:4294967297, rollback_from:4294967297, uref:1073741825
[start_stmt] u=50000 ret:0, tenant_id:1003, sql_no:4294967298, phy_plan_type:3, stmt_type:2, sql_id:"AA2155E24549E97", trace_id:Y9C4064586A6B-0005CDCF253FBE70, start_time:1633664744166256, uref:1073741825
[end_stmt] u=10 ret:0, is_rollback:false, rollback_to:4294967298, rollback_from:4294967298, uref:1073741825
[submit_commit] u=52 ret:0, uref:1073741824
[end_trans] u=35 ret:0, is_rollback:false, uref:1073741825
[exiting] u=114618 uref:1073741824, arg1:3221531139, arg2:7230647234361492284
[handle_message] u=1 ret:0, msg_type:1, uref:1
[end_trans_cb] u=13 ret:0, param:0, param:true
[destroy] u=1 uref:0
total_timeu=195572)
フィールドの説明：
| trace event | 意味 | 重要な注記 |
| init | トランザクションが始まったばかりで、schedulerのコンテキストが作成された | - |
| start_trans | トランザクション開始。通常はbegin/start transactionが呼び出される | - |
| start_stmt | ステートメントの実行開始 | - |
| end_stmt | ステートメントの実行終了 | - |
| submit_commit | schedulerが coordinatorに対してトランザクションのコミット/ロールバックコマンドを送信 | この2つのアクションはend_transによってトリガーされます |
| end_trans | クライアントがトランザクションのコミット/ロールバックコマンドを呼び出す | この2つのアクションはend_transによってトリガーされます |
| exiting | トランザクションのコミットが終了し、終了状態が設定されました | この4つのアクションは同じ時点でトリガーされます |
| handle_message | coordinatorから送信されたコミット成功のメッセージを受信 | この4つのアクションは同じ時点でトリガーされます |
| end_trans_cb | クライアントへのトランザクションコミット結果の応答 | この4つのアクションは同じ時点でトリガーされます |
| destroy | トランザクションコンテキストが終了 | この4つのアクションは同じ時点でトリガーされます |
その他の説明：
トレースログ内のu=xxxフィールドは、2つのトレース間の時間間隔を示します。
パフォーマンス問題の調査過程で、[start_stmt] u= xxxのu= xxx値が前の[end_stmt] u= xxxのu= xxx値よりも大きい場合、以下の原因が考えられます：
クライアントの前のSQL実行が終了した後、データ処理に時間がかかるため、次のSQLがOBServer側に送信されるまでに時間がかかります。
前のSQL実行が終了した後、中間リンクに時間がかかる（都市間、ネットワークなど）ことでも同様の状況が発生します。
OBServer側のリソース不足により、SQLリクエストがOBServer側でキューイングされます。この状況を確認するために、
start_stmtトレースの後にそのリクエストがOBServer側に到達した時点のstart_timeが付加されています。この情報に基づいて、この状況であるかどうかを判断することも可能です。
participant
以下は、スロートランザクションのシナリオで participant トランザクションコンテキストが出力した trace log です。
[2021-10-08 11:45:38.282471] TRACE [TRACE]:0 [8867][1304][Y9C4064586A6B-0005CDCF23FFC4F0] [lt=18] [dc=1] [slow trans] (TRACE=begin_ts=1633664737962453 2021-10-08 03:45:37.962453
[init] u=0 arg1:140559776221904, ctx_type:"participant", trans_type:2, trans_id:{hash:4872971512783667647, inc:524414, addr:{ip:"xx.xx.xx.xx", port:40000}, t:1633664737942500}, pkey:{tid:1102810162709333, partition_id:36, part_cnt:0}, arg1:false, uref:1073741824
[start_trans] u=4 ret:0, left_time:99999978261, uref:1073741825
[snapshot] u=3 snapshot:1633664737962304, uref:1073741825
[update_gts] u=1 ret:0, sql_no:{main_sql_no:1, sub_sql_no:1}, uref:1073741825, snapshot:1633664737962304, tenant_id:1003
[start_task] u=1 ret:0, sql_no:{main_sql_no:1, sub_sql_no:1}, uref:1073741825, need_update_gts:true
[end_task] u=146 ret:0, is_rollback:false, uref:1073741825
--次のいくつかのアクションは、同じ handle_message によってトリガーされます [set_stc] u=10590 stc:1633664737942598
[alloc_logid_ts] u=4 ret:0, log_id:18446744073709551615, tenant_id:1003, uref:1073741825, used:2
[prepare] u=0 ret:0, trans_version:-1, uref:1073741825
[inc_submit_log_count] u=19 logging:1, pending:0, uref:1073741825
[submit_log] u=4 ret:0, uref:1073741825, timeguard:{click:[1, 16, 6]}
[handle_message] u=2 ret:0, msg_type:240, uref:1073741825
--トランザクションのredo prepare logの書き込みが成功した後にトリガーされるコールバック。dec_submit_log_countから、このログに84ms以上の時間がかかったことがわかります。
[dec_submit_log_count] u=84790 logging:0, pending:0, uref:1073741825
[on_sync_log_succ] u=17 ret:0, log_type:3, log_id:14517, uref:1073741825
[handle_timeout] u=21791 ret:0, used:{click:[0, 0, 6]}, uref:1073741825
--commit logの書き込みをトリガーします [update_trans_version] u=3051 trans_version:1633664737964470, uref:1073741825
[inc_submit_log_count] u=13 logging:1, pending:0, uref:1073741825
[submit_log] u=0 ret:0, uref:1073741825, timeguard:{click:[0, 4, 3]}
[handle_message] u=1 ret:0, msg_type:280, uref:1073741825
--commit logの書き込みが成功し、コールバックトランザクションがトリガーされました。このログ全体に80ms以上の時間がかかったことがわかります。
[dec_submit_log_count] u=80964 logging:0, pending:0, uref:1073741825
[on_sync_log_succ] u=15 ret:0, log_type:4, log_id:14519, uref:1073741825
[handle_message] u=22908 ret:0, msg_type:280, uref:1073741825
[inc_submit_log_count] u=543 logging:1, pending:0, uref:1073741825
[submit_log] u=1 ret:0, uref:1073741825, timeguard:{click:[1, 0, 3]}
[handle_message] u=0 ret:0, msg_type:320, uref:1073741825
[dec_submit_log_count] u=95141 logging:0, pending:0, uref:1073741825
[exiting] u=1 uref:1073741825, arg1:3221531078, arg2:7230647234361492206
[on_sync_log_succ] u=5 ret:0, log_type:16, log_id:14521, uref:1
[destroy] u=2 arg1:140559776223360
total_timeu=320017)
この trace log の u=xxx フィールドに表示される間隔時間が長すぎる場合は、技術サポートエンジニアまでお問い合わせください。
コーディネーター
以下は、スロートランザクションのシナリオでコーディネーターのトランザクションコンテキストから出力されるトレースログです。
observer.log:[2021-10-08 11:45:47.429179] TRACE [TRACE]:0 [9428][2426][Y9C4064586A6B-0005CDCF204FCDEE] [lt=95] [dc=7] [slow trans] (TRACE=begin_ts=1633664744223393 2021-10-08 03:45:44.223393
[init] u=0 arg1:140543227771456, ctx_type:"coordinator", trans_type:2, trans_id:{hash:16764817863274798805, inc:532875, addr:{ip:"xx.xx.xx.xx", port:40000}, t:1633664744191993}, pkey:{tid:1102810162709332, partition_id:25, part_cnt:0}, arg1:false, uref:1073741824
[cons_context] u=5 ret:0, read_only:false, uref:1073741825
[set_stc] u=1 stc:1633664744192080
[handle_message] u=51 ret:0, id1:-1, id2:-1, msg_type:0, sender:{tid:1000, partition_id:1000, part_cnt:1000}, uref:1073741825
[update_trans_version] u=4436 trans_version:1633664744216959, uref:1073741825
[handle_message] u=0 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=50 trans_version:1633664744216959, uref:1073741825
[handle_message] u=0 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=56 trans_version:1633664744216959, uref:1073741825
[handle_message] u=0 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=1948 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=21 trans_version:1633664744216959, uref:1073741825
[handle_message] u=2 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=7 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=6 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=319 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=9 trans_version:1633664744216959, uref:1073741825
[handle_message] u=0 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=7 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=12 trans_version:1633664744216959, uref:1073741825
[handle_message] u=0 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=32 trans_version:1633664744216959, uref:1073741825
[handle_message] u=0 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=542 trans_version:1633664744216959, uref:1073741825
[handle_message] u=0 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=9 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=8 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=274 trans_version:1633664744216959, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=73993 trans_version:1633664744221650, uref:1073741825
[handle_message] u=2 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=17 trans_version:1633664744221649, uref:1073741825
[handle_message] u=2 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=82 trans_version:1633664744221649, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=130 trans_version:1633664744221650, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=2675 trans_version:1633664744221650, uref:1073741825
[handle_message] u=1 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=22 trans_version:1633664744221649, uref:1073741825
[handle_message] u=2 ret:0, msg_type:250, uref:1073741825
[update_trans_version] u=5517 trans_version:1633664744221649, uref:1073741825
[handle_message] u=2 ret:0, msg_type:250, uref:1073741825
[handle_message] u=15129 ret:0, msg_type:250, uref:1073741825
[handle_timeout] u=412 ret:0, total_count:9, uref:1073741825
[handle_message] u=83 ret:0, msg_type:250, uref:1073741825
[handle_message] u=16 ret:0, msg_type:250, uref:1073741825
[handle_message] u=13 ret:0, msg_type:250, uref:1073741825
[handle_message] u=12 ret:0, msg_type:250, uref:1073741825
[handle_message] u=12 ret:0, msg_type:250, uref:1073741825
[handle_message] u=19 ret:0, msg_type:250, uref:1073741825
[handle_message] u=20 ret:0, msg_type:250, uref:1073741825
[handle_message] u=4764 ret:0, msg_type:250, uref:1073741825
[handle_message] u=48 ret:0, msg_type:250, uref:1073741825
[handle_message] u=7 ret:0, msg_type:250, uref:1073741825
[handle_message] u=5 ret:0, msg_type:250, uref:1073741825
[handle_message] u=4 ret:0, msg_type:250, uref:1073741825 [handle_message] u=7
[handle_message] u=5
[handle_message] u=6
[handle_message] u=4
[handle_message] u=17
[handle_message] u=8
[handle_message] u=5
[handle_message] u=8
[handle_message] u=5
[handle_message] u=5
[update_trans_version] u=2230
[handle_message] u=2
[update_trans_version] u=1279
[handle_message] u=1
[update_trans_version] u=9483
[handle_message] u=1
[update_trans_version] u=166
[handle_message] u=1
[update_trans_version] u=26
[handle_message] u=1
[update_trans_version] u=2748
[handle_message] u=1
[update_trans_version] u=136
[handle_message] u=1
[update_trans_version] u=9
[handle_message] u=1
[update_trans_version] u=6791
[response_scheduler] u=11
[handle_message] u=35
[handle_message] u=1588
[handle_message] u=64575
[handle_message] u=2339
[handle_message] u=15533
[handle_message] u=991
[handle_message] u=18567
[destroy] u=2968405
total_timeu=3205785 DROPPED_EVENTS=15)
これはコーディネーターのトランザクションコンテキストのトレースログであり、40の参加者を駆動してトランザクションのコミットを行います。解析方法はスケジューラーやパートナーと同様であり、ここでは詳細には触れません。
DROPPED_EVENTS は破棄されたイベント数を表します。
トレースログ内の u=xxx フィールドに表示される間隔時間が長すぎる場合は、技術サポートエンジニアに連絡し、調査を支援してください。