#追踪
YashanDB定义了一系列追踪事件，用户可按需选择追踪不同的事件从而了解SQL执行过程、不同阶段YashanDB各组件的内部状态等信息，助力于性能观测与调整。
# 追踪事件
每一个追踪事件拥有一个唯一ID，对应一个不同的追踪目标，追踪启/停时采用事件ID进行指定。
YashanDB支持的事件如下表所示：
| 追踪事件ID | 追踪级别 | 追踪目标 |
|---|---|---|
| 10046 | 1（默认值）：语法分析、执行、提取的次数、时间、CPU时间，物理读次数，逻辑读次数，行数，提交和回归，执行计划的行数，时间，一致性读数，物理读数，物理写数等 4：level1 + 绑定参数 8：level1 + 等待事件 12：level1 + level4 + level8 | 追踪SQL语句执行时的性能信息 |
| 10053 | 1（默认值） 2 级别1会比级别2多输出优化器参数信息 | 追踪CBO优化器在解析（Parse）阶段的执行状态，主要包括自顶向下的算子选择过程信息、待选算子的代价信息、计算算子代价的统计信息等 |
# 开启追踪
根据追踪生效范围，开启追踪的操作可分为：
会话级追踪：执行ALTER SESSION语句为当前会话可以开启追踪。
全局追踪：执行ALTER SYSTEM为全局开启追踪。追踪事件会对系统性能产生一定影响，非必要不建议开启全局追踪。
开启追踪时，可以按需指定如下属性信息：
EVENT_ID：追踪事件ID，必填参数，根据ID值指定具体的追踪事件。
LEVEL LEVEL_NUM：追踪级别，可选参数，每一个追踪事件都支持不同的追踪级别，在不同的级别下追踪获得的输出信息不同。
TRACE NAME CONTEXT、FOREVER：仅用于语法兼容，无实际含义。
-- 以默认级别追踪10053事件
ALTER SESSION SET EVENTS = '10053';
ALTER SESSION SET EVENTS = '10053 TRACE NAME CONTEXT';
ALTER SESSION SET EVENTS = '10053 TRACE NAME CONTEXT FOREVER';
-- 以级别2追踪10053事件
ALTER SESSION SET EVENTS = '10053 TRACE NAME CONTEXT FOREVER, LEVEL 2';
-- 一次追踪多个事件
ALTER SESSION SET EVENTS = '10053, LEVEL 2:10046, LEVEL 12';
Note：
由于YashanDB已完成历史执行SQL的解析缓存，开启10053追踪有可能因为命中SQL缓存而未跟踪到trace日志，因此可将业务SQL做简单改写，然后重新执行完成SQL硬解析并记录trace日志。SQL改写时，可在SQL语句中添加无意义字符串，例如原SQL语句
select c1 from t1可以改写为select /*abc*/ c1 from t1。
# 追踪结果
追踪结果将以trace文件承载，并通过时间和会话ID（sid）作为标识区分不同的会话、不同时期产生的trace文件，默认命名格式为{dbname}{yyyymmdd}{sid}.trc。
# 文件名称配置
YashanDB支持在trace文件名中添加自定义标识，由TRACE_FILE_IDENTIFIER参数指定。
ALTER SESSION SET TRACE_FILE_IDENTIFIER = 'YashanDB_Trace';
-- 设置后，生成的trace文件的名称将为{dbname}_{yyyymmdd}_{sid}_YashanDB_Trace.trc
# 文件内容
# 10046事件
追踪10046事件输出的信息包括语法分析、执行、提取的次数、时间、CPU时间，物理读次数，逻辑读次数，行数，提交和回归，执行计划的行数，时间，一致性读数，物理读数，物理写数等。
级别12的输出示例如下：
Trace file /data/yashan/yashan/data/yashan/db-1-1/diag/trace/yashandb_20250417_27_trace_event_10046.trc
YashanDB Server Enterprise Edition {版本号} x86_64 67d26ef
Session ID: 27 (2025-04-17 11:43:29.302)
=====================
PARSING IN CURSOR #140146796809528 len=61 dep=0 uid=0 yct=7 lid=0 tim=1744861410698210 hv=143826514 ad='7f76780a5648' sqlid='1wsv3qmr968yu'
BEGIN DBMS_OUTPUT.GET_LINES(?,?); DBMS_OUTPUT.PUT(NULL); END;
END OF STMT
PARSE #140146796809528 c=22,e=22,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1744861410698214
BINDS #140146796809528:
Bind#0
ydbdty=37 mxl=0 scl=0 pre=0 avl=0 toid=0
value="NULL"
Bind#1
ydbdty=4 mxl=4 scl=0 pre=0 avl=4 toid=0
value="2147483647"
WAIT #140146852137560: nam='log file sync' ela= 1 tim=1744861410698717
WAIT #140146852153968: nam='log file sync' ela= 0 tim=1744861410698851
EXEC #140146796809528 c=1190,e=1190,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=0,tim=1744861410699410
WAIT #140146796809528: nam='db file scattered read' ela= 12 tim=1744861410700963
WAIT #140146796809528: nam='log file parallel write' ela= 66 tim=1744861410701784
WAIT #140146796809528: nam='redo remote sync complete' ela= 516 tim=1744861410702303
WAIT #140146796809528: nam='log file sync' ela= 593 tim=1744861410702304
WAIT #140146796809528: nam='db file scattered read' ela= 8 tim=1744861410702836
WAIT #140146796809528: nam='log file parallel write' ela= 69 tim=1744861410703035
WAIT #140146796809528: nam='redo remote sync complete' ela= 481 tim=1744861410703519
WAIT #140146796809528: nam='log file sync' ela= 559 tim=1744861410703520
CLOSE #140146796809528 type=0,tim=1744861410703989
WAIT #140146801009976: nam='SQL*Net message to client' ela= 25 tim=1744861410704136
WAIT #140146801009976: nam='db file scattered read' ela= 14 tim=1744861410704207
WAIT #140146801009976: nam='log file parallel write' ela= 65 tim=1744861410705127
WAIT #140146801009976: nam='redo remote sync complete' ela= 528 tim=1744861410705657
WAIT #140146801009976: nam='log file sync' ela= 604 tim=1744861410705658
WAIT #140146801009976: nam='db file scattered read' ela= 9 tim=1744861410706141
WAIT #140146801009976: nam='log file parallel write' ela= 68 tim=1744861410706386
WAIT #140146801009976: nam='redo remote sync complete' ela= 754 tim=1744861410707144
WAIT #140146801009976: nam='log file sync' ela= 834 tim=1744861410707148
WAIT #140146801009976: nam='db file scattered read' ela= 11 tim=1744861410708790
WAIT #140146801009976: nam='log file parallel write' ela= 68 tim=1744861410709681
WAIT #140146801009976: nam='redo remote sync complete' ela= 532 tim=1744861410710217
WAIT #140146801009976: nam='log file sync' ela= 612 tim=1744861410710219
WAIT #140146801009976: nam='db file scattered read' ela= 11 tim=1744861410710890
WAIT #140146801009976: nam='log file parallel write' ela= 68 tim=1744861410711091
WAIT #140146801009976: nam='redo remote sync complete' ela= 503 tim=1744861410711597
WAIT #140146801009976: nam='log file sync' ela= 582 tim=1744861410711599
STAT #140146801009976 id=1 cnt=0 pid=0 pos=1 obj=0 op='SELECT (cr=0 cu=0 pr=0 pw=0 time=130 us cost=0 card=0)'
STAT #140146801009976 id=2 cnt=0 pid=1 pos=1 obj=0 op='MERGE JOIN ANTI (cr=0 cu=0 pr=0 pw=0 time=125 us cost=2 card=1)'
STAT #140146801009976 id=3 cnt=4 pid=2 pos=1 obj=0 op='MERGE SORT (cr=0 cu=0 pr=0 pw=0 time=55 us cost=0 card=0)'
STAT #140146801009976 id=4 cnt=4 pid=3 pos=1 obj=2653 op='TABLE ACCESS FULL TRACE_EVENT_10046_INDEXT_8 (cr=0 cu=1 pr=0 pw=0 time=23 us cost=1 card=4)'
STAT #140146801009976 id=5 cnt=7 pid=2 pos=2 obj=0 op='MERGE SORT (cr=0 cu=0 pr=0 pw=0 time=42 us cost=0 card=0)'
STAT #140146801009976 id=6 cnt=13 pid=3 pos=1 obj=2652 op='TABLE ACCESS FULL TRACE_EVENT_10046_INDEXT_7 (cr=0 cu=1 pr=0 pw=0 time=16 us cost=1 card=13)'
CLOSE #140146801009976 type=0,tim=1744861410712259
WAIT #140146801009976: nam='SQL*Net message from client' ela= 3 tim=1744861410712449
# 10053事件
追踪10053事件输出的信息包括trace文件路径信息、数据库版本信息、会话ID与起始时间、追踪的SQL语句、优化器参数信息（级别1）、算子追踪信息以及执行计划信息。
级别1的输出示例如下：
Trace file /data/master/YASDB_DATA/diag/trace/yashandb_20250331_22.trc
YashanDB Server Enterprise Edition {版本号} x86_64
Session ID: 22 (2025-03-31 16:04:13.591)
**************** Trace Start [Event: 10053 Level: 1] ****************
Current SQL statement:
select 1+2 from dual
******************** CBO Parameters ******************
BLOOM_FILTER_FACTOR = 0.30
DML_PARALLEL = FALSE
FILTER_EXTEND_MODE = NOTNULL
FILTER_OR_TO_UNION = TRUE
MAX_RECURSION_DEPTH = 1000
OPT_FILTER_THRESHOLD = 0.30
OPTIMIZER_DYNAMIC_SAMPLING = 0
QUERY_REWRITE_ENABLED = FALSE
SQL_MAP = FALSE
STATISTICS_LEVEL = TYPICAL
SUBQUERY_NDV_FACTOR = 0.10
USE_STORED_OUTLINES = FALSE
_COLUMNAR_ENABLE_HASH_GROUP_DISTINCT = TRUE
_COLUMNAR_ENABLE_FILTER_INVALID = FALSE
_RWRT_OPT = 255
_ENABLE_EXPLAIN_STAGE = TRUE
_ENABLE_EXPLAIN_STATS = TRUE
_OPTIMIZE_EXTEND_FILTER = TRUE
_SPAREINDEX_OPT = ON
_TAC_FILTER_PUSH_THRESHOLD = 5
_OPTMZ_MINMAX_OPT = SINGLE
_OPTMZ_EARLY_GROUP_OPT = ON
_OPTMZ_EXEC_ENGINE = ROW
_OPTMZ_ENABLE_DSTB_AC = TRUE
_B_TREE_BITMAP_PLANS = TRUE
_OPTMZ_ENABLE_DUP_TABLE_PARALLEL = TRUE
_HASH_JOIN_ALGORITHM = PARTITION
*************** CBO Optimize Trace Start *************
Group 0
Logical : Select [ 1 ]
Physical 0 : Select [ 1 ]
Group 1
Logical : Project [ 2 ]
Physical 0 : Project [ 2 ]
Group 2
Logical : Scan Table Name: X$DUAL
Physical 0 : TableFullScan Table Name: X$DUAL
Physical 0: TableFullScan
Stats: rows=1 rowSize=0 keyDistinct=1 columns=1 selectivity=1.000000
Cost: self=8.004000 total=8.004000 fetch=0.000088
Group 2 Best :
Logical : Scan Table Name: X$DUAL
Best Physical : TableFullScan Table Name: X$DUAL
Cost: self=8.004000 total=8.004000 fetch=0.000088
Physical 0: Project
Stats: rows=1 rowSize=0 keyDistinct=1 columns=1 selectivity=1.000000
Cost: self=0.000000 total=8.004000 fetch=0.000088
Group 1 Best :
Logical : Project [ 2 ]
Best Physical : Project [ 2 ]
Cost: self=0.000000 total=8.004000 fetch=0.000088
Physical 0: Select
Stats: rows=1 rowSize=8 keyDistinct=1 columns=1 selectivity=1.000000
Cost: self=0.000000 total=8.004000 fetch=0.000088
Group 0 Best :
Logical : Select [ 1 ]
Best Physical : Select [ 1 ]
Cost: self=0.000000 total=8.004000 fetch=0.000088
*************** Trace Bottom Up **********************
Group 2
Logical : Scan Table Name: X$DUAL
Physical 0 : TableFullScan Table Name: X$DUAL
Physical 0: TableFullScan
Stats: rows=1 rowSize=0 keyDistinct=1 columns=1 selectivity=1.000000
Cost: self=8.004000 total=8.004000 fetch=0.000088
Group 2 Best :
Logical : Scan Table Name: X$DUAL
Best Physical : TableFullScan Table Name: X$DUAL
Cost: self=8.004000 total=8.004000 fetch=0.000088
Group 1
Logical : Project [ 2 ]
Physical 0 : Project [ 2 ]
Group 1 Best :
Logical : Project [ 2 ]
Best Physical : Project [ 2 ]
Cost: self=0.000000 total=8.004000 fetch=0.000088
Group 0
Logical : Select [ 1 ]
Physical 0 : Select [ 1 ]
Group 0 Best :
Logical : Select [ 1 ]
Best Physical : Select [ 1 ]
Cost: self=0.000000 total=8.004000 fetch=0.000088
***************** CBO Optimize Trace End *************
******************************************************
* Executor Plan *
******************************************************
SQL hash value: 2231489676
Optimizer: ADOPT_C
+----+--------------------------------+----------------------+------------+----------+-------------+--------------------------------+
| Id | Operation type | Name | Owner | Rows | Cost(%CPU) | Partition info |
+----+--------------------------------+----------------------+------------+----------+-------------+--------------------------------+
| 0 | SELECT STATEMENT | | | | | |
| 1 | TABLE ACCESS FULL | X$DUAL | SYS | 1| 8( 0)| |
+----+--------------------------------+----------------------+------------+----------+-------------+--------------------------------+
***************** Trace End [Event: 10053 Level: 1] *****************
# 关闭追踪
若不再需要对某个事件进行自动追踪，可以按需关闭自动追踪：
EVENT_ID：追踪事件ID，必填参数，根据ID值指定具体的追踪事件。
OFF：通过该关键字关闭自动追踪。
TRACE NAME CONTEXT、FOREVER：仅用于语法兼容，无实际含义。
ALTER SESSION SET EVENTS = '10053 OFF:10046 OFF';
下载文档
复制链接
