我的书签
添加书签
移除书签SQL TRACE能够交互式的提供上一次执行的SQL请求执行过程信息及各阶段的耗时。
sql trace开关
sql trace功能默认时关闭的，可通过session变量来控制其关闭和打开；
set ob_enable_trace_log = 0/1;
show trace
当sql trace功能打开后，执行需要诊断的SQL， 然后通过show trace能够查看该SQL执行的信息。这些执行信息以表格方式输出，每列说明如下表所示。
列名 | 说明 |
Title | 记录执行过程某一个阶段点 |
KeyValue | 记录某一个阶段点产生的一些执行信息 |
Time | 记录上一个阶段点到这次阶段点执行耗时 |
如下一节举例中show trace结果：
Title列从上往下看，可以看出整个SQL执行经历的各个阶段，从而知道该SQL真实的执行路径， 比如举例结果中有经过resolve，transform，optimizer，code generate， 说明该SQL重新生成了计划，没有命中plan cache。
KeyValue列，可以看出一些执行信息，帮助我们进行问题排查, 比如1) 记录的trace_id， 可以方便我们在sql_audit中指定trace_id为过滤条件，快速找到该SQL执行信息，同时也可以通过该trace_id快速查找相关的observer日志；2）记录的plan id可以方便在v$plan_cache_plan_explain中查看plan cache中缓存的具体执行计划；3）phy_plan_type告诉我们该次执行计划的类型， 1表示本地计划， 2表示远程计划，3表示分布式计划。里面还有很多类似信息都可以辅助我们进行SQL诊断。
Time列，可以知道上一个阶段点到这次阶段点执行耗时，比如，resolve end对应的206us表示的是resolve begin到resolve耗时。如果某个SQL执行很慢，则通过查看time列，能够快速定位出具体是哪个阶段执行较慢，然后再去具体分析。比如举例结果中，执行耗时主要在生成计划过程中，因此我们只需要分析为什么没有命中plan cache，有可能是计划淘汰后SQL第一次执行，也有可能是Plan Cache不支持的SQL；
示例
- 打开sql trace。
OceanBase (root@test)> set ob_enable_trace_log = 1;
- 执行目标SQL。
OceanBase (root@test)> select * from t1 where c1 = 1;+----+------+------+| c1 | c2 | c3 |+----+------+------+| 1 | 1 | 1 |+----+------+------+
- 显示trace。
OceanBase (root@test)> show trace;+------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+| Title | KeyValue | Time |+------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+| process begin | in_queue_time:20, receive_ts:1523761166127727, enqueue_ts:1523761166127730 | 0 || query begin | trace_id:"YC4186451FC11-000569D9EEAEE567" | 8 || parse begin | stmt:"select * from t1 where c1 = 1", stmt_len:29 | 51 || pc get plan begin | | 13 || transform_with_outline begin | | 24 || transform_with_outline end | | 61 || resolve begin | | 30 || resolve end | | 206 || transform begin | | 28 || transform begin | | 46 || transform end | | 101 || optimizer begin | | 3 || get location cache begin | | 50 || get location cache end | | 23 || optimizer end | | 315 || cg begin | | 1 || cg end | | 102 || execution begin | arg1:false, end_trans_cb:false | 102 || sql start trans begin | | 4 || sql start trans end | ret:0, trans_id:{hash:676060840998016888, inc:51422, addr:{ip:"100.81.252.17", port:50200}, t:1523761163082001}, timeout:1523761266127727, start_time:1523761166127727 | 8 || do open plan begin | plan_id:635 | 1 || sql start stmt begin | | 5 || sql start stmt end | ret:0, autocommit:true, phy_plan_type:1, stmt_type:1, safe_weak_read_snapshot:0, is_inner_query:false, retry_times:0 | 15 || execute plan begin | | 1 || execute plan end | | 2 || sql start participant begin | | 1 || sql start participant end | ret:0, trans_id:{hash:7055361525995234482, inc:51424, addr:{ip:"100.81.252.17", port:50200}, t:1523761166128081} | 68 || table scan begin | | 24 || table scan end | | 18 || do open plan end | | 2 || start_close_plan begin | | 52 || sql end participant begin | | 12 || sql end participant end | ret:0, is_rollback:false | 3 || sql end stmt begin | | 1 || sql end stmt end | ret:0, is_rollback:false | 2 || start_close_plan end | | 0 || start_auto_end_plan begin | | 2 || sql start trans begin | | 1 || sql start trans end | ret:0, is_rollback:false, is_need_disconnect:false, callback_type:0 | 27 || start_auto_end_plan end | is_async_callback:false | 3 || execution end | | 2 || query end | | 53 |+------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+
