使用logon trigger完成动态的session跟踪(r4笔记第29天)

jeanron100

发布于 2018-03-15 07:28:59

70100

代码可运行

文章被收录于专栏：杨建荣的学习笔记杨建荣的学习笔记

运行总次数：0

代码可运行

在之前讨论过关于oracle中session跟踪的总结，可以参见链接 http://blog.itpub.net/23718752/viewspace-1150568/ 基本的session跟踪方法都做了讨论，但是在实际应用中场景可能要复杂一些，比如我们可以对指定的session开诊断事件，如果session中运行的某个环节出现问题，可以根据诊断事件得到比较明细的递归sql来逐步查看排除，知道问题的根源。但是如果不确定session的情况，因为每次连接进来的session都是不固定的，这样就很难开诊断事件了。这个还得从这些天的一个例子说起，开发找到我希望我能够帮他们查一个问题，开发需要启动一个job，job会在启动的过程中做一些数据校验检查，然后数据处理，最后退出，但是目前他们碰到的问题是job在启动的时候就会报错，而且没有很详细的日志，所以希望我能够不能帮他们看看，碰到这种问题，一般来说都是友情客串一下，帮他们看看，给点思路，对于更根本的原因还是需要他们自己在调优级别加入一些对应的日志。得到的错误是一个ORA的错误，但是日志只有简单的几行。为了把问题简化，排除各种场景的干扰，在此我就简单的模拟了一下这个job，假设这个job需要做下面的事情 sqlplus -s xxx/xxx@test01 <<EOF set feedback off select count(*) from cat; create table catt as select *from cat where rownum<2; drop table catt; select *from catt; EOF 简单的查看一下这个脚本，就会发现最后一步的时候，肯定会报错。因为在倒数第二步中已经把新建的表删除了。再次查看肯定会报ORA-00942: table or view does not exist的错误。我们就以这个例子来分析一下，怎么使用session跟踪来分析问题。最开始的想法是通过shell脚本来不断的扫描某个用户下的session，比如job是需要处理用户test下的数据，在job启动的过程就会有一些session链接到test用户，然后做一些操作。我就尝试通过一个循环的脚本来不断的扫描用户test下的session，然后对这些session使用dbms_system.set_sql_trace_in_session来启动session跟踪。理论上是可行的，但是在实际的操作中还是感觉力不从心，主要有下面几个问题。一个是我也不知道这个job什么时候启动，所以不断的扫描用户test下的session就会有些频繁，而且需要在脚本中不断的去比较哪些session是已经存在的session，需要排除，本身这个过程就会消耗不少的资源。还有一个问题是尽管资源消耗可以接受，但是在扫描的过程中不一定能够完全捕捉到那个session，怎么来理解呢，比如某个job在在数据检查工作的时候使用一个session1,然后在数据处理的时候使用4个session,数据处理的速度可能很快，比如1秒钟完成，扫描的过程中就不一定能够完完全全的捕捉到对应的日志。最后一个就是关闭session跟踪的问题，如果开启了大量的session跟踪，最后需要关闭的时候就需要保证都能够关闭跟踪，否则日志会越来越多，造成不必要的影响。所以最开始和同事在调试的时候，都是我和他坐在一起，我给他说一声，然后启动后台扫描，然后他启动一下job，我们保持几秒中的时间间隔，尽管这样，遗憾的是还是没有找到相关的日志。这种方式太不灵活了，而且调试起来确实费时费力。最后考虑了一下这种灵活性，考虑采用logon trigger来做。我们可以使用如下的代码来实现这种复杂的需求，如果有用户连进来，就开启10046事件，这样逻辑就灵活了很多，不用我在后台做很多无用功来不断的扫描了,也是按需调试的一种很好的例子。 CREATE OR REPLACE TRIGGER set_trace_on_logon AFTER LOGON ON DATABASE BEGIN if ( user not in ('SYS','SYSTEM' )) then EXECUTE IMMEDIATE 'alter session set statistics_level=ALL'; EXECUTE IMMEDIATE 'alter session set max_dump_file_size=UNLIMITED'; EXECUTE IMMEDIATE 'alter session set tracefile_identifier='''||user||'_10046'''; EXECUTE IMMEDIATE 'alter session set events ''10046 trace name context forever, level 12'''; end if; END set_10046_trace_on_logon; / 注意创建trigger的语句需要在sys下执行，如果在其它dba账户下执行还是有权限的限制，在生成递归sql的时候就有问题了，生成的日志中不会有明细的调试信息，只会包含这些错误和警告。 Skipped error 604 during the execution of N1.SET_TRACE_ON_LOGON *** 2015-01-28 06:27:02.751 dbkedDefDump(): Starting a non-incident diagnostic dump (flags=0x0, level=0, mask=0x0) ----- Error Stack Dump ----- ORA-00604: error occurred at recursive SQL level 1 ORA-01031: insufficient privileges ORA-06512: at line 6 创建了trigger之后，我们再次运行脚本，就会得到预期的ora错误,我们假设最后一步的逻辑很复杂，我们还不能直观的分析出到底是哪出了错。 COUNT(*) ---------- 59 select *from catt * ERROR at line 1: ORA-00942: table or view does not exist 查看生成的trace文件 -rw-r----- 1 ora11g dba 1145 Jan 28 07:05 TEST01_ora_8380_N1_10046.trm -rw-r----- 1 ora11g dba 126028 Jan 28 07:05 TEST01_ora_8380_N1_10046.trc 如果通过tkprof简单格式化trace文件的话，很可能把重要的错误信息也给过滤掉了。我们可以完全自己手工来查看trace文件。在trace文件中，我们使用关键字”err=“或者"ERROR"来查找一般都能有所收获。


