slow transの役割
slow transは、トランザクション実行中のscheduler、coordinator、participantの3つのロールの呼び出しチェーンを記録します。重要なステップの時間消費情報を詳細に統計し、問題の調査・診断に役立ちます。
OceanBaseデータベース3.xおよびそれ以前のバージョンでは、トランザクションタイプは単一パーティショントランザクションと分散トランザクションに分かれており、トランザクションは2フェーズコミット方式を採用しています。第1フェーズでは、participantのみがコミットされ、実装上で極めて効率的な最適化が施されています。第2フェーズでは、scheduler、coordinator、participantの3つのロールがコミットされます。ここで、schedulerは各トランザクションに対して1つずつ存在し、セッションが配置されているマシンと共存します。coordinatorとparticipantは2フェーズコミットの2つのロールであり、その役割についてはここでは詳述しません。
slow trans 解決策
scheduler
以下は、slow transシナリオでschedulerトランザクションコンテキストが出力したtraceログです。
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がordinatorに対してトランザクションのコミット/ロールバックコマンドを送信する | これら2つのアクションはend_transによってトリガーされる |
| end_trans | クライアントがトランザクションのコミット/ロールバックコマンドを呼び出す | これら2つのアクションはend_transによってトリガーされる |
| exiting | トランザクションのコミット終了、終了状態を設定 | これら4つのアクションは同じ時点でトリガーされる |
| handle_message | coordinatorから送信されたコミット成功・失敗のメッセージを受信 | これら4つのアクションは同じ時点でトリガーされる |
| end_trans_cb | クライアントに対するトランザクションコミット結果を応答する | これら4つのアクションは同じ時点でトリガーされる |
| destroy | トランザクションコンテキストの終了 | これら4つのアクションは同じ時点でトリガーされる |
その他の説明：
traceログ内のu=xxxフィールドは、2つのtrace間の時間間隔を示します。
パフォーマンス問題の調査過程で、[start_stmt] u= xxx の u= xxx の値が前の[end_stmt] u= xxx の u= xxx の値に比べて大きい場合、以下の原因が考えられます：
クライアントの前のSQLの実行が終わった後、データ処理に時間がかかり、次のSQLがOBServer側に到達するのが遅くなった場合。
前のSQLの実行が終わった後、中間リンクで時間がかかった場合（都市間、ネットワークなど）もこのような状況が発生することがあります。
OBServer側のリソース不足により、SQLリクエストがOBServer側でキューイングされている場合。この状況を確認するために、
start_stmtというtraceの後には、そのリクエストがOBServer側に到達した時刻であるstart_timeが記録されています。この情報に基づいて、この状況であるかどうかを判断することも可能です。
participant
以下は、slow transシナリオでparticipantトランザクションコンテキストが出力したtraceログです。
[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ログの書き込みが成功した後にトリガーされるコールバックです。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ログの書き込みをトリガーします [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ログの書き込みが成功し、トランザクションのコールバックがトリガーされます。このログ全体には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ログのu=xxxフィールドに表示されている間隔時間が長すぎる場合は、技術サポートエンジニアにお問い合わせいただき、調査をお手伝いいたします。
coordinator
以下は、slow transシナリオでコーディネーター（ordinator）トランザクションコンテキストが出力するトレースログです。
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)
これはコーディネーター（ordinator）トランザクションコンテキストのトレースログであり、40個の参加者を駆動してトランザクションのコミットを行います。解析方法はスケジューラー（scheduler）や参加者（participant）と同様であり、ここでは詳述しません。
DROPPED_EVENTS は破棄されたイベント数を表します。
トレースログ内の u=xxx フィールドに表示される間隔時間が長すぎる場合は、テクニカルサポートエンジニアにお問い合わせいただき、調査をご依頼ください。