唯一索引扫描消耗数十万的逻辑读——触发器被重复计算到父sql级别中

问题现象:sql_id 49q3u07d1gq00在最近awr周期的早上9点到9点半时段进入了awr top logical sql中,该sql是唯一索引扫描,单次执行平均消耗了10万左右的逻辑读

基本信息:
sql_id 49q3u07d1gq00的历史执行信息:

sys@CRMDB3>@sqlhis_add.sql
Enter value for sql_id: 49q3u07d1gq00
old  27:            and a.sql_id = '&sql_id'
new  27:            and a.sql_id = '49q3u07d1gq00'

BEGIN_TIME          INSTANCE_NUMBER MODULE                                        PLAN_HASH_VALUE       EXEC    PER_GET   PER_ROWS    TIME_MS   PER_READ
------------------- --------------- --------------------------------------------- --------------- ---------- ---------- ---------- ---------- ----------
2015-07-14 09:00:14               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937       1035     101810       .507     735.73       7.92
2015-07-13 09:00:21               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937      16297       4035         .5      32.51        .73
2015-07-12 09:00:28               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        737      80142       .512     547.93       4.13
2015-07-11 09:30:17               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        721      42485        .49    1099.47      54.38
2015-07-11 09:00:09               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        101      42784       .653   28242.53    1746.62
2015-07-10 09:00:30               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        626     124180         .5     888.19        8.6
2015-07-10 00:30:28               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937         73     153057       .589   25345.94    1602.25
2015-07-10 00:00:15               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937         32      52617       .563   54712.96    3174.03
2015-07-09 09:00:44               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        676      82156       .506     587.43       8.35
2015-07-08 09:00:09               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        729     142419       .513     950.26       7.52
2015-07-07 09:00:27               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        791     129498       .508     893.71       8.07
2015-07-06 09:00:21               1 tpengine@wbgapp1 (TNS V1-V3)                       1710364937        608      88258       .484     627.47       9.02
。。。。。。

sql_id 49q3u07d1gq00的执行计划:

sys@CRMDB3>@plan.sql
Enter value for hash_value: 49q3u07d1gq00

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
SQL_ID  49q3u07d1gq00, child number 0
-------------------------------------
 UPDATE SUBS_SPSERVICE SET BILLINGFLAG = :BILLINGFLAG WHERE OID = :OID
AND NVL(BILLINGFLAG, '0') <> :BILLINGFLAG AND REGION = 14

Plan hash value: 1710364937

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name                 | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT                    |                      |       |       |     4 (100)|          |       |       |
|   1 |  UPDATE                             | SUBS_SPSERVICE       |       |       |            |          |       |       |
|   2 |   PARTITION RANGE SINGLE            |                      |     1 |   121 |     4   (0)| 00:00:01 |     2 |     2 |
|*  3 |    TABLE ACCESS BY LOCAL INDEX ROWID| SUBS_SPSERVICE       |     1 |   121 |     4   (0)| 00:00:01 |     2 |     2 |
|*  4 |     INDEX UNIQUE SCAN               | PK_CM_SUBS_SPSERVICE |     1 |       |     3   (0)| 00:00:01 |     2 |     2 |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter(NVL("BILLINGFLAG",0)<>:BILLINGFLAG)
   4 - access("OID"=TO_NUMBER(:OID) AND "REGION"=14)

取了cursor cache中的某个绑定变量的具体值:

sys@CRMDB3>set autotrace traceonly;
sys@CRMDB3>select *
  2    from tbcs.SUBS_SPSERVICE
  3   wHERE OID = '88369193732011'
  4     AND NVL(BILLINGFLAG, '0') <> 1
  5     AND REGION = 14;

1 row selected.


Execution Plan
----------------------------------------------------------
Plan hash value: 2043816665