EXEC #139804991168728:c=1000,e=815,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=2853959010,tim=1422457558003768
FETCH #139804991168728:c=0,e=54,p=0,cr=2,cu=0,mis=0,r=0,dep=1,og=4,plh=2853959010,tim=1422457558003877
CLOSE #139804991168728:c=0,e=9,dep=1,type=3,tim=1422457558004037
=====================
PARSE ERROR #139804993076144:len=17 dep=0 uid=36 oct=3 lid=36 tim=1422457558004335 err=942
select *from catt 
WAIT #139804993076144: nam='SQL*Net break/reset to client' ela= 68 driver id=1650815232 break?=1 p3=0 obj#=-1 tim=1422457558004957
WAIT #139804993076144: nam='SQL*Net break/reset to client' ela= 559 driver id=1650815232 break?=0 p3=0 obj#=-1 tim=1422457558005796
WAIT #139804993076144: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1422457558005865
WAIT #139804993076144: nam='SQL*Net message from client' ela= 2665 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=1422457558008607
XCTEND rlbk=0, rd_only=1, tim=1422457558008854
CLOSE #139804993076144:c=0,e=15,dep=0,type=0,tim=1422457558009096
CLOSE #139804993033288:c=0,e=15,dep=0,type=0,tim=1422457558009186

通过这些日志，我们可以很明显的看到出现了解析错误，报错code为942 对应的sql语句是select *from catt 最后的重要步骤就是需要禁用10046事件，然后删除这个trigger.


CREATE OR REPLACE TRIGGER sys.set_trace_on_logon
AFTER LOGON ON DATABASE
BEGIN
  if (  user not in ('SYS','SYSTEM' )) then
    EXECUTE IMMEDIATE 'alter session set statistics_level=ALL';
    EXECUTE IMMEDIATE 'alter session set max_dump_file_size=UNLIMITED';
    EXECUTE IMMEDIATE 'alter session set tracefile_identifier='''||user||'_10046''';
    EXECUTE IMMEDIATE 'alter session set events ''10046 trace name context forever, level 12''';
  end if; 
END set_10046_trace_on_logon;
/
drop trigger sys.set_trace_on_logon;