寻找SQL执行线索的武器库

Posted 2023-03-09 bisal(Chen Liu)

碰到一些SQL问题，有时常规的方式，例如执行计划，不足以给出问题的线索。因此，可能还需要跟踪这条SQL，通过Oracle提供的trace，了解它内部执行的机制，从中寻找线索。

需求：用户TEST通过dbeaver登录到数据库，需要跟踪它所执行的SQL。

（1）确定TEST用户通过dbeaver执行SQL的会话信息。

sys或者具有v$访问权限的用户，执行如下SQL，

select p.PID,p.SPID,s.SID, s.serial#, s.program, p.tracefile
from v$process p,v$session s
where s.paddr = p.addr
and s.username='TEST';

得到会话信息，根据实际情况，确认第二条记录，是需要的会话，

（2）sys或者高级别账号，执行如下语句，其中session_id是（1）的s.sid，serial_num是（1）的s.serial#，

begin
dbms_monitor.session_trace_enable(session_id =>364,
                                  serial_num =>5061,
                                  binds =>TRUE,
                                  waits =>TRUE,
                                  plan_stat =>'all_executions');
end;
/

（3）TEST用户执行语句，

SELECT * FROM t;（t表不存在）
SELECT * FROM test;

（4）如上SQL执行的数据都存储到（1）的p.tracefile。从如下的展示，仅仅是（3）的这两条简单的语句，就写了33K的内容到trace，足以见得Oracle为了执行语句，其实内部机制还是很复杂的，

[oracle@VM-24-12-centos ~]$ ls -lrht /opt/oracle/diag/rdbms/bisalcdb/BISALCDB/trace/BISALCDB_ora_12992.trc
-rw-r----- 1 oracle oinstall 33K Mar  5 22:30 /opt/oracle/diag/rdbms/bisalcdb/BISALCDB/trace/BISALCDB_ora_12992.trc

打开trace，可以看到第一条SQL提示了"PARSE ERROR"，第二条SQL展示了具体执行的信息（包括执行计划、PARSE/EXEC/FETCH等语句执行阶段的消耗），可以有助于进一步对SQL进行探索，

vi /opt/oracle/diag/rdbms/bisalcdb/BISALCDB/trace/BISALCDB_ora_12992.trc
...
=====================
PARSE ERROR #140644761776904:len=15 dep=0 uid=112 oct=3 lid=112 tim=29833470188260 err=942
SELECT * FROM t
WAIT #140644761776904: nam='SQL*Net break/reset to client' ela= 6 driver id=1413697536 break?=1 p3=0 obj#=0 tim=29833470188396
WAIT #140644761776904: nam='SQL*Net break/reset to client' ela= 171292 driver id=1413697536 break?=0 p3=0 obj#=0 tim=29833470359703
WAIT #140644761776904: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=29833470359777


*** 2023-03-05T22:30:19.385011+08:00 (BISALPDB1(3))
WAIT #140644761776904: nam='SQL*Net message from client' ela= 7794254 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=29833478155022
CLOSE #140644761776904:c=6,e=6,dep=0,type=0,tim=29833478155121
...
=====================
PARSING IN CURSOR #140644761776904 len=18 dep=0 uid=112 oct=3 lid=112 tim=29833495043325 hv=2851490487 ad='68c943b0' sqlid='46ncd1ynzckpr'
SELECT * FROM test
END OF STMT
PARSE #140644761776904:c=12575,e=27931,p=3,cr=47,cu=0,mis=1,r=0,dep=0,og=1,plh=1357081020,tim=29833495043325
EXEC #140644761776904:c=10,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=29833495043368
WAIT #140644761776904: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=0 tim=29833495043420
FETCH #140644761776904:c=2,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1357081020,tim=29833495043440
STAT #140644761776904 id=1 cnt=0 pid=0 pos=1 obj=73296 op='TABLE ACCESS FULL TEST (cr=0 pr=0 pw=0 str=1 time=1 us cost=2 size=13 card=1)'
...

（5）关闭trace跟踪，则需要执行如下这条语句，

begin
dbms_monitor.session_trace_disable(session_id =>364,serial_num =>5061);
end;
/

可以将上述过程进行封装，通过工具、脚本等形式，快速调用，丰富我们排查问题的工具箱。

除此之外，10046和10053，也是我们探究问题需要具备的武器，

《如何生成其他会话的10046？》

《PL/SQL中SQL语句10053创建方法》

《有关10053事件，你知道这两个知识点么？》

《探索索引的奥秘 - 10053事件》

像常见的ORA-00060，同样通过Oracle自动生成的trace文件，可以从中找到锁之间的关联，进而有助于判断应用设计的逻辑顺序问题，

《了解ORA-00060和trace跟踪文件》

如果您认为这篇文章有些帮助，还请不吝点下文章末尾的"点赞"和"在看"，或者直接转发pyq，

近期更新的文章：

《MySQL唯一索引有重复值且不是bug的场景》

《《数字中国建设整体布局规划》》

《MySQL日志 - Error Log错误日志》

《MySQL日志 - General Query Log》

《最近碰到的一些问题》

近期的热文：

《推荐一篇Oracle RAC Cache Fusion的经典论文》

《"红警"游戏开源代码带给我们的震撼》

文章分类和索引：

《公众号1100篇文章分类和索引》