SQL Trace 能够交互式的提供上一次执行的 SQL 请求执行过程信息及各阶段的耗时。

SQL Trace 开关

SQL Trace 功能默认时关闭的,可通过 session 变量来控制其关闭和打开。

  1. set ob_enable_trace_log = 1;

Show Trace

当 SQL Trace 功能打开后,执行需要诊断的 SQL, 然后通过 show trace 能够查看该 SQL 执行的信息。
这些执行信息以表格方式输出,每列说明如下:

列名说明
Title记录执行过程某一个阶段点
KeyValue记录某一个阶段点产生的一些执行信息
Time记录上一个阶段点到这次阶段点执行耗时

示例

  1. 打开 SQL Trace
  1. OceanBase (root@test)> set ob_enable_trace_log = 1;
  1. 执行目标 SQL
  1. OceanBase (root@test)> select * from t1 where c1 = 1;
  2. +----+------+------+
  3. | c1 | c2 | c3 |
  4. +----+------+------+
  5. | 1 | 1 | 1 |
  6. +----+------+------+
  1. 显示Trace
  1. OceanBase (root@test)> show trace;
  2. +------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+
  3. | Title | KeyValue | Time |
  4. +------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+
  5. | process begin | in_queue_time:20, receive_ts:1523761166127727, enqueue_ts:1523761166127730 | 0 |
  6. | query begin | trace_id:"YC4186451FC11-000569D9EEAEE567" | 8 |
  7. | parse begin | stmt:"select * from t1 where c1 = 1", stmt_len:29 | 51 |
  8. | pc get plan begin | | 13 |
  9. | transform_with_outline begin | | 24 |
  10. | transform_with_outline end | | 61 |
  11. | resolve begin | | 30 |
  12. | resolve end | | 206 |
  13. | transform begin | | 28 |
  14. | transform begin | | 46 |
  15. | transform end | | 101 |
  16. | optimizer begin | | 3 |
  17. | get location cache begin | | 50 |
  18. | get location cache end | | 23 |
  19. | optimizer end | | 315 |
  20. | cg begin | | 1 |
  21. | cg end | | 102 |
  22. | execution begin | arg1:false, end_trans_cb:false | 102 |
  23. | sql start trans begin | | 4 |
  24. | 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 |
  25. | do open plan begin | plan_id:635 | 1 |
  26. | sql start stmt begin | | 5 |
  27. | 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 |
  28. | execute plan begin | | 1 |
  29. | execute plan end | | 2 |
  30. | sql start participant begin | | 1 |
  31. | 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 |
  32. | table scan end | | 18 |
  33. | do open plan end | | 2 |
  34. | start_close_plan begin | | 52 |
  35. | sql end participant begin | | 12 |
  36. | sql end participant end | ret:0, is_rollback:false | 3 |
  37. | sql end stmt begin | | 1 |
  38. | sql end stmt end | ret:0, is_rollback:false | 2 |
  39. | start_close_plan end | | 0 |
  40. | start_auto_end_plan begin | | 2 |
  41. | sql start trans begin | | 1 |
  42. | sql start trans end | ret:0, is_rollback:false, is_need_disconnect:false, callback_type:0 | 27 |
  43. | start_auto_end_plan end | is_async_callback:false | 3 |
  44. | execution end | | 2 |
  45. | query end | | 53 |
  46. +------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------+

示例中 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 对应的 206us 表示的是 resolve begin 到 resolve 耗时。如果某个 SQL 执行很慢,则通过查看 time 列,能够快速定位出具体是哪个阶段执行较慢,然后再进行具体分析。此例中,执行耗时主要在生成计划过程中,因此只需要分析没有命中 plan cache的原因有哪些,可能是计划淘汰后 SQL 第一次执行,或是 Plan Cache 不支持的 SQL。