当前位置：首页 > news >正文

达梦存储过程执行后 sql日志信息粗读

news 来源：原创 2025/5/8 4:15:13

如何调试达梦存储过程？快速定位问题
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
begin
  DBMS_OUTPUT.PUT_LINE('proc1--过程');
  insert into t1 values (1, 'proc1--过程', sysdate);
  commit;
  DBMS_LOCK.sleep(1);
end;
/

create or replace procedure proc2
as
begin
  DBMS_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;
begin
  DBMS_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;