风哥教程

培训 . 交流 . 分享
Make progress together!

LogMiner的使用

[复制链接]
内容发布:luashin| 发布时间:2020-5-16 11:01:47
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 Log
SQL> 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-17
2  1  30  52428800  512  2  NO   CURRENT  1567897 27-JUN-17 2.8147E+14 27-JUN-17
3  2  25  52428800  512  2  NO   CURRENT  1567902 27-JUN-17 2.8147E+14
4  2  24  52428800  512  2  YES  INACTIVE  1567900 27-JUN-17 1567902 27-JUN-17
这里当前日志(current)是:
thread 1 sequence 30
thread 2 sequence 25
2.业务用户插入操作
模拟业务用户jingyu插入T2表数据:
2.1 业务用户插入操作
sqlplus jingyu/jingyu@jyzhao
SQL> 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+14
2  1  30  52428800  512  2 YES ACTIVE  1567897 27-JUN-17  1572517 27-JUN-17
3  2  25  52428800  512  2 YES ACTIVE  1567902 27-JUN-17  1572521 27-JUN-17
4  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+14
2  1  32  52428800  512  2 YES ACTIVE  1574293 27-JUN-17 1575480 27-JUN-17
3  2  27  52428800  512  2 YES ACTIVE  1574296 27-JUN-17 1575458 27-JUN-17
4  2  28  52428800  512  2 NO  CURRENT  1575458 27-JUN-17      2.8147E+14
8.确认需要分析的日志
确认之后需要使用LogMiner分析的日志:
8.1 确认需要分析的日志
thread# 1 sequence# 30
thread# 2 sequence# 25
这部分日志肯定是有记录插入操作
thread# 1 sequence# 31
thread# 2 sequence# 26
这部分日志肯定是有记录删除操作
thread# 1 sequence# 32
thread# 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 -lrth
total 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_contents
set lines 180 pages 500
col username format a8
col 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" = 'YSWGNNLCLMYWPSLQ
ETVLGQJRKQIEAMOEYUFNRUQULVFRVPEDRV' and ROWID = 'AAAVWVAAGAAAAHnABj';
UNKNOWN   1575420    27-JUN-17  update "JINGYU"."T2" set "CONTENTS" = 'xxx' where "CONTENTS" = 'WHCWFOZVLJWHFWLJ
DNVSMQTORGJFFXYADIOJZWJCDDOYXAOQJG' 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;
--停止logmnr
exec 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 180
SQL> /
    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-17
2 1  36   52428800  512  2 NO  CURRENT  1591935 27-JUN-17 2.8147E+14
3 2  29   52428800  512  2 YES INACTIVE  1590594 27-JUN-17 1591938 27-JUN-17
4  2  30   52428800  512  2 NO  CURRENT  1591938 27-JUN-17 2.8147E+14
1,36
2,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;
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps724D.tmp.jpg
另外也可以用基于事务级别的视图进行查询阻塞的源头,如下:
示例2
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;
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps724E.tmp.jpg
示例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_TYPE
FROM gV$SESSION A
INNER JOIN gV$LOCKED_OBJECT B
ON A.SID=b.SESSION_ID
INNER JOIN DBA_OBJECTS C
ON B.OBJECT_ID=c.OBJECT_ID
WHERE A.WAIT_CLASS='Idle'
AND A.SECONDS_IN_WAIT>1
以上示例1-3,只能查当前阻塞与被阻塞的信息,一旦ash在内存中被”flush“掉,就无法获取历史阻塞信息。
    虽然Oracle没有直接提供查找阻塞源头sql的方法,然而根据项目中多次实践、探究,梳理了间接查找历史阻塞会话的方法
