LogMiner的使用 LogMiner是用于Oracle日志挖掘的利器。LogMiner是Oracle公司从产品8i以后提供的一个实际非常有用的分析工具，使用该工具可以轻松获得Oracle重做日志文件（归档日志文件）中的具体内容，LogMiner分析工具实际上是由一组PL/SQL包和一些动态视图组成，它作为Oracle数据库的一部分来发布，是Oracle公司提供的一个完全免费的工具。 本文主要演示LogMiner的使用，直观展示LogMiner的作用。环境：Oracle 11.2.0.4 RAC 1.查询当前日志组使用sys用户查询Oracle数据库的当前日志组:1.1 Current LogSQL> select * from v$log;GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME----- ---- --- --- ---- ----- --- ----- ---- ------------ ------------ ------------1 1 29 52428800 512 2 YES INACTIVE 1547838 25-JUN-17 1547840 25-JUN-172 1 30 52428800 512 2 NO CURRENT 1567897 27-JUN-17 2.8147E+14 27-JUN-173 2 25 52428800 512 2 NO CURRENT 1567902 27-JUN-17 2.8147E+144 2 24 52428800 512 2 YES INACTIVE 1567900 27-JUN-17 1567902 27-JUN-17这里当前日志（current）是：thread 1 sequence 30thread 2 sequence 25 2.业务用户插入操作模拟业务用户jingyu插入T2表数据：2.1 业务用户插入操作sqlplus jingyu/jingyu@jyzhaoSQL> select count(1) from t2; COUNT(1)---------- 0 SQL> insert into t2 select rownum, rownum, rownum, dbms_random.string('b',50) from dual connect by level <= 100000 order by dbms_random.random;commit;100000 rows created. SQL> commit;Commit complete. SQL> select count(1) from t2; COUNT(1)----------100000 3. 归档日志切换为了区分每个日志的不同操作，这里对数据库进行手工归档切换，模拟现实中实际的归档切换。3.1 模拟归档日志切换SQL> alter system archive log current;System altered. SQL> select * from v$log;GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME---- ---- ----- ---------- ----- ----- --- ------- ------ ----- ----- ----1 1 31 52428800 512 2 NO CURRENT 1572517 27-JUN-17 2.8147E+142 1 30 52428800 512 2 YES ACTIVE 1567897 27-JUN-17 1572517 27-JUN-173 2 25 52428800 512 2 YES ACTIVE 1567902 27-JUN-17 1572521 27-JUN-174 2 26 52428800 512 2 NO CURRENT 1572521 27-JUN-17 2.8147E+14 4.业务用户删除操作模拟业务用户jingyu删除T2表部分数据：4.1 业务用户删除操作SQL> delete from t2 where id < 10000;9999 rows deleted. SQL> commit;Commit complete. SQL> select count(1) from t2; COUNT(1)---------- 90001 5.归档日志切换为了区分每个日志的不同操作，这里对数据库进行手工归档切换，模拟现实中实际的归档切换。5.1 模拟归档日志切换SQL> alter system archive log current;System altered. SQL> select * from v$log; GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME---------- ---------- ---------- ---------- ---------- ---------- --- ---------------- ------------- ------------ ------------ ------------ 1 1 31 52428800 512 2 YES ACTIVE 1572517 27-JUN-17 1574293 27-JUN-17 2 1 32 52428800 512 2 NO CURRENT 1574293 27-JUN-17 2.8147E+14 3 2 27 52428800 512 2 NO CURRENT 1574296 27-JUN-17 2.8147E+14 4 2 26 52428800 512 2 YES ACTIVE 1572521 27-JUN-17 1574296 27-JUN-17 6.业务用户更新操作模拟业务用户jingyu更新T2表部分数据：6.1 业务用户更新操作SQL> update T2 SET contents = 'xxx' where id > 99998;2 rows updated. SQL> commit;Commit complete. 7.归档日志切换为了区分每个日志的不同操作，这里对数据库进行手工归档切换，模拟现实中实际的归档切换。7.1 模拟归档日志切换SQL> alter system archive log current;System altered. SQL> select * from v$log; GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME------ ----- ------ --- ----- ---- --- ----- ----- ----- ----- -----1 1 33 5242880 512 2 NO CURRENT 1575480 27-JUN-17 2.8147E+142 1 32 52428800 512 2 YES ACTIVE 1574293 27-JUN-17 1575480 27-JUN-173 2 27 52428800 512 2 YES ACTIVE 1574296 27-JUN-17 1575458 27-JUN-174 2 28 52428800 512 2 NO CURRENT 1575458 27-JUN-17 2.8147E+14 8.确认需要分析的日志确认之后需要使用LogMiner分析的日志：8.1 确认需要分析的日志thread# 1 sequence# 30thread# 2 sequence# 25这部分日志肯定是有记录插入操作 thread# 1 sequence# 31thread# 2 sequence# 26这部分日志肯定是有记录删除操作 thread# 1 sequence# 32thread# 2 sequence# 27这部分日志肯定是有记录更新操作 9.备份归档日志将相关的归档都copy备份出来：9.1 将相关的归档都copy备份出来RUN {allocate channel dev1 device type disk format '/tmp/backup/arc_%h_%e_%t';backup as copy archivelog sequence 30 thread 1;backup as copy archivelog sequence 31 thread 1;backup as copy archivelog sequence 32 thread 1;backup as copy archivelog sequence 25 thread 2;backup as copy archivelog sequence 26 thread 2;backup as copy archivelog sequence 27 thread 2;release channel dev1;}备份出来的归档日志文件如下：[oracle@jyrac1 backup]$ ls -lrthtotal 17M-rw-r----- 1 oracle asmadmin 2.3M Jun 27 21:50 arc_1_30_947800247-rw-r----- 1 oracle asmadmin 591K Jun 27 21:50 arc_1_31_947800249-rw-r----- 1 oracle asmadmin 143K Jun 27 21:50 arc_1_32_947800250-rw-r----- 1 oracle asmadmin 9.5M Jun 27 21:50 arc_2_25_947800251-rw-r----- 1 oracle asmadmin 3.6M Jun 27 21:50 arc_2_26_947800253-rw-r----- 1 oracle asmadmin 77K Jun 27 21:50 arc_2_27_947800254 10.使用LogMiner分析使用LogMiner分析归档日志：--使用LogMiner分析归档日志--应该有插入操作的日志begin dbms_logmnr.add_logfile('/tmp/backup/arc_1_30_947800247'); dbms_logmnr.add_logfile('/tmp/backup/arc_2_25_947800251'); dbms_logmnr.start_logmnr(Options=>dbms_logmnr.dict_from_online_catalog);end;/ --应该有删除操作的日志begin dbms_logmnr.add_logfile('/tmp/backup/arc_1_31_947800249'); dbms_logmnr.add_logfile('/tmp/backup/arc_2_26_947800253'); dbms_logmnr.start_logmnr(Options=>dbms_logmnr.dict_from_online_catalog);end;/ --应该有更新操作的日志begin dbms_logmnr.add_logfile('/tmp/backup/arc_1_32_947800250'); dbms_logmnr.add_logfile('/tmp/backup/arc_2_27_947800254'); dbms_logmnr.start_logmnr(Options=>dbms_logmnr.dict_from_online_catalog);end;/ 查询v$logmnr_contentsset lines 180 pages 500col username format a8col sql_redo format a50 select username,scn,timestamp,sql_redo from v$logmnr_contents where table_name='T2'; select username,scn,timestamp,sql_redo from v$logmnr_contents where username='JINGYU';select username,scn,timestamp,sql_redo from v$logmnr_contents where sql_redo like '%JINGYU%';select username,scn,timestamp,sql_redo from v$logmnr_contents where sql_redo like 'insert%JINGYU%';select username,scn,timestamp,sql_redo from v$logmnr_contents where sql_redo like 'delete%JINGYU%';select username,scn,timestamp,sql_redo from v$logmnr_contents where sql_redo like 'update%JINGYU%'; 实验发现，以username为条件无法查询到相关记录，最终确认username都是unknown而不是真正执行语句的业务用户jingyu。 而挖掘出的日志sql_redo这个字段是完整的SQL，可以采用like的方式查询，比如我分析更新操作的日志，就可以得到下面这样的结果：--应该有更新操作的日志SQL> begin dbms_logmnr.add_logfile('/tmp/backup/arc_1_32_947800250'); dbms_logmnr.add_logfile('/tmp/backup/arc_2_27_947800254'); dbms_logmnr.start_logmnr(Options=>dbms_logmnr.dict_from_online_catalog); end;/PL/SQL procedure successfully completed. SQL> select count(1) from v$logmnr_contents; COUNT(1)---------- 388 SQL> select username,scn,timestamp,sql_redo from v$logmnr_contents where username='JINGYU';no rows selected SQL> select username,scn,timestamp,sql_redo from v$logmnr_contents where sql_redo like '%JINGYU%';USERNAME SCN TIMESTAMP SQL_REDO-------- --------- --------- ----------------------------------------------UNKNOWN 1575420 27-JUN-17 update "JINGYU"."T2" set "CONTENTS" = 'xxx' where "CONTENTS" = 'YSWGNNLCLMYWPSLQETVLGQJRKQIEAMOEYUFNRUQULVFRVPEDRV' and ROWID = 'AAAVWVAAGAAAAHnABj';UNKNOWN 1575420 27-JUN-17 update "JINGYU"."T2" set "CONTENTS" = 'xxx' where "CONTENTS" = 'WHCWFOZVLJWHFWLJDNVSMQTORGJFFXYADIOJZWJCDDOYXAOQJG' and ROWID = 'AAAVWVAAGAAAAOYAAE';至此，LogMiner基本的操作实验已完成。 附：与LogMiner有关的一些操作命令参考：conn / as sysdba --安装LOGMINER@$ORACLE_HOME/rdbms/admin/dbmslmd.sql;@$ORACLE_HOME/rdbms/admin/dbmslm.sql;@$ORACLE_HOME/rdbms/admin/dbmslms.sql;@$ORACLE_HOME/rdbms/admin/prvtlm.plb; --停止logmnrexec dbms_logmnr.end_logmnr --查询附加日志开启情况：select supplemental_log_data_min, supplemental_log_data_pk, supplemental_log_data_ui from v$database; --开启附加日志alter database add supplemental log data; --取消补充日志alter database drop supplemental log data (primary key) columns;alter database drop supplemental log data (unique) columns;alter database drop supplemental log data; --最后一个即为新的归档select name,dest_id,thread#,sequence# from v$archived_log; 最后确认如果开启了附加日志，username就可以捕获到正确的值：SQL> set lines 180SQL> / GROUP# THREAD# SEQUENCE# BYTES BLOCKSIZE MEMBERS ARC STATUS FIRST_CHANGE# FIRST_TIME NEXT_CHANGE# NEXT_TIME---------- ---------- ------ ---- ---- ----- --- ----- ----- ---- ---- ----1 1 35 52428800 512 2 YES INACTIVE 1590589 27-JUN-17 1591935 27-JUN-172 1 36 52428800 512 2 NO CURRENT 1591935 27-JUN-17 2.8147E+143 2 29 52428800 512 2 YES INACTIVE 1590594 27-JUN-17 1591938 27-JUN-174 2 30 52428800 512 2 NO CURRENT 1591938 27-JUN-17 2.8147E+141,362,30 SQL> update t2 set contents = 'aaa' where id = 44449;1 row updated. SQL> commit;Commit complete. RUN {allocate channel dev1 device type disk format '/tmp/backup/arc_%h_%e_%t';backup as copy archivelog sequence 36 thread 1;backup as copy archivelog sequence 30 thread 2;release channel dev1;} begin dbms_logmnr.add_logfile('/tmp/backup/arc_1_36_947808116'); dbms_logmnr.add_logfile('/tmp/backup/arc_2_30_947808118'); dbms_logmnr.start_logmnr(Options=>dbms_logmnr.dict_from_online_catalog);end;/ SQL> select username,scn,timestamp,sql_redo from v$logmnr_contents where username='JINGYU';USERNAME SCN TIMESTAMP SQL_REDO-------- ------- --------- -------------------------------------JINGYU 1593448 27-JUN-17 set transaction read write;JINGYU 1593448 27-JUN-17 update "JINGYU"."T2" set "CONTENTS" = 'aaa' where "CONTENTS" = 'WZTSQZWYOCNDFKSMNJQLOLFUBRDOHCBMKXBHAPJSHCMWBYZJVH' and ROWID = 'AAAVWVAAGAAAACLAAL';JINGYU 1593450 27-JUN-17 commit;可以看到，开启附加日志，就可以正常显示username的信息。利用Logmnr分析历史阻塞会话之前基于ASH会话级视图可以查当前阻塞以及被阻塞的会话信息，如下：示例1：select sample_time,sql_text,session_id,session_serial#,session_type,b.sql_id,event,blocking_session,blocking_session_serial#,blocking_inst_id from gv$active_session_history a,gv$sqlarea b where session_id=5 and session_serial#=171 and a.SQL_ID=b.SQL_ID order by sample_id asc;[img=554,197]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps724D.tmp.jpg[/img] 另外也可以用基于事务级别的视图进行查询阻塞的源头，如下：示例2with ltr as ( select to_char(sysdate,'YYYYMMDDHH24MISS') TM, s.inst_id, s.sid, s.serial#, s.status, s.sql_id, s.sql_child_number, s.prev_sql_id, xid, t.start_scn, to_char(t.start_date,'YYYY-MM-DD HH24:MI:SS') start_time, e.TYPE,e.block, e.ctime/3600 runtime_Hour, decode(e.CTIME, 0, (sysdate - t.start_date) * 3600*24, e.ctime) el_second -- q.sql_text from gv$transaction t, gv$session s,gv$transaction_enqueue e where t.start_date <= sysdate - interval '1' second /*查询开始多少秒的事务*/ and t.addr = s.taddr --and s.sql_child_number = q.CHILD_NUMBER(+) --and s.sql_id = q.sql_id(+) and s.prev_sql_id = q.sql_id(+) and t.addr = e.addr(+) ) select ltr.* , (select q1.sql_text from gv$sql q1 where ltr.prev_sql_id = q1.sql_id(+) and rownum = 1) prev_sql_text , (select q1.sql_text from gv$sql q1 where ltr.sql_id = q1.sql_id(+) and ltr.sql_child_number = q1.CHILD_NUMBER(+)) sql_text from ltr ltr;[img=554,47]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps724E.tmp.jpg[/img] 示例1是基于事务，主要查询的是还在进行中，未完成的事务，此脚本虽然可以查出阻塞的源头，但是无法取得阻塞的SQL。 示例3 SELECT A.INST_ID,A.SID,A.SERIAL#,A.USERNAME,A.EVENT,A.WAIT_CLASS,A.SECONDS_IN_WAIT,A.PREV_EXEC_START,b.LOCKED_MODE,C.OWNER,C.OBJECT_NAME,C.OBJECT_TYPEFROM gV$SESSION AINNER JOIN gV$LOCKED_OBJECT BON A.SID=b.SESSION_IDINNER JOIN DBA_OBJECTS CON B.OBJECT_ID=c.OBJECT_IDWHERE A.WAIT_CLASS='Idle'AND A.SECONDS_IN_WAIT>1以上示例1-3，只能查当前阻塞与被阻塞的信息，一旦ash在内存中被”flush“掉，就无法获取历史阻塞信息。 虽然Oracle没有直接提供查找阻塞源头sql的方法，然而根据项目中多次实践、探究，梳理了间接查找历史阻塞会话的方法1、先确定好环境中阻塞发生的时间点，拉取ASH报告[img=553,331]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps725F.tmp.jpg[/img] 根据blocking session的% Activity与top sessions中一样，可以判断出，会话4189阻塞了上面会话6245 2、在开启追加日志的前提下，捞取阻塞会话信息阻塞会话与被阻塞会话在logmnr中的记录select scn, timestamp, start_scn, commit_scn, xid, operation, seg_name, sql_redo, machine_name, session_info, thread#, session#, serial# from archdump where ( (session# = 4189 and serial# = 2382) or --blocking (session# = 2925 and serial# = 4336) or --blocking (session# = 3321 and serial# = 45918) or --blocking (session# = 6245 and serial# = 39240) or --blocked (session# = 2688 and serial# = 57682) --blocked (session# = 2846 and serial# = 4244) or --blocked (session# = 3320 and serial# = 42418) ) --blocked and scn >= 791019425 and scn <= 791125745 and seg_name = 'FRAME_ONLINEUSER' order by scn asc 3、在借助PL/SQL高亮显示相同功能，我们可以很清楚的看出，阻塞会话阻塞的其他会话[img=358,172]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7260.tmp.jpg[/img] [img=554,183]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7271.tmp.jpg[/img] 如上红色的是阻塞者，绿色是被阻塞会话 4、总结 要分析历史阻塞会话，可借助归档日志来分析，但是前提是追加日志要开启；在确定好时间点的情况下，需要知道阻塞会话的session_id，借助logmnr分析上下会话之间的关系按照scn进行排序后，如果阻塞源头的sql语句在后续scn中出现相同的sql语句，基本可以确定此sql为阻塞的源头。Oracle阻塞会话使用Redo Log排查 Oracle的会话被阻塞后，虽然说可以通过脚本、Trace跟踪、生成ASH或ADDM查看被阻塞的对象及SQL语句，但是无法获取作为阻塞源头会话的SQL语句。其原因是阻塞其它会话的Session，在v$session中status为'INACTIVE'，此状态意思是没有SQL语句正在执行（在等待其他操作），所以sql_id为空，自然在v$sql中查不到sql text。 下面构建2个会话，模拟事务被阻塞的情景第一个会话事务执行update不要commitSQL> col spid for a10SQL> col tracefile for a80SQL> set pagesize 200 linesize 200SQL> select distinct(m.sid),s.serial#,p.spid,p.tracefile from v$mystat m,v$session s,v$process p where m.sid=s.sid and s.paddr=p.addr;SID SERIAL# SPID TRACEFILE--- ------- ---- ---------------------------------------------------------858 247 83223 /u01/app/oracle/diag/rdbms/orcl/orcl1/trace/orcl1_ora_83223.trc SQL> set time on 14:58:53 SQL> update test set name='aa' where id=1;1 row updated.15:02:18 SQL> 没有commit 第二个会话执行updateSQL> set time on15:08:42 SQL> col spid for a1015:08:45 SQL> col tracefile for a8015:08:45 SQL> set pagesize 200 linesize 20015:08:45 SQL> select distinct(m.sid),s.serial#,p.spid,p.tracefile from v$mystat m,v$session s,v$process p where m.sid=s.sid and s.paddr=p.addr;SID SERIAL# SPID TRACEFILE--- ------- ---------- --------------------------------------------113 33109 /u01/app/oracle/diag/rdbms/orcl/orcl2/trace/orcl2_ora_33109.trc 15:08:45 SQL> update test set name='aaa' where id=1;由于会话1没有commit，会话2被hang住 脚本查下v$transaction,v$session会话信息与事务信息之间的联系--下面SQL 查询数据库中正在执行大于秒的事务信息及SQL Text，一部分先前执行的SQL及非对象锁事务with ltr as ( select to_char(sysdate,'YYYYMMDDHH24MISS') TM, s.inst_id, s.sid, s.serial#, s.status, s.sql_id, s.sql_child_number, s.prev_sql_id, xid, t.start_scn, to_char(t.start_date,'YYYY-MM-DD HH24:MI:SS') start_time, e.TYPE,e.block, e.ctime/3600 runtime_Hour, decode(e.CTIME, 0, (sysdate - t.start_date) * 3600*24, e.ctime) el_second -- q.sql_text from gv$transaction t, gv$session s,gv$transaction_enqueue e where t.start_date <= sysdate - interval '1' second /*查询开始多少秒的事务*/ and t.addr = s.taddr --and s.sql_child_number = q.CHILD_NUMBER(+) --and s.sql_id = q.sql_id(+) and s.prev_sql_id = q.sql_id(+) and t.addr = e.addr(+) ) select ltr.* , (select q1.sql_text from gv$sql q1 where ltr.prev_sql_id = q1.sql_id(+) and rownum = 1) prev_sql_text , (select q1.sql_text from gv$sql q1 where ltr.sql_id = q1.sql_id(+) and ltr.sql_child_number = q1.CHILD_NUMBER(+)) sql_text from ltr ltr;[img=554,542]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7281.tmp.png[/img] 会话1 sid：858，serial#:247，事务开始的start_scn：8308839，start_scn很重要，在redo log里记录了事务起始执行的scn。如上可以看到，sql_text虽然为空，但是数据库v$session会记录会话信息中最后一条执行成功的prev_sql_id,由此可在v$sql中查找sql_text。不过虽然知道prev_sql_text，但是此sql文本并不能保证就是阻塞事务的sql文本，因为此sql可能会是select或者其他对象DML语句，如select count(*) from dba_users;另外可以发现，只有事务未完成的会话才会在v$transaction中有记录，会话2由于被hang住所以事务还没开始。还可以查询会话与被锁对象之间的联系，其目的都是判断会话是否被阻塞，或者是因为其他非DML、DDL因素引起的表锁或者事务锁--判断哪个SESSION执行了DML（Insert/Update/Delete） 但是未提交 （Commit ），引起的行锁SELECT A.INST_ID,A.SID,A.SERIAL#,A.USERNAME,A.EVENT,A.WAIT_CLASS,A.SECONDS_IN_WAIT,A.PREV_EXEC_START,b.LOCKED_MODE,C.OWNER,C.OBJECT_NAME,C.OBJECT_TYPEFROM gV$SESSION AINNER JOIN gV$LOCKED_OBJECT BON A.SID=b.SESSION_IDINNER JOIN DBA_OBJECTS CON B.OBJECT_ID=c.OBJECT_IDWHERE A.WAIT_CLASS='Idle'AND A.SECONDS_IN_WAIT>1[img=554,243]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7292.tmp.jpg[/img] 查询被阻塞的SQL--dml事务查询阻塞与被阻塞，ill阻塞者select 'alter system kill session ' || chr(39) || bs.sid || ',' ||bs.SERIAL# || ',@' || bs.INST_ID || chr(39) || ';' as "kill blocker on command line", bs.USERNAME blocking_user, bs.MACHINE blocking_machine, bs.program blocking_program, ws.USERNAME blocked_user_Waiting, ws.machine blockd_MACHINE_Waiting, ws.program blockd_program_Waiting, lw.CTIME Waiting_time_second, 'SID ' ||lh.sid || ',' || bs.SERIAL# || '@' || lh.INST_ID || ' is blocking SID' || lw.SID || ',' || ws.serial# || '@' || lw.INST_ID state, ws.SQL_ID blockd_sql_id, qw.SQL_TEXT blocked_sql_Wating, qw.SQL_FULLTEXT blocked_sql_full_text from gv$lock lh, gv$lock lw, gv$session ws, gv$session bs, gv$sql qw where lh.id1 = lw.id1 and lh.id2 = lw.id2 and lw.type in ('TM', 'TX') and lh.kaddr <> lw.KADDR and lh.TYPE = lw.TYPE and lw.LMODE = 0 and lw.INST_ID = ws.INST_ID and lw.sid = ws.SID and lh.INST_ID = bs.INST_ID and lh.SID = bs.SID and ws.SQL_ID = qw.SQL_ID and lw.CTIME > 2;[img=504,289]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7293.tmp.jpg[/img] 可以查询出阻塞与被阻塞的会话信息生成ADDM报告如下： ADDM Report for Task 'TASK_6684' -------------------------------- Analysis Period---------------AWR snapshot range from 2189 to 2193.Time period starts at 17-DEC-19 02.00.23 PMTime period ends at 17-DEC-19 06.00.02 PM Analysis Target---------------Database 'ORCL' with DB ID 1542083228.Database version 11.2.0.4.0.ADDM performed an analysis of instance orcl2, numbered 2 and hosted at rac2. Activity During the Analysis Period-----------------------------------Total database time was 10278 seconds.The average number of active sessions was .71. Summary of Findings------------------- Description Active Sessions Recommendations Percent of Activity ------------------ ------------------- ---------------1 Row Lock Waits .71 | 99.83 12 Top SQL Statements .71 | 99.8 1~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ADDM中的行锁等待，正是被阻塞的SQL Findings and Recommendations ---------------------------- Finding 1: Row Lock WaitsImpact is .71 active sessions, 99.83% of total activity.--------------------------------------------------------SQL statements were found waiting for row lock waits. Recommendation 1: Application Analysis Estimated benefit is .71 active sessions, 99.83% of total activity. ------------------------------------------------------------------- Action Significant row contention was detected in the TABLE "ADMIN.TEST" with object ID 93460. Trace the cause of row contention in the application logic using the given blocked SQL. Related Object Database object with ID 93460. Rationale The SQL statement with SQL_ID "gs5jbusmq794d" was blocked on row locks. Related Object SQL statement with SQL_ID gs5jbusmq794d. update test set name='aaa' where id=1 Rationale The session with ID 858 and serial number 247 in instance number 1 was the blocking session responsible for 100% of this recommendation's benefit.----->addm同样能知道被阻塞与阻塞会话者的信息，与前文用脚本查出的阻塞session id一致 Symptoms That Led to the Finding: --------------------------------- Wait class "Application" was consuming significant database time. Impact is .71 active sessions, 99.83% of total activity. Finding 2: Top SQL StatementsImpact is .71 active sessions, 99.8% of total activity.-------------------------------------------------------SQL statements consuming significant database time were found. Thesestatements offer a good opportunity for performance improvement. Recommendation 1: SQL Tuning Estimated benefit is .71 active sessions, 99.8% of total activity. ------------------------------------------------------------------ Action Investigate the UPDATE statement with SQL_ID "gs5jbusmq794d" for possible performance improvements. You can supplement the information given here with an ASH report for this SQL_ID. Related Object SQL statement with SQL_ID gs5jbusmq794d. update test set name='aaa' where id=1 Rationale The SQL spent only 0% of its database time on CPU, I/O and Cluster waits. Therefore, the SQL Tuning Advisor is not applicable in this case. Look at performance data for the SQL to find potential improvements. Rationale Database time for this SQL was divided as follows: 100% for SQL execution, 0% for parsing, 0% for PL/SQL execution and 0% for Java execution. Rationale Waiting for event "enq: TX - row lock contention" in wait class "Application" accounted for 100% of the database time spent in processing the SQL statement with SQL_ID "gs5jbusmq794d".~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Additional Information ---------------------- Miscellaneous Information-------------------------Wait class "Cluster" was not consuming significant database time.Wait class "Commit" was not consuming significant database time.Wait class "Concurrency" was not consuming significant database time.Wait class "Configuration" was not consuming significant database time.CPU was not a bottleneck for the instance.Wait class "Network" was not consuming significant database time.Wait class "User I/O" was not consuming significant database time.The network latency of the cluster interconnect was within acceptable limitsof 1 milliseconds.Session connect and disconnect calls were not consuming significant databasetime.Hard parsing of SQL statements was not consuming significant database time. 目前ASH视图可以查看历史被阻塞会话的sql_text[img=456,367]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72A3.tmp.jpg[/img] 以上的脚本以及报告均不能查询出阻塞根源执行的sql语句，只能查出阻塞源session id，由此可以借助logmnr挖取online redo log或者archive log事务信息。 需要注意的是在logmnr挖取日志之前需要在数据库开启最小附加日志，否则在v$logmnr_contents中session#,serail#,seesion_info等字段不会有任何信息。 由于已经知道了阻塞源头的sid，serial#，可以在logmnr视图中根据会话信息查找事务信息[img=554,154]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72B4.tmp.jpg[/img] [img=447,336]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72B5.tmp.jpg[/img] 可以看到logmnr挖取的日志与上面脚本查出的start_scn,xid相匹配另一部分，查询被阻塞的sql在logmnr里并不存在[img=554,224]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72C6.tmp.jpg[/img] 被阻塞的sql由于未执行成功，所以在redo里并不会记录 现在在会话1提交18:09:51 SQL> commit;Commit complete.会话1在sqlplus提交之后，redo log从set transaction read write到commit标志着一个事务的结束，如果redo里没有commit那说明事务还一直在持续。也只有挖取日志才能将事务分析清除。[img=554,250]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72C7.tmp.jpg[/img] 总结：如果要查出对象类阻塞（DML,DDL)的源头以及有关sql信息，只能通过挖取redo log事务日志的方式，而且需要保证追加日志要开启。在logmnr里根据session id以及事务start_scn可以查询阻塞源头的事务信息。一个事务不能完成往往就是3个原因，事务内的SQL执行本身被Hang住，被其他事务阻塞、其他事务执行慢。追加日志与v$logmnr_content会话字段信息未开启追加日志前v$logmnr_content，seesion#列没有会话信息[img=462,287]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72D7.tmp.jpg[/img] [img=553,212]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72D8.tmp.jpg[/img] 开启追加日志之后[img=446,254]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72E9.tmp.jpg[/img] [img=408,166]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72EA.tmp.jpg[/img] [img=553,102]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72FA.tmp.jpg[/img] 结论：只有开启最小追加日志之后，Logmnr才会有会话相关信息。V$LOGMNR_CONTENTS确定唯一行SQL> select SCN,start_scn,commit_scn,xid,rs_id,ssn,csf,timestamp "Time Stamp",sql_redo "SQL Redo",session#From V$LOGMNR_CONTENTS t where session#=863 and serial#=3 Order by t.scn,t.rs_id,t.ssn;[img=554,208]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72FB.tmp.jpg[/img] 1、rs_id,ssn确定唯一行，Order by t.scn,t.rs_id,t.ssn基本可以确定sql在redo里的执行顺序；2、csf是sql_redo过长（超过4000字节）其值就为1，从第一个csf=1到最后一个cdf=0代表完整的一行。备注：rs_id：XX1.XX2.XX3 xx1：16进制的归档日志IDxx2：当前行的block idxx3：16进制的当前行block id的偏移量ssn：SQL sequence number[img=554,163]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps730C.tmp.jpg[/img] [img=554,335]file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps731D.tmp.jpg[/img] 附Oracle DocRS_ID VARCHAR2(32) Record set ID. The tuple (RS_ID, SSN) together uniquely identifies a logical row change. This will usually mean one row from V$LOGMNR_CONTENTS, but could be more than one row if a single SQL statement for either the Redo or Undo would be too large to fit within the respective columns SQL_UNDO or SQL_REDO. RS_ID uniquely identifies the redo record that generated the row. SSN NUMBER SQL sequence number. Used in conjunction with RS_ID, this uniquely identifies a logical row change, shown as one or more rows from the V$LOGMNR_CONTENTS view. CSF NUMBER Continuation SQL flag. Possible values are:0 - Indicates SQL_REDO and SQL_UNDO is contained within the same row1 - Indicates that either SQL_REDO or SQL_UNDO is greater than 4000 bytes in size and is continued in the next row returned by the view.