如何调试达梦存储过程?快速定位问题
dmgdb 或 manager图形工具
我觉得还可以靠sql日志和DBMS_OUTPUT包,不过最省事的办法放到了最后面,一个sql就能搞清楚了
来段演示代码
set serveroutput on
drop table t1;
create TABLE t1 (id int, gc varchar(20), rq timestamp);create or replace procedure proc1
as
beginDBMS_OUTPUT.PUT_LINE('proc1--过程');insert into t1 values (1, 'proc1--过程', sysdate);commit;DBMS_LOCK.sleep(1);
end;
/create or replace procedure proc2
as
beginDBMS_OUTPUT.PUT_LINE('proc2..过程');insert into t1 values (2, 'proc2..过程', sysdate);commit;DBMS_LOCK.sleep(1);
end;
/create or replace procedure proc_test(i in int)
as j int;
beginDBMS_OUTPUT.PUT_LINE('主体过程开始');DBMS_LOCK.sleep(1);call proc2;call proc1;call proc2;insert into t1 values (i+10,'main proc', sysdate);commit;DBMS_OUTPUT.PUT_LINE('主体过程结束!');
end;
/call proc_test(3);
select id,gc,to_char(rq,'yyyy-mm-dd hh24:mi:ss') from t1;
先从最底下说
执行这个简单的查询后,在sql日志(通常在$DM_HOME/log/)
中显示
sql日志详细内容:
2025-02-13 21:06:11.718 (EP[0] sess:0x7fffbc042a20 thrd:66316 user:SYSDBA trxid:104349 stmt:0x7fffbc03e7b8 appname:disql ip:::1) [ORA]: select id,gc,to_char(rq,'yyyy-mm-dd hh24:mi:ss') riqi from t1;
2025-02-13 21:06:11.719 (EP[0] sess:0x7fffbc042a20 thrd:66316 user:SYSDBA trxid:104349 stmt:0x7fffbc03e7b8 appname:disql ip:::1) DLCK used time:1(us)
2025-02-13 21:06:11.719 (EP[0] sess:0x7fffbc042a20 thrd:66316 user:SYSDBA trxid:104349 stmt:0x7fffbc03e7b8 appname:disql ip:::1) [SEL] select id,gc,to_char(rq,'yyyy-mm-dd hh24:mi:ss') riqi from t1; EXECTIME: 0(ms) ROWCOUNT: 4(rows) EXEC_ID: 1902.
信息量很丰富。
在2025-02-13 21:06:11时间点开始执行这个简单的查询sql
EP[0] 我猜代表执行节点execute point的意思,可以理解为oracle的thread 或实例,默认从0开始,DSC(类似ORACLE的RAC环境)中会看到EP[1]
sess 代表会话id,select to_number(‘7fffbc03e7b8’,‘xxxxxxxxxxxxxxxxxxxxx’) sid from dual ;
thrd代表线程号
从会话、线程和进程信息中都可以看到此id
user显示哪个用户发起的这个sql
trxid事务id,即使查询也分配一个事务id,如果会话内开启一个事务则会增加1
stmt sql执行句柄,同一会话的不同sql还是一样的(有点像sess_id)
但是执行的话就变为null了
appname应用程序名,这里看到是disql程序执行的这个sql
ip客户端ip
而且这几行的上述几列都是一样的,说明是一件事
**[ORA]**这就有些好看了,估计是从ORA的解析sql模块带过来的信息
[SEL]这是sql的类型,可能有DML、SEL、INS、DEL等,也有可能是操作符,例如DLCK
锁定数据字典,估计是解析这个查询sql时触发的对数据字典加了一次锁。
后面跟着输出的就是sql文本,如果多行sql输出也会换行
EXECTIME: 0(ms) ROWCOUNT: 4(rows) EXEC_ID: 1902
EXECTIME: 0(ms)执行耗时1毫秒,
ROWCOUNT: 4(rows) 返回记录数
EXEC_ID: 执行id是1902,可以用于et分析性能
除了执行应用的sql,内部一些操作也会被记录,例如释放undo信息:
purg2_page free pseg page (0, 831)
综上,
一个简单的查询语句会输出3行信息,按时间发生顺序输出。
sess、thrd可以定位会话信息。
trxid会随着会话里执行的事务数量而增长,如果为0说明事务结束。
stmt在结束事务时为null
user、trxid、stmt、appname为空可能是内部的系统调用
进入正题,调用存储过程后,会记录什么信息?
根据日志输出,可见只记录存储过程最外层的执行情况,如果内部有事务才输出相关信息。
根据存储过程的代码
共发生了4次提交,所以日志中事务号,从trxid:104379 一直增加到trxid:104382
[CAL] call proc_test(3); EXECTIME: 4116(ms) EXEC_ID: 1964
执行存储过程时,传入参数3,耗时4116毫秒,执行id是1964(这个很关键,看下面)
主干执行情况
select line_no,method,time_used,FIRST_START_TIME from V$DMSQL_EXEC_TIME where exec_id=&exec_id and caller='&proc_name' and type$='METHOD' order by 1 ;
或者直接看哪步最慢
select type$,seq,level,caller,method,time_used,sql_text,line_no,FIRST_START_TIME from V$DMSQL_EXEC_TIME where exec_id=&exec_id order by level,time_used desc;
这4秒多都是由这些子过程中或直接调用的sleep导致的。
如果你的数据库还没开启sql日志,请参考
https://eco.dameng.com/document/dm/zh-cn/ops/installation-install#2.3%20%E9%85%8D%E7%BD%AE%20SQL%20%E6%97%A5%E5%BF%97
截图不全,去达梦官网看完整的配置步骤。