Purpose
slow trans logs record the call chains of the scheduler, coordinator, and participant roles during transaction execution. The detailed time consumption information of key steps is recorded, which can help you troubleshoot the corresponding issues.
Trace log of slow trans
Scheduler
The following trace log of slow trans is generated in the scheduler context:
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)
Field description:
| trace event | Description | Remarks |
| init | A scheduler context is created at the beginning of the transaction. | - |
| start_trans | The transaction is started, which is typically triggered by calling begin/start transaction. | - |
| start_stmt | Statement execution starts. | - |
| end_stmt | Statement execution ends. | - |
| submit_commit | The scheduler issues the commit/rollback command to the coordinator. | submit_commit and end_trans are triggered by end_trans. |
| end_trans | The client calls the transaction commit/rollback command. | submit_commit and end_trans are triggered by end_trans. |
| exiting | The transaction is committed and is set to the exiting state. | exiting, handle_message, end_trans_cb, and destroy are triggered at the same point in time. |
| handle_message | A commit failure/success message is received from the coordinator. | exiting, handle_message, end_trans_cb, and destroy are triggered at the same point in time. |
| end_trans_cb | The transaction commit result is returned to the client. | exiting, handle_message, end_trans_cb, and destroy are triggered at the same point in time. |
| destroy | The transaction context is exited. | exiting, handle_message, end_trans_cb, and destroy are triggered at the same point in time. |
Note:
The u=xxx field in the trace log indicates the interval between two traces.
When you troubleshoot a performance issue, if the value of u= xxx in [start_stmt] u= xxx is greater than that of u= xxx in previous [end_stmt] u= xxx, the possible causes for the issue are:
Data processing for the previous SQL statement on the client takes a long time. In this case, the current SQL statement waits for a long period before it is sent to the OBServer.
After the previous SQL statement is executed, the intermediate link may take a long time due to reasons such as cross-city connection or network issue.
Resources on the OBServer are insufficient. SQL requests are queued up on the OBServer. You can check the start_time in the
start_stmttrace, which indicates the time when the request reaches the OBServer, to determine whether the resources are sufficient on the OBServer.
Participant
The following trace log of slow trans is generated in the participant context:
[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
--The following actions are triggered by the same 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
--The callback triggered after the redo prepare log of the transaction is successfully written. According to dec_submit_log_count, this log takes more than 84 ms.
[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
-Triggers commit log writes [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
--The commit log is successfully written. The callback transaction is triggered. The overall time consumed by this log is more than 80 ms.
[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)
If the u=xxx field in the trace log denotes an excessively long interval, contact OceanBase Technical Support for troubleshooting.
Coordinator
The following trace log of slow trans is generated in the coordinator context:
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)
According to this trace log, 40 participants are driven to commit the transaction. The analysis method is similar to that of trace logs of the scheduler and participant transaction contexts.
DROPPED_EVENTS indicates the number of events dropped.
If the u=xxx field in the trace log denotes an excessively long interval, contact OceanBase Technical Support for troubleshooting.