---------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name                 | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
---------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                   |                      |     1 |   121 |     4   (0)| 00:00:01 |       |       |
|   1 |  PARTITION RANGE SINGLE            |                      |     1 |   121 |     4   (0)| 00:00:01 |     2 |     2 |
|*  2 |   TABLE ACCESS BY LOCAL INDEX ROWID| SUBS_SPSERVICE       |     1 |   121 |     4   (0)| 00:00:01 |     2 |     2 |
|*  3 |    INDEX UNIQUE SCAN               | PK_CM_SUBS_SPSERVICE |     1 |       |     3   (0)| 00:00:01 |     2 |     2 |
---------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   2 - filter(NVL("BILLINGFLAG",0)<>1)
   3 - access("OID"=88369193732011 AND "REGION"=14)


Statistics
----------------------------------------------------------
         36  recursive calls
          0  db block gets
        152  consistent gets
          7  physical reads
          0  redo size
       3005  bytes sent via SQL*Net to client
        520  bytes received via SQL*Net from client
          2  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
          1  rows processed

带入具体的bind value逻辑读也只有100多。

可能的原因:
1 表中的倾斜值:
由于是唯一索引扫描,对于这个sql语句而言是不太有倾斜值的,所以排除了这个问题。

2 构造CR块引起的:
在业务闲暇时段我们采取了select /*+full(SUBS_SPSERVICE)*/count(*) from tbcs.SUBS_SPSERVICE让oracle对SUBS_SPSERVICE做一次全表扫描,此时可以有效的解决延迟块清除、构造CR块等问题的影响,但是排除延迟块后在第二天早上9点到10点还是进入了awr top sql行列,并且单次执行的逻辑读依然达到了十多万左右,这个也排除了是因为CR块等影响。

3 触发器:
跟表tbcs.SUBS_SPSERVICE相关的有6个触发器,分别为:
tbcs.TRG_CHECK_SUBS_SPSERVICE
tbcs.TRG_CHECK_SUBS_SPSERVICE_STM
tbcs.TRG_CS_REC_SUBS_SPSVC_TRYOUT
tbcs.TRG_CBS_SUBS_SPSERVICE
tbcs.TRG_CBS_SUBS_SPSERVICE_15
tbcs.TRG_SPBINDPRD_SUBS_SPSERVICE

其中触发器TBCS.TRG_CBS_SUBS_SPSERVICE中存在如下的代码:

if :new.status=0 and :old.status=0 and :new.enddate=:old.enddate then
      NULL;
  else
      update cs_cu_subs_spservice_list
                  set expiretime=:new.statusdate
                  where subsid=:new.subsid
                  and spcode=:new.spid
                  and servicecode=:new.spbizid
                  and region = :new.region
                  and (expiretime=:old.enddate or (expiretime is null or expiretime>=to_date('20370101','yyyymmdd')) and status=1 );
  end if;
--修正预约失效的业务在月结处理进程中失效时间被更新为零点之后的问题end

else if UPDATING then  --是计费标示变更
     update cs_cu_subs_spservice_list
                  set BILLINGFLAG=:new.BILLINGFLAG
                  where subsid=:new.subsid  —1419200000285166
                  and spcode=:new.spid  —810630
                  and startdate=:new.startdate
                  and servicecode=:new.spbizid  —9980018984
                  and region = :new.region
                  and (expiretime=:old.enddate or (expiretime is null or expiretime>=to_date('20370101','yyyymmdd')) and status=1 );
     --和秦工确认,BILLINGFLAG修改后直接退出
     RETURN;
    end if;
end if ;

上述代码也进入了awr top logical sql中。

触发器中的sql语句的逻辑读会被重复计算到了父级别的sql语句中,而最可能消耗大量逻辑读就是上面的TBCS.TRG_CBS_SUBS_SPSERVICE触发器的相关代码

该代码的执行计划为:

