20180508-Oracle 性能优化-trigger问题

问题现象 :

谓词通过唯一性索引，更新一条记录，耗时很长；
通过 AWR 查看 TOP SQL ，这个UPDATE SQL 语句逻辑读，物理读等都 非常高；
初步怀疑执行计划出现变化， index unique scan 变成 table access full ，但是通过 DBA_HIST_SQL_PLAN 发现近期执行计划并没有改变；
通过 10046 查看 SQL 执行计划，显示这个更新语句耗时，逻辑读，物理读等都 非常低；

问题原因 :

触发器导致的；
更新语句 A 执行前，触发了 trigger B ，其中 trigger B 内部执行较慢，导致 A 一直在等待；
由于 trigger B 执行过程中占用大量的资源，在 AWR 中会将 trigger 消耗的资源也加到 update 语句上，有时可能会干扰问题诊断；

问题结论：

当发现某个语句执行突然变慢了，执行时间，逻辑读，物理读等突然飙升，
在排查数据量，执行计划等都没有异常，可以查看是否存在不合理的触发器；

问题重现举例 :

—1 创建测试用户

SQL> create user c##chenjch identified by a;
SQL> grant connect,resource,dba to c##chenjch;

—2 创建测试表，索引并插入数据

SQL> create table test01(id number);
SQL> create table test02 as select * from dba_objects;
SQL>
begin
  for i in 1 .. 100000 loop
    insert into test01 values (i);
    commit;
  end loop;
end;
SQL> create unique index ui_test_id on test01(id); 
SQL> insert into test02 select * from test02; 
SQL> commit; 
/
/
select count(*) from test02;   ---2329536

—3 创建触发器

SQL>
create or replace trigger TG_TEST01_UPDATE
  BEFORE UPDATE ON TEST01
  for each row
begin
  insert into test02
    SELECT * FROM TEST02;
end;

—4 生成快照

SQL>
begin
  dbms_workload_repository.create_snapshot;
end;
SQL>
select SNAP_ID, BEGIN_INTERVAL_TIME, FLUSH_ELAPSED, SNAP_LEVEL
  from dba_hist_snapshot
 order by snap_id desc;

—5 update test01 通过唯一性索引，更新一条数据

SQL> set timing on
SQL> set autotrace on
SQL> alter session set tracefile_identifier='10046';
Session altered.
Elapsed: 00:00:00.00
SQL> ALTER SESSION SET EVENTS '10046 trace name context forever, level 12';
Session altered.
Elapsed: 00:00:00.03

—耗时19秒

SQL> update test01 set id=1000000000 where id=1;
1 row updated.
Elapsed: 00:00:19.49
Execution Plan
----------------------------------------------------------
Plan hash value: xxxxx
--------------------------------------------------------------------------------

| Id  | Operation          | Name       | Rows  | Bytes | Cost (%CPU)| Time

--------------------------------------------------------------------------------

|   0 | UPDATE STATEMENT   |            |     1 |    13 |     1   (0)| 00:00:01
|   1 |  UPDATE            | TEST01     |       |       |            |
|*  2 |   INDEX UNIQUE SCAN| UI_TEST_ID |     1 |    13 |     1   (0)| 00:00:01
-------------------------------------------------------------------------------
Predicate Information (identified by operation id):
--------------------------------------------------
   2 - access("ID"=1)
Statistics
---------------------------------------------------------
        637  recursive calls
     351598  db block gets
     103565  consistent gets
      38393  physical reads
  374300700  redo size
        858  bytes sent via SQL*Net to client
        962  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
        102  sorts (memory)
          0  sorts (disk)
          1  rows processed

SQL> ALTER SESSION SET EVENTS '10046 trace name context off';
Session altered.
Elapsed: 00:00:00.01

SQL> select value from v$diag_info where name='Default Trace File';
VALUE
-----------------------------------------------------------------------------
/u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_56542_10046.trc
Elapsed: 00:00:00.06
SQL> @?/rdbms/admin/awrrpt.sql

AWR显示update语句消耗资源很高

select * from table(dbms_xplan.display_cursor('afqfknn3nwwpw'));

10046 显示update语句消耗的资源很少；

欢迎关注我的微信公众号"IT小Chen"