我的书签
添加书签
移除书签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 | 记录上一个阶段点到这次阶段点执行耗时 |
举例说明
- 打开 SQL Trace
obclient> set ob_enable_trace_log = 1;
- 执行目标SQL
obclient> select * from t1 where c1 = 1;+----+------+------+| c1 | c2 | c3 |+----+------+------+| 1 | 1 | 1 |+----+------+------+
- 显示Trace
obclient> 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 |+------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+
示例中 show trace 结果如下：
Title 列包含整个 SQL 执行经历的各个阶段的信息，以及该 SQL 真实的执行路径。 例如，结果中有经过resolve，transform，optimizer，code generate， 说明该 SQL 重新生成了计划，没有命中 plan cache。
KeyValue 列包含一些执行信息，用于问题排查：
记录的 trace_id， 可以作为 sql_audit 中的过滤条件，快速找到该 SQL 执行信息，同时也可以通过该 trace_id 快速查找相关的 observer 日志；
记录的 plan id 可以用于在
v$plan_cache_plan_explain中查看 plan cache 中缓存的具体执行计划；phy_plan_type 指出该次执行计划的类型如下，可以辅助 SQL 诊断。
1 表示本地计划
2 表示远程计划
3 表示分布式计划
Time 列显示上一个阶段点到这次阶段点执行耗时。
例如，resolve end 对应的 206 us 表示的是 resolve begin 到 resolve 耗时。如果某个 SQL 执行很慢，则通过查看 time 列，能够快速定位出具体是哪个阶段执行较慢，然后再进行具体分析。此例中，执行耗时主要在生成计划过程中，因此只需要分析没有命中 plan cache的原因有哪些，可能是计划淘汰后 SQL 第一次执行，或是 plan cache 不支持的 SQL。