UPDATE CS_CU_SUBS_SPSERVICE_LIST
   SET BILLINGFLAG = :B1
 WHERE SUBSID = :B7
   AND SPCODE = :B6
   AND STARTDATE = :B5
   AND SERVICECODE = :B4
   AND REGION = :B3
   AND (
       EXPIRETIME = :B2 OR
       (EXPIRETIME IS NULL OR EXPIRETIME >= TO_DATE('20370101', 'yyyymmdd'))
       AND STATUS = 1
       )


Plan hash value: 1591679211

---------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name                      | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
---------------------------------------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT                    |                           |       |       |    24 (100)|          |       |       |
|   1 |  UPDATE                             | CS_CU_SUBS_SPSERVICE_LIST |       |       |            |          |       |       |
|   2 |   PARTITION RANGE SINGLE            |                           |     1 |    84 |    24   (0)| 00:00:01 |   KEY |   KEY |
|*  3 |    TABLE ACCESS BY LOCAL INDEX ROWID| CS_CU_SUBS_SPSERVICE_LIST |     1 |    84 |    24   (0)| 00:00:01 |   KEY |   KEY |
|*  4 |     INDEX RANGE SCAN                | IDX_SUBS_SPSERVICELIST    |    20 |       |     4   (0)| 00:00:01 |   KEY |   KEY |
---------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter(("STARTDATE"=:B5 AND "REGION"=:B3 AND ((("EXPIRETIME" IS NULL OR "EXPIRETIME">=TO_DATE(' 2037-01-01
              00:00:00', 'syyyy-mm-dd hh24:mi:ss')) AND TO_NUMBER("STATUS")=1) OR "EXPIRETIME"=:B2)))
   4 - access("SUBSID"=:B7 AND "SPCODE"=:B6 AND "SERVICECODE"=:B4)

目前该sql走的是subsid、SPCODE、SERVICECODE的索引

但是实际查询发现表cs_cu_subs_spservice_list的subsid、SPCODE、SERVICECODE有倾斜数据,最高达到了40多万:

SQL> select *
  2    from (select /*+parallel(CS_CU_SUBS_SPSERVICE_LIST 20)*/SUBSID||'', SPCODE, SERVICECODE, region,count(*)
  3            from tbcs.CS_CU_SUBS_SPSERVICE_LIST
  4           group by SUBSID, SPCODE, SERVICECODE,region
  5           order by count(*) desc)
  6   where rownum < 20
  7  ;
 
SUBSID||''                               SPCODE               SERVICECODE              REGION   COUNT(*)
---------------------------------------- -------------------- ------------------------ ------ ----------
1419200000285166                         810630               9980018984                   14     424111
1419200000285166                         900137               11000002                     14      52303
1419300014905486                         701001               500231883000                 14      43596
1419200001247851                         698026               YDWB                         14      25345
1419300023013352                         600902               6009020705                   14      16066
1419200007950949                         698026               YDWB                         14      10369
1633300001231000                         910008               -XXWDHY                      16       6872
1419200011168237                         801234               110301                       14       6370
1419300014622929                         801234               112324                       14       5992
1419200001450109                         698026               YDWB                         14       5317
1633200020544477                         910008               -XXWDHY                      16       4605
1419300014667224                         801234               112323                       14       4521
1419200006732616                         900675               03203322                     14       4209
1419200006732616                         900635               30040712                     14       4209
1419200006732616                         698001               100100                       14       3993
1419200007887731                         900501               08090006                     14       3881
1419200007887731                         698026               YDWB                         14       3869
1419200001196946                         698026               YDWB                         14       3381
1419200005964444                         698026               YDWB                         14       3122
 
19 rows selected

为了模拟这种现象,我们通过取tbcs.CS_CU_SUBS_SPSERVICE_LIST表的最大倾斜数据,反推出TBCS.SUBS_SPSERVICE的OID和BILLINGFLAG字段,然后重复赋值给原唯一索引扫描sql语句来看消耗的资源:

select OID,BILLINGFLAG
  from TBCS.SUBS_SPSERVICE
 where subsid = 1419200000285166
   and spid = '810630'
   and spbizid = '9980018984'
   and region = 14
   and status <> 0
   and rownum < 10

OID              BILLINGFLAG
---------------  -----------
88375756944223   2
SQL> oradebug setmypid
SQL> oradebug event 10046 trace name context forever,level 12
SQL> set timing on
SQL> set autotrace traceonly;
SQL> UPDATE TBCS.SUBS_SPSERVICE SET BILLINGFLAG = 2 WHERE OID =88375756944223
  2  AND NVL(BILLINGFLAG, '0') <> 3 AND REGION = 14;

1 row updated.

Elapsed: 00:27:26.43

Execution Plan
----------------------------------------------------------
Plan hash value: 1710364937

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name                 | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
----------------------------------------------------------------------------------------------------------------------------
|   0 | UPDATE STATEMENT                    |                      |     1 |   121 |     4   (0)| 00:00:01 |       |       |
|   1 |  UPDATE                             | SUBS_SPSERVICE       |       |       |            |          |       |       |
|   2 |   PARTITION RANGE SINGLE            |                      |     1 |   121 |     4   (0)| 00:00:01 |     2 |     2 |
|*  3 |    TABLE ACCESS BY LOCAL INDEX ROWID| SUBS_SPSERVICE       |     1 |   121 |     4   (0)| 00:00:01 |     2 |     2 |
|*  4 |     INDEX UNIQUE SCAN               | PK_CM_SUBS_SPSERVICE |     1 |       |     3   (0)| 00:00:01 |     2 |     2 |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   3 - filter(NVL("BILLINGFLAG",0)<>3)
   4 - access("OID"=88375756944223 AND "REGION"=14)


Statistics
----------------------------------------------------------
         38  recursive calls
         60  db block gets
     420009  consistent gets
     272579  physical reads
      12224  redo size
        831  bytes sent via SQL*Net to client
        872  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
          1  rows processed

oracle这里将触发器的资源消耗也记录到了父级别的sql语句中。

10046 event trace中也看见这个倾斜值造成了大量的逻辑读:

SQL ID: 62kbdd8s4wnnw Plan Hash: 1591679211

UPDATE CS_CU_SUBS_SPSERVICE_LIST SET EXPIRETIME=:B1
WHERE
 SUBSID=:B6 AND SPCODE=:B5 AND SERVICECODE=:B4 AND REGION = :B3 AND
  (EXPIRETIME=:B2 OR (EXPIRETIME IS NULL OR EXPIRETIME>=TO_DATE('20370101',
  'yyyymmdd')) AND STATUS=1 )


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1     71.61    1415.46     272538     420225          9           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2     71.61    1415.46     272538     420225          9           1

Misses in library cache during parse: 1
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 57     (recursive depth: 1)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  UPDATE  CS_CU_SUBS_SPSERVICE_LIST (cr=420227 pr=272543 pw=0 time=1415554526 us)
         1          1          1   PARTITION RANGE SINGLE PARTITION: KEY KEY (cr=420225 pr=272537 pw=0 time=1415454032 us cost=24 size=84 card=1)
         1          1          1    TABLE ACCESS BY LOCAL INDEX ROWID CS_CU_SUBS_SPSERVICE_LIST PARTITION: KEY KEY (cr=420225 pr=272537 pw=0 time=1415454015 us cost=24 size=84 card=1)
    425187     425187     425187     INDEX RANGE SCAN IDX_SUBS_SPSERVICELIST PARTITION: KEY KEY (cr=5122 pr=4865 pw=0 time=43992007 us cost=4 size=0 card=20)(object id 1025693)

。。。。。。

About xiaoyu

xiaoyu,享受数据库带给xiaoyu的乐趣! 13439818916@163.com 欢迎邮件联系讨论
This entry was posted in oracle, sql tuning and troubleshooting. Bookmark the permalink.