1、先确定好环境中阻塞发生的时间点,拉取ASH报告
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps725F.tmp.jpg
根据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高亮显示相同功能,我们可以很清楚的看出,阻塞会话阻塞的其他会话
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7260.tmp.jpg
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7271.tmp.jpg
如上红色的是阻塞者,绿色是被阻塞会话
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不要commit
SQL> col spid for a10
SQL> col tracefile for a80
SQL> set pagesize 200 linesize 200
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
---  ------- ----  ---------------------------------------------------------
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
第二个会话执行update
SQL> set time on
15:08:42 SQL> col spid for a10
15:08:45 SQL> col tracefile for a80
15:08:45 SQL> set pagesize 200 linesize 200
15: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;
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7281.tmp.png
会话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_TYPE
FROM gV$SESSION A
INNER JOIN gV$LOCKED_OBJECT B
ON A.SID=b.SESSION_ID
INNER JOIN DBA_OBJECTS C
ON B.OBJECT_ID=c.OBJECT_ID
WHERE A.WAIT_CLASS='Idle'
AND A.SECONDS_IN_WAIT>1
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7292.tmp.jpg
查询被阻塞的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;
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps7293.tmp.jpg
可以查询出阻塞与被阻塞的会话信息
生成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 PM
Time 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          1
2  Top SQL Statements  .71 | 99.8           1
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
ADDM中的行锁等待,正是被阻塞的SQL
          Findings and Recommendations
          ----------------------------
Finding 1: Row Lock Waits
Impact 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 Statements
Impact is .71 active sessions, 99.8% of total activity.
-------------------------------------------------------
SQL statements consuming significant database time were found. These
statements 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 limits
of 1 milliseconds.
Session connect and disconnect calls were not consuming significant database
time.
Hard parsing of SQL statements was not consuming significant database time.
目前ASH视图可以查看历史被阻塞会话的sql_text
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72A3.tmp.jpg
以上的脚本以及报告均不能查询出阻塞根源执行的sql语句,只能查出阻塞源session id,由此可以借助logmnr挖取online redo log或者archive log事务信息。
    需要注意的是在logmnr挖取日志之前需要在数据库开启最小附加日志,否则在v$logmnr_contents中session#,serail#,seesion_info等字段不会有任何信息。
    由于已经知道了阻塞源头的sid,serial#,可以在logmnr视图中根据会话信息查找事务信息
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72B4.tmp.jpg
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72B5.tmp.jpg
可以看到logmnr挖取的日志与上面脚本查出的start_scn,xid相匹配
另一部分,查询被阻塞的sql在logmnr里并不存在
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72C6.tmp.jpg
被阻塞的sql由于未执行成功,所以在redo里并不会记录
现在在会话1提交
18:09:51 SQL> commit;
Commit complete.
会话1在sqlplus提交之后,redo log从set transaction read write到commit标志着一个事务的结束,如果redo里没有commit那说明事务还一直在持续。也只有挖取日志才能将事务分析清除。
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72C7.tmp.jpg
总结:如果要查出对象类阻塞(DML,DDL)的源头以及有关sql信息,只能通过挖取redo log事务日志的方式,而且需要保证追加日志要开启。在logmnr里根据session id以及事务start_scn可以查询阻塞源头的事务信息。一个事务不能完成往往就是3个原因,事务内的SQL执行本身被Hang住,被其他事务阻塞、其他事务执行慢。
追加日志与v$logmnr_content会话字段信息
未开启追加日志前v$logmnr_content,seesion#列没有会话信息
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72D7.tmp.jpg
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72D8.tmp.jpg
开启追加日志之后
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72E9.tmp.jpg
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72EA.tmp.jpg
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72FA.tmp.jpg
结论:只有开启最小追加日志之后,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;
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps72FB.tmp.jpg
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进制的归档日志ID
xx2:当前行的block id
xx3:16进制的当前行block id的偏移量
ssn:SQL sequence number
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps730C.tmp.jpg
file:///C:\Users\ThinkPad\AppData\Local\Temp\ksohtml\wps731D.tmp.jpg
附Oracle Doc
RS_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 row
1 - 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.


上一篇:MySQL 8.0数据库安装实践
下一篇:10046事件跟踪会话SQL
回复

使用道具 举报

内容发布:gsmer2009| 发布时间:2020-5-18 09:37:31
很好的资料,谢谢分享~~~~~~~~~~~~~
回复 支持 反对

使用道具 举报

1框架
您需要登录后才可以回帖 登录 | 立即注册

本版积分规则

热门文章教程

  • PostgreSQL数据库中文培训手册
  • Oracle Database 12c 数据库100个新特性与
  • Navicat for MySQL最新版下载地址及注册码
  • oracle 12c RAC 日志频繁切换 checkpoint n
  • 风哥Oracle数据库巡检工具V1.0(附2.6网页
  • MySQL权威指南(第2版)PDF电子书下载
快速回复 返回顶部 返回列表