寻找SQL执行线索的武器库

2023-03-07 21:07:16 浏览数 (1)

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

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

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

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

代码语言:javascript复制
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#,

代码语言:javascript复制
begin
dbms_monitor.session_trace_enable(session_id =>364,
                                  serial_num =>5061,
                                  binds =>TRUE,
                                  waits =>TRUE,
                                  plan_stat =>'all_executions');
end;
/

(3)TEST用户执行语句,

代码语言:javascript复制
SELECT * FROM t;(t表不存在)
SELECT * FROM test;

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

代码语言:javascript复制
[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进行探索,

代码语言:javascript复制
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跟踪,则需要执行如下这条语句,

代码语言:javascript复制
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跟踪文件

0 人点赞