Oracle删除数据效率低下案例

最新推荐文章于 2023-07-15 11:56:02 发布

__风__

最新推荐文章于 2023-07-15 11:56:02 发布

阅读量3.2k

点赞数 1

分类专栏： Oracle数据库

本文链接：https://blog.csdn.net/liufeng1980423/article/details/81025474

版权

Oracle数据库专栏收录该内容

27 篇文章 0 订阅

订阅专栏

前段时间碰到一电信客户的删除效率低下案例，处理的过程记录一下：

现场的环境：

OS:AIX6

Oracle 11.2.0.4.0

问题详细描述如下：

客户有一个定时任务，任务中有一步是根据主键删除某些过期的数据，但是删除效率非常低，300w的表，删除一条记录需要好0.5s，

在此将现场环境重现一下：

表的字段：

SQL> desc subdltb
 名称                                                              是否为空? 类型
 ----------------------------------------------------------------- -------- --------------------------------------------
 OBJECTID                                                          NOT NULL NUMBER(38)
 DB2GSE_ST_                                                                 NUMBER(18,8)
 DB2GSE_SDE                                                                 NUMBER(18,8)
 SHAPE                                                                      ST_GEOMETRY

表的记录数：

SQL> select count(*) from subdltb;

  COUNT(*)
----------
   2999999

表上的索引信息：

SQL> select a.index_name,a.column_name,b.index_type,b.uniqueness from user_ind_columns a,user_indexes b where a.index_name=b.index_name and b.table_name='SUBDLTB';

INDEX_NAME                     COLUMN_NAME          INDEX_TYPE                  UNIQUENES
------------------------------ -------------------- --------------------------- ---------
R39_SDE_ROWID_UK               OBJECTID             NORMAL                      UNIQUE
A4_IX1                         SHAPE                DOMAIN                      NONUNIQUE

在OBJECTID上建立了一个唯一索引

根据主键删除一条记录

SQL> delete from subdltb where objectid=1;


已删除 1 行。


已用时间:  00: 00: 00.62

正常情况根据主键删除记录，应该在毫秒级别就可以完成，因此非常不正常。

解决过程：

1. 查看其执行计划，是否走主键索引

SQL> delete from subdltb where objectid=1;

已删除 1 行。

已用时间:  00: 00: 00.68

执行计划
----------------------------------------------------------
Plan hash value: 3736342072

-------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name             | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------
|   0 | DELETE STATEMENT             |                  |     1 |   387 |     3   (0)| 00:00:01 |
|   1 |  DELETE                      | SUBDLTB          |       |       |            |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| SUBDLTB          |     1 |   387 |     3   (0)| 00:00:01 |
|*  3 |    INDEX UNIQUE SCAN         | R39_SDE_ROWID_UK |     1 |       |     2   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------

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

   3 - access("OBJECTID"=1)


统计信息
----------------------------------------------------------
         16  recursive calls
         10  db block gets
      72637  consistent gets
          0  physical reads
          0  redo size
        867  bytes sent via SQL*Net to client
        845  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
          1  rows processed

从执行计划本身看，确实走了索引的唯一扫描，说明oracle选择的是正确的执行计划。但是统计信息部分不知道为什么由7w多个内存读，正常走唯一索引，连索引+堆块的扫描绝对不会这么多，应该后面执行的更深度的SQL导致的问题，这必须打开跟踪看看后面执行了哪些深度的SQL。

跟踪结果如下：

Trace file D:\ORACLE\diag\rdbms\test\test\trace\test_ora_41948.trc
Oracle Database 12c Enterprise Edition Release 12.1.0.2.0 - 64bit Production
With the Partitioning, OLAP, Advanced Analytics and Real Application Testing options
Windows NT Version V6.2  
CPU                 : 8 - type 8664, 4 Physical Cores
Process Affinity    : 0x0x0000000000000000
Memory (Avail/Total): Ph:16984M/32393M, Ph+PgF:10671M/37257M 
Instance name: test
Redo thread mounted by this instance: 1
Oracle process number: 36
Windows thread id: 41948, image: ORACLE.EXE (SHAD)


*** 2018-07-13 09:42:45.954
*** SESSION ID:(249.15503) 2018-07-13 09:42:45.954
*** CLIENT ID:() 2018-07-13 09:42:45.954
*** SERVICE NAME:(pdbsde) 2018-07-13 09:42:45.954
*** MODULE NAME:(SQL*Plus) 2018-07-13 09:42:45.954
*** CLIENT DRIVER:(SQL*PLUS) 2018-07-13 09:42:45.954
*** ACTION NAME:() 2018-07-13 09:42:45.954
*** CONTAINER ID:(3) 2018-07-13 09:42:45.954
 
CLOSE #746902760:c=0,e=8,dep=0,type=0,tim=674585862962
=====================
PARSING IN CURSOR #746860784 len=76 dep=2 uid=0 oct=3 lid=0 tim=674585866528 hv=1052578227 ad='7ff8f85da360' sqlid='04kug40zbu4dm'
select policy#, action# from aud_object_opt$ where object# = :1 and type = 2
END OF STMT
PARSE #746860784:c=0,e=25,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585866527
BINDS #746860784:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2f77ffe8  bln=22  avl=03  flg=05
  value=679
EXEC #746860784:c=0,e=92,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585866720
FETCH #746860784:c=0,e=60,p=0,cr=9,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585866798
STAT #746860784 id=1 cnt=0 pid=0 pos=1 obj=450 op='TABLE ACCESS FULL AUD_OBJECT_OPT$ (cr=9 pr=0 pw=0 time=61 us cost=4 size=114 card=1)'
CLOSE #746860784:c=0,e=4,dep=2,type=1,tim=674585866852
=====================
PARSING IN CURSOR #796392400 len=76 dep=2 uid=0 oct=3 lid=0 tim=674585866891 hv=1052578227 ad='7ff8f85da360' sqlid='04kug40zbu4dm'
select policy#, action# from aud_object_opt$ where object# = :1 and type = 2
END OF STMT
PARSE #796392400:c=0,e=20,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585866891
BINDS #796392400:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2f77f788  bln=22  avl=03  flg=05
  value=677
EXEC #796392400:c=0,e=168,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585867111
FETCH #796392400:c=0,e=34,p=0,cr=9,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585867162
STAT #796392400 id=1 cnt=0 pid=0 pos=1 obj=448 op='TABLE ACCESS FULL AUD_OBJECT_OPT$ (cr=9 pr=0 pw=0 time=34 us cost=4 size=114 card=1)'
CLOSE #796392400:c=0,e=3,dep=2,type=1,tim=674585867203
=====================
PARSING IN CURSOR #796391152 len=865 dep=2 uid=0 oct=3 lid=0 tim=674585868131 hv=715221786 ad='7ff8fddeda80' sqlid='616m6uhpa2usu'
select i.obj#,i.ts#,i.file#,i.block#,i.intcols,i.type#,i.flags,i.property,i.pctfree$,i.initrans,i.maxtrans,i.blevel,i.leafcnt,i.distkey,i.lblkkey,i.dblkkey,i.clufac,i.cols,i.analyzetime,i.samplesize,i.dataobj#,nvl(i.degree,1),nvl(i.instances,1),i.rowcnt,mod(i.pctthres$,256),i.indmethod#,i.trunccnt,nvl(c.unicols,0),nvl(c.deferrable#+c.valid#,0),nvl(i.spare1,i.intcols),i.spare4,i.spare2,i.spare6,decode(i.pctthres$,null,null,mod(trunc(i.pctthres$/256),256)),nvl(i.evaledition#,1),nvl(i.unusablebefore#,0),nvl(i.unusablebeginning#,0), ist.cachedblk,ist.cachehit,ist.logicalread from ind$ i, ind_stats$ ist, (select enabled, min(cols) unicols,min(to_number(bitand(defer,1))) deferrable#,min(to_number(bitand(defer,4))) valid# from cdef$ where obj#=:1 and enabled > 1 group by enabled) c where i.obj#=c.enabled(+) and i.obj# = ist.obj#(+) and i.bo#=:1 order by i.obj#
END OF STMT
PARSE #796391152:c=0,e=903,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,plh=0,tim=674585868131
BINDS #796391152:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2f77ba38  bln=22  avl=03  flg=05
  value=677
 Bind#1
  No oacdef for this bind.
EXEC #796391152:c=0,e=2632,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=4,plh=2556297882,tim=674585870839
FETCH #796391152:c=15625,e=344,p=0,cr=7,cu=0,mis=0,r=1,dep=2,og=4,plh=2556297882,tim=674585871199
=====================
PARSING IN CURSOR #777473776 len=74 dep=2 uid=0 oct=3 lid=0 tim=674585871303 hv=3309402135 ad='7ff8fc95e8e0' sqlid='5n1fs4m2n2y0r'
select pos#,intcol#,col#,spare1,bo#,spare2,spare3 from icol$ where obj#=:1
END OF STMT
PARSE #777473776:c=0,e=55,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=452367486,tim=674585871302
BINDS #777473776:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2f774538  bln=22  avl=03  flg=05
  value=678
EXEC #777473776:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=452367486,tim=674585871460
FETCH #777473776:c=0,e=13,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=4,plh=452367486,tim=674585871485
FETCH #777473776:c=0,e=2,p=0,cr=1,cu=0,mis=0,r=0,dep=2,og=4,plh=452367486,tim=674585871504
STAT #777473776 id=1 cnt=1 pid=0 pos=1 obj=20 op='TABLE ACCESS BY INDEX ROWID BATCHED ICOL$ (cr=4 pr=0 pw=0 time=12 us cost=2 size=54 card=2)'
STAT #777473776 id=2 cnt=1 pid=1 pos=1 obj=42 op='INDEX RANGE SCAN I_ICOL1 (cr=3 pr=0 pw=0 time=12 us cost=1 size=0 card=2)'
CLOSE #777473776:c=0,e=2,dep=2,type=3,tim=674585871555
FETCH #796391152:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=2556297882,tim=674585871570
STAT #796391152 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=7 pr=0 pw=0 time=348 us cost=6 size=374 card=2)'
STAT #796391152 id=2 cnt=1 pid=1 pos=1 obj=0 op='HASH JOIN OUTER (cr=7 pr=0 pw=0 time=332 us cost=5 size=374 card=2)'
STAT #796391152 id=3 cnt=1 pid=2 pos=1 obj=0 op='NESTED LOOPS OUTER (cr=4 pr=0 pw=0 time=31 us cost=2 size=288 card=2)'
STAT #796391152 id=4 cnt=1 pid=3 pos=1 obj=19 op='TABLE ACCESS CLUSTER IND$ (cr=3 pr=0 pw=0 time=25 us cost=2 size=184 card=2)'
STAT #796391152 id=5 cnt=1 pid=4 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=13 us cost=1 size=0 card=1)'
STAT #796391152 id=6 cnt=0 pid=3 pos=2 obj=75 op='TABLE ACCESS BY INDEX ROWID IND_STATS$ (cr=1 pr=0 pw=0 time=3 us cost=0 size=52 card=1)'
STAT #796391152 id=7 cnt=0 pid=6 pos=1 obj=76 op='INDEX UNIQUE SCAN I_IND_STATS$_OBJ# (cr=1 pr=0 pw=0 time=3 us cost=0 size=0 card=1)'
STAT #796391152 id=8 cnt=0 pid=2 pos=2 obj=0 op='VIEW  (cr=3 pr=0 pw=0 time=98 us cost=3 size=43 card=1)'
STAT #796391152 id=9 cnt=0 pid=8 pos=1 obj=0 op='SORT GROUP BY (cr=3 pr=0 pw=0 time=98 us cost=3 size=15 card=1)'
STAT #796391152 id=10 cnt=0 pid=9 pos=1 obj=31 op='TABLE ACCESS BY INDEX ROWID BATCHED CDEF$ (cr=3 pr=0 pw=0 time=83 us cost=2 size=15 card=1)'
STAT #796391152 id=11 cnt=2 pid=10 pos=1 obj=54 op='INDEX RANGE SCAN I_CDEF2 (cr=2 pr=0 pw=0 time=15 us cost=1 size=0 card=5)'
CLOSE #796391152:c=0,e=1,dep=2,type=3,tim=674585871708
=====================
PARSING IN CURSOR #796373976 len=418 dep=2 uid=0 oct=3 lid=0 tim=674585871747 hv=3759961951 ad='7ff8fc963dd0' sqlid='14d7z6mh1sxuz'
select name,intcol#,segcol#,type#,length,nvl(precision#,0),decode(type#,2,nvl(scale,-127/*MAXSB1MINAL*/),178,scale,179,scale,180,scale,181,scale,182,scale,183,scale,231,scale,0),null$,fixedstorage,nvl(deflength,0),default$,rowid,col#,property, nvl(charsetid,0),nvl(charsetform,0),spare1,spare2,nvl(spare3,0), nvl(evaledition#,1),nvl(unusablebefore#,0),nvl(unusablebeginning#,0) from col$ where obj#=:1 order by intcol#
END OF STMT
PARSE #796373976:c=0,e=23,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=3765558045,tim=674585871747
BINDS #796373976:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2e578588  bln=22  avl=03  flg=05
  value=677
EXEC #796373976:c=0,e=135,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=3765558045,tim=674585871935
FETCH #796373976:c=0,e=34,p=0,cr=3,cu=0,mis=0,r=1,dep=2,og=4,plh=3765558045,tim=674585871981
FETCH #796373976:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=2,og=4,plh=3765558045,tim=674585872009
FETCH #796373976:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=1,dep=2,og=4,plh=3765558045,tim=674585872036
FETCH #796373976:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=3765558045,tim=674585872098
STAT #796373976 id=1 cnt=3 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=34 us cost=3 size=793 card=13)'
STAT #796373976 id=2 cnt=3 pid=1 pos=1 obj=21 op='TABLE ACCESS CLUSTER COL$ (cr=3 pr=0 pw=0 time=10 us cost=2 size=793 card=13)'
STAT #796373976 id=3 cnt=1 pid=2 pos=1 obj=3 op='INDEX UNIQUE SCAN I_OBJ# (cr=2 pr=0 pw=0 time=6 us cost=1 size=0 card=1)'
CLOSE #796373976:c=0,e=1,dep=2,type=3,tim=674585872153
=====================
PARSING IN CURSOR #746862560 len=47 dep=1 uid=0 oct=3 lid=0 tim=674585873626 hv=1023521005 ad='7ff8fc981df0' sqlid='cb21bacyh3c7d'
select metadata from kopm$  where name='DB_FDO'
END OF STMT
PARSE #746862560:c=15625,e=7385,p=0,cr=32,cu=0,mis=1,r=0,dep=1,og=4,plh=3452538079,tim=674585873625
EXEC #746862560:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3452538079,tim=674585873713
FETCH #746862560:c=0,e=11,p=0,cr=2,cu=0,mis=0,r=1,dep=1,og=4,plh=3452538079,tim=674585873742
STAT #746862560 id=1 cnt=1 pid=0 pos=1 obj=677 op='TABLE ACCESS BY INDEX ROWID KOPM$ (cr=2 pr=0 pw=0 time=13 us cost=1 size=108 card=1)'
STAT #746862560 id=2 cnt=1 pid=1 pos=1 obj=678 op='INDEX UNIQUE SCAN I_KOPM1 (cr=1 pr=0 pw=0 time=7 us cost=0 size=0 card=1)'
CLOSE #746862560:c=0,e=2,dep=1,type=0,tim=674585873793
=====================
PARSING IN CURSOR #777534464 len=128 dep=1 uid=0 oct=3 lid=0 tim=674585876090 hv=2896898424 ad='7ff8f6dce968' sqlid='a6r5q9yqaqabs'
select obj#, name, stab#, sobj#, sobjd#, ttab#, tobj#, tobjd#, mflags from rmtab$ where (stab# = :1 or ttab# = :1) order by obj#
END OF STMT
PARSE #777534464:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=140787661,tim=674585876090
BINDS #777534464:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2f791e60  bln=22  avl=03  flg=05
  value=92800
 Bind#1
  No oacdef for this bind.
EXEC #777534464:c=0,e=214,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=140787661,tim=674585876471
FETCH #777534464:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=140787661,tim=674585876525
STAT #777534464 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=0 pr=0 pw=0 time=24 us cost=3 size=121 card=1)'
STAT #777534464 id=2 cnt=0 pid=1 pos=1 obj=1049 op='TABLE ACCESS FULL RMTAB$ (cr=0 pr=0 pw=0 time=9 us cost=2 size=121 card=1)'
CLOSE #777534464:c=0,e=8,dep=1,type=1,tim=674585876622
=====================
PARSING IN CURSOR #777520568 len=41 dep=1 uid=0 oct=3 lid=0 tim=674585877401 hv=4138818835 ad='7ff8f4713f50' sqlid='95nx0kvvb2r8m'
select indmethod# from ind$ where obj#=:1
END OF STMT
PARSE #777520568:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3312860272,tim=674585877400
BINDS #777520568:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2f791e60  bln=22  avl=04  flg=05
  value=92809
EXEC #777520568:c=0,e=182,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=3312860272,tim=674585877667
FETCH #777520568:c=0,e=31,p=0,cr=3,cu=0,mis=0,r=1,dep=1,og=4,plh=3312860272,tim=674585877713
STAT #777520568 id=1 cnt=1 pid=0 pos=1 obj=19 op='TABLE ACCESS BY INDEX ROWID IND$ (cr=3 pr=0 pw=0 time=35 us cost=2 size=8 card=1)'
STAT #777520568 id=2 cnt=1 pid=1 pos=1 obj=41 op='INDEX UNIQUE SCAN I_IND1 (cr=2 pr=0 pw=0 time=22 us cost=1 size=0 card=1)'
CLOSE #777520568:c=0,e=5,dep=1,type=1,tim=674585877796
CLOSE #746672408:c=0,e=11,dep=1,type=1,tim=674585882120
=====================
PARSING IN CURSOR #796461512 len=823 dep=1 uid=0 oct=3 lid=0 tim=674585882578 hv=3156785590 ad='7ff8f9cf6c60' sqlid='frjd8zfy2jfdq'
SELECT executions, end_of_fetch_count,              elapsed_time/px_servers elapsed_time,        cpu_time/px_servers     cpu_time,            buffer_gets/executions  buffer_gets   FROM (SELECT sum(executions)   as executions,                            sum(case when px_servers_executions > 0                              then px_servers_executions                                  else executions end) as px_servers,                sum(end_of_fetch_count) as end_of_fetch_count,              sum(elapsed_time) as elapsed_time,                 sum(cpu_time)     as cpu_time,                     sum(buffer_gets)  as buffer_gets            FROM   gv$sql                                      WHERE executions > 0                                 AND sql_id = :1                                    AND parsing_schema_name = :2)
END OF STMT
PARSE #796461512:c=0,e=335,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=4,plh=0,tim=674585882577
PARSE #796392400:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585882735
BINDS #796392400:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2e583bd0  bln=22  avl=06  flg=05
  value=4294951306
EXEC #796392400:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585882839
FETCH #796392400:c=0,e=50,p=0,cr=9,cu=0,mis=0,r=0,dep=2,og=4,plh=4006480256,tim=674585882905
CLOSE #796392400:c=0,e=5,dep=2,type=3,tim=674585882937
PARSE #796392400:c=0,e=13,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=4,plh=4006480256,tim=674585883526
BINDS #796392400:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=08 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2e583bd0  bln=22  avl=06  flg=05
  value=4294952683
EXEC #796392400:c=0,e=62,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=4,plh=4006480256,tim=674585883633
FETCH #796392400:c=0,e=41,p=0,cr=9,cu=0,mis=0,r=0,dep=3,og=4,plh=4006480256,tim=674585883689
CLOSE #796392400:c=0,e=5,dep=3,type=3,tim=674585883718
=====================
PARSING IN CURSOR #746865720 len=1847 dep=2 uid=0 oct=3 lid=0 tim=674585886316 hv=2967838950 ad='7ff8f9cf2ca0' sqlid='fa5z3v2sfb876'
select inst_id,kglnaobj,kglfnobj,kglobt03, kglobhs0+kglobhs1+kglobhs2+kglobhs3+kglobhs4+kglobhs5+kglobhs6+kglobt16, kglobt08+kglobt11, kglobt10, kglobt01, decode(kglobhs6,0,0,1), decode(kglhdlmd,0,0,1), kglhdlkc, kglobt04, kglobt05, kglobt48, kglobt35, kglobpc6, kglhdldc, substr(to_char(kglnatim,'YYYY-MM-DD/HH24:MI:SS'),1,19), kglhdivc, kglobt12, kglobt13, kglobwdw, kglobt14, kglobwap, kglobwcc, kglobwcl, kglobwui, kglobt42, kglobt43, kglobt15, kglobt02, decode(kglobt32,        0, 'NONE',        1, 'ALL_ROWS',        2, 'FIRST_ROWS',        3, 'RULE',        4, 'CHOOSE',           'UNKNOWN'), kglobtn0, kglobcce, kglobcceh, kglobt17, kglobt18, kglobts4, kglhdkmk, kglhdpar, kglobtp0, kglnahsh, kglobt46, kglobt30, kglobt61, kglobt09, kglobts5, kglobt48, kglobts0, kglobt19, kglobts1, kglobt20, kglobt21, kglobts2, kglobt06, kglobt07, decode(kglobt28, 0, to_number(NULL), kglobt28), kglhdadr, kglobt29, decode(bitand(kglobt00,64),64, 'Y', 'N'), decode(kglobsta,        1, 'VALID',        2, 'VALID_AUTH_ERROR',        3, 'VALID_COMPILE_ERROR',        4, 'VALID_UNAUTH',        5, 'INVALID_UNAUTH',        6, 'INVALID'), kglobt31, substr(to_char(kglobtt0,'YYYY-MM-DD/HH24:MI:SS'),1,19), decode(kglobt33, 1, 'Y', 'N'),  decode(bitand(kglobacs, 1), 1, 'Y', 'N'),  decode(bitand(kglobacs, 2), 2, 'Y', 'N'),  decode(bitand(kglobacs, 4), 4, 'Y', 'N'),  kglhdclt, kglobts3, kglobts7, kglobts6, kglobt44, kglobt45,  kglobt47, kglobt49, kglobcla,  kglobcbca, kglobt22, kglobt52, kglobt53, kglobt54, kglobt55,  kglobt56, kglobt57, kglobt58, kglobt23, kglobt24, kglobt59,  kglobt53 - ((kglobt55+kglobt57) - kglobt52),  con_id,  decode(bitand(kglobaqp,1), 1, decode(bitand(kglobaqp,2), 2, 'R', 'Y'), 'N'),  decode(bitand(kglobaqp,4), 4, decode(bitand(kglobaqp,8), 8, 'Y', 'N'), ''),  kglimscans, kglimbytesuncomp, kglimbytesinmem  from x$kglcursor_child
END OF STMT
PARSE #746865720:c=0,e=3348,p=0,cr=9,cu=0,mis=1,r=0,dep=2,og=4,plh=903671040,tim=674585886315
CLOSE #746865720:c=0,e=6,dep=2,type=0,tim=674585886463
BINDS #796461512:
 Bind#0
  oacdty=01 mxl=32(13) mxlc=00 mal=00 scl=00 pre=00
  oacflg=21 fl2=0000 frm=01 csi=852 siz=64 off=0
  kxsbbbfp=2e583ba8  bln=32  avl=13  flg=05
  value="5guafpj5rsx8r"
 Bind#1
  oacdty=01 mxl=32(03) mxlc=00 mal=00 scl=00 pre=00
  oacflg=21 fl2=0000 frm=01 csi=852 siz=0 off=32
  kxsbbbfp=2e583bc8  bln=32  avl=03  flg=01
  value="SDE"
EXEC #796461512:c=15625,e=5931,p=0,cr=18,cu=0,mis=1,r=0,dep=1,og=4,plh=987782979,tim=674585888592
FETCH #796461512:c=0,e=46,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,plh=987782979,tim=674585888702
STAT #796461512 id=1 cnt=1 pid=0 pos=1 obj=0 op='VIEW  (cr=0 pr=0 pw=0 time=48 us)'
STAT #796461512 id=2 cnt=1 pid=1 pos=1 obj=0 op='SORT AGGREGATE (cr=0 pr=0 pw=0 time=46 us)'
STAT #796461512 id=3 cnt=1 pid=2 pos=1 obj=0 op='FIXED TABLE FIXED INDEX X$KGLCURSOR_CHILD (ind:2) (cr=0 pr=0 pw=0 time=35 us)'
=====================
PARSING IN CURSOR #746902760 len=36 dep=0 uid=103 oct=7 lid=103 tim=674585889789 hv=1266447639 ad='7ff8f48453f8' sqlid='5guafpj5rsx8r'
delete from subdltb where objectid=1
END OF STMT
PARSE #746902760:c=31250,e=24077,p=0,cr=467,cu=0,mis=1,r=0,dep=0,og=1,plh=3736342072,tim=674585889788
=====================
PARSING IN CURSOR #797253696 len=25 dep=1 uid=103 oct=3 lid=103 tim=674585890592 hv=4010258057 ad='7ff8f8a64750' sqlid='1v717nvrhgbn9'
SELECT USER FROM SYS.DUAL
END OF STMT
PARSE #797253696:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=674585890592
EXEC #797253696:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=674585890666
FETCH #797253696:c=0,e=5,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=674585890696
STAT #797253696 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
CLOSE #797253696:c=0,e=2,dep=1,type=3,tim=674585890744
EXEC #797253696:c=0,e=8,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=1388734953,tim=674585890802
FETCH #797253696:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,plh=1388734953,tim=674585890825
CLOSE #797253696:c=0,e=1,dep=1,type=3,tim=674585890843
=====================
PARSING IN CURSOR #797131000 len=315 dep=1 uid=103 oct=3 lid=103 tim=674585891504 hv=3345710817 ad='7ff8ee48a4b0' sqlid='6f7dtbg3qqzr1'
SELECT S.INDEX_ID,S.GRID.GRID1,S.GRID.GRID2,S.GRID.GRID3, SR.SRID,SR.X_OFFSET,SR.Y_OFFSET,SR.XYUNITS,ST.PROPERTIES FROM SDE.ST_GEOMETRY_INDEX S,SDE.ST_GEOMETRY_COLUMNS ST,SDE.ST_SPATIAL_REFERENCES SR WHERE S.OWNER = :B3 AND S.TABLE_NAME = :B2 AND S.COLUMN_NAME = :B1 AND S.INDEX_ID = ST.GEOM_ID AND SR.SRID = S.SRID
END OF STMT
PARSE #797131000:c=0,e=608,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,plh=0,tim=674585891503
WAIT #777476272: nam='Disk file operations I/O' ela= 1182 FileOperation=2 fileno=7 filetype=2 obj#=657 tim=674585893184
WAIT #777476272: nam='db file sequential read' ela= 23944 file#=7 block#=25766 blocks=1 obj#=657 tim=674585917174
BINDS #797131000:
 Bind#0
  oacdty=01 mxl=2000(256) mxlc=128 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=02 csi=2000 siz=4000 off=0
  kxsbbbfp=2f78f060  bln=2000  avl=06  flg=05
  value=0 53 0 44 0 45 
 Bind#1
  oacdty=01 mxl=2000(256) mxlc=128 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=02 csi=2000 siz=0 off=2000
  kxsbbbfp=2f78f830  bln=2000  avl=14  flg=01
  value=0 53 0 55 0 42 0 44 0 4c 0 54 0 42 
 Bind#2
  oacdty=01 mxl=128(64) mxlc=32 mal=00 scl=00 pre=00
  oacflg=03 fl2=1206001 frm=02 csi=2000 siz=128 off=0
  kxsbbbfp=2f833c48  bln=128  avl=10  flg=05
  value=0 53 0 48 0 41 0 50 0 45 
EXEC #797131000:c=15625,e=28168,p=1,cr=24,cu=0,mis=1,r=0,dep=1,og=1,plh=3247942301,tim=674585919729
FETCH #797131000:c=0,e=45,p=0,cr=7,cu=0,mis=0,r=1,dep=1,og=1,plh=3247942301,tim=674585919869
STAT #797131000 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS  (cr=7 pr=0 pw=0 time=47 us cost=3 size=82 card=1)'
STAT #797131000 id=2 cnt=1 pid=1 pos=1 obj=0 op='NESTED LOOPS  (cr=5 pr=0 pw=0 time=38 us cost=2 size=77 card=1)'
STAT #797131000 id=3 cnt=1 pid=2 pos=1 obj=92076 op='TABLE ACCESS BY INDEX ROWID ST_GEOMETRY_INDEX (cr=2 pr=0 pw=0 time=29 us cost=1 size=55 card=1)'
STAT #797131000 id=4 cnt=1 pid=3 pos=1 obj=92080 op='INDEX UNIQUE SCAN ST_GEOM_IDX_UK2 (cr=1 pr=0 pw=0 time=20 us cost=0 size=0 card=1)'
STAT #797131000 id=5 cnt=1 pid=2 pos=2 obj=92064 op='TABLE ACCESS BY INDEX ROWID ST_SPATIAL_REFERENCES (cr=3 pr=0 pw=0 time=9 us cost=1 size=22 card=1)'
STAT #797131000 id=6 cnt=1 pid=5 pos=1 obj=92065 op='INDEX UNIQUE SCAN ST_SPREFS_PK (cr=2 pr=0 pw=0 time=7 us cost=0 size=0 card=1)'
STAT #797131000 id=7 cnt=1 pid=1 pos=2 obj=92068 op='TABLE ACCESS BY INDEX ROWID ST_GEOMETRY_COLUMNS (cr=2 pr=0 pw=0 time=6 us cost=1 size=5 card=1)'
STAT #797131000 id=8 cnt=1 pid=7 pos=1 obj=92070 op='INDEX UNIQUE SCAN GEOM_ID_UK (cr=1 pr=0 pw=0 time=4 us cost=0 size=0 card=1)'
CLOSE #797131000:c=0,e=7,dep=1,type=3,tim=674585920086
=====================
PARSING IN CURSOR #796396256 len=47 dep=1 uid=103 oct=7 lid=103 tim=674585920418 hv=4226023344 ad='7ff81ec7bbd0' sqlid='akr29bmxy7zxh'
DELETE FROM "SDE".S4_IDX$ WHERE sp_id = :sp_row
END OF STMT
PARSE #796396256:c=0,e=59,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,plh=0,tim=674585920417
PARSE #777534464:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=140787661,tim=674585920843
BINDS #777534464:
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=2e5d5378  bln=22  avl=04  flg=05
  value=92810
 Bind#1
  No oacdef for this bind.
EXEC #777534464:c=0,e=188,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=140787661,tim=674585921113
FETCH #777534464:c=0,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=4,plh=140787661,tim=674585921147
CLOSE #777534464:c=0,e=4,dep=2,type=3,tim=674585921177
BINDS #796396256:
 Bind#0
  oacdty=01 mxl=32(18) mxlc=00 mal=00 scl=00 pre=00
  oacflg=13 fl2=0001 frm=01 csi=852 siz=32 off=0
  kxsbbbfp=2f7e00a0  bln=32  avl=18  flg=09
  value="AAAWqAAAKAAACLFAAA"

*** 2018-07-13 09:42:46.739
EXEC #796396256:c=718750,e=729472,p=0,cr=72629,cu=4,mis=1,r=4,dep=1,og=1,plh=3992397619,tim=674586649992
CLOSE #796396256:c=0,e=6,dep=1,type=0,tim=674586650234
EXEC #746902760:c=734375,e=777847,p=1,cr=72664,cu=10,mis=0,r=1,dep=0,og=1,plh=3736342072,tim=674586667714
STAT #746902760 id=1 cnt=0 pid=0 pos=1 obj=0 op='DELETE  SUBDLTB (cr=72664 pr=1 pw=0 time=777763 us)'
STAT #746902760 id=2 cnt=1 pid=1 pos=1 obj=92800 op='TABLE ACCESS BY INDEX ROWID SUBDLTB (cr=4 pr=0 pw=0 time=35 us cost=3 size=387 card=1)'
STAT #746902760 id=3 cnt=1 pid=2 pos=1 obj=92801 op='INDEX UNIQUE SCAN R39_SDE_ROWID_UK (cr=3 pr=0 pw=0 time=17 us cost=2 size=0 card=1)'
WAIT #746902760: nam='SQL*Net message to client' ela= 3 driver id=1413697536 #bytes=1 p3=0 obj#=92803 tim=674586667980

*** 2018-07-13 09:43:20.464
WAIT #746902760: nam='SQL*Net message from client' ela= 33706980 driver id=1413697536 #bytes=1 p3=0 obj#=92803 tim=674620374982

格式化后：

C:\Users\liufeng>tkprof D:\oracle\diag\rdbms\test\test\trace\test_ora_41948.trc D:\oracle\diag\rdbms\test\test\trace\test_ora_41948.txt sys=no explain=sde/sde@localhost/pdbsde

TKPROF: Release 12.1.0.2.0 - Development on 星期五 7月 13 09:51:06 2018

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

TKPROF: Release 12.1.0.2.0 - Development on 星期五 7月 13 09:51:06 2018

Copyright (c) 1982, 2014, Oracle and/or its affiliates.  All rights reserved.

Trace file: D:\oracle\diag\rdbms\test\test\trace\test_ora_41948.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing 
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************

SQL ID: 5guafpj5rsx8r Plan Hash: 3736342072

delete from subdltb 
where
 objectid=1


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0        412          0           0
Execute      1      0.00       0.01          0          4          6           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.02          0        416          6           1

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103  (SDE)
Number of plan statistics captured: 1

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         0          0          0  DELETE  SUBDLTB (cr=72664 pr=1 pw=0 time=777763 us)
         1          1          1   TABLE ACCESS BY INDEX ROWID SUBDLTB (cr=4 pr=0 pw=0 time=35 us cost=3 size=387 card=1)
         1          1          1    INDEX UNIQUE SCAN R39_SDE_ROWID_UK (cr=3 pr=0 pw=0 time=17 us cost=2 size=0 card=1)(object id 92801)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  DELETE STATEMENT   MODE: ALL_ROWS
      0   DELETE OF 'SUBDLTB'
      1    TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 'SUBDLTB' 
               (TABLE)
      1     INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'R39_SDE_ROWID_UK' 
                (INDEX (UNIQUE))


Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1       33.70         33.70
********************************************************************************

SQL ID: 1v717nvrhgbn9 Plan Hash: 1388734953

SELECT USER 
FROM
 SYS.DUAL


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      2      0.00       0.00          0          0          0           0
Fetch        2      0.00       0.00          0          0          0           2
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        5      0.00       0.00          0          0          0           2

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   FAST DUAL

********************************************************************************

SQL ID: 6f7dtbg3qqzr1 Plan Hash: 3247942301

SELECT S.INDEX_ID,S.GRID.GRID1,S.GRID.GRID2,S.GRID.GRID3, SR.SRID,SR.X_OFFSET,
  SR.Y_OFFSET,SR.XYUNITS,ST.PROPERTIES 
FROM
 SDE.ST_GEOMETRY_INDEX S,SDE.ST_GEOMETRY_COLUMNS ST,SDE.ST_SPATIAL_REFERENCES 
  SR WHERE S.OWNER = :B3 AND S.TABLE_NAME = :B2 AND S.COLUMN_NAME = :B1 AND 
  S.INDEX_ID = ST.GEOM_ID AND SR.SRID = S.SRID


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.01       0.02          1         24          0           0
Fetch        1      0.00       0.00          0          7          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.02          1         31          0           1

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

Rows (1st) Rows (avg) Rows (max)  Row Source Operation
---------- ---------- ----------  ---------------------------------------------------
         1          1          1  NESTED LOOPS  (cr=7 pr=0 pw=0 time=47 us cost=3 size=82 card=1)
         1          1          1   NESTED LOOPS  (cr=5 pr=0 pw=0 time=38 us cost=2 size=77 card=1)
         1          1          1    TABLE ACCESS BY INDEX ROWID ST_GEOMETRY_INDEX (cr=2 pr=0 pw=0 time=29 us cost=1 size=55 card=1)
         1          1          1     INDEX UNIQUE SCAN ST_GEOM_IDX_UK2 (cr=1 pr=0 pw=0 time=20 us cost=0 size=0 card=1)(object id 92080)
         1          1          1    TABLE ACCESS BY INDEX ROWID ST_SPATIAL_REFERENCES (cr=3 pr=0 pw=0 time=9 us cost=1 size=22 card=1)
         1          1          1     INDEX UNIQUE SCAN ST_SPREFS_PK (cr=2 pr=0 pw=0 time=7 us cost=0 size=0 card=1)(object id 92065)
         1          1          1   TABLE ACCESS BY INDEX ROWID ST_GEOMETRY_COLUMNS (cr=2 pr=0 pw=0 time=6 us cost=1 size=5 card=1)
         1          1          1    INDEX UNIQUE SCAN GEOM_ID_UK (cr=1 pr=0 pw=0 time=4 us cost=0 size=0 card=1)(object id 92070)


Rows     Execution Plan
-------  ---------------------------------------------------
      0  SELECT STATEMENT   MODE: ALL_ROWS
      1   NESTED LOOPS
      1    NESTED LOOPS
      1     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 
                'ST_GEOMETRY_INDEX' (TABLE)
      1      INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'ST_GEOM_IDX_UK2' 
                 (INDEX (UNIQUE))
      1     TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 
                'ST_SPATIAL_REFERENCES' (TABLE)
      1      INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'ST_SPREFS_PK' 
                 (INDEX (UNIQUE))
      1    TABLE ACCESS   MODE: ANALYZED (BY INDEX ROWID) OF 
               'ST_GEOMETRY_COLUMNS' (TABLE)
      1     INDEX   MODE: ANALYZED (UNIQUE SCAN) OF 'GEOM_ID_UK' (INDEX 
                (UNIQUE))

********************************************************************************

SQL ID: akr29bmxy7zxh Plan Hash: 3992397619

DELETE FROM "SDE".S4_IDX$ 
WHERE
 sp_id = :sp_row


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.71       0.72          0      72629          4           4
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.71       0.72          0      72629          4           4

Misses in library cache during parse: 0
Misses in library cache during execute: 1
Optimizer mode: ALL_ROWS
Parsing user id: 103  (SDE)   (recursive depth: 1)

Rows     Execution Plan
-------  ---------------------------------------------------
      0  DELETE STATEMENT   MODE: ALL_ROWS
      0   DELETE OF 'S4_IDX$'
      0    INDEX   MODE: ANALYZED (FAST FULL SCAN) OF 'S4$_IX1' (INDEX 
               (UNIQUE))




********************************************************************************

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0        412          0           0
Execute      1      0.00       0.01          0          4          6           1
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.00       0.02          0        416          6           1

Misses in library cache during parse: 1

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  Disk file operations I/O                        1        0.00          0.00
  db file sequential read                         1        0.02          0.02
  SQL*Net message to client                       1        0.00          0.00
  SQL*Net message from client                     1       33.70         33.70


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       16      0.01       0.01          0         41          0           0
Execute     16      0.73       0.76          1      72671          4           4
Fetch       20      0.01       0.00          0         62          0          11
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       52      0.76       0.78          1      72774          4          15

Misses in library cache during parse: 5
Misses in library cache during execute: 4

    4  user  SQL statements in session.
   10  internal SQL statements in session.
   14  SQL statements in session.
    4  statements EXPLAINed in this session.
********************************************************************************
Trace file: D:\oracle\diag\rdbms\test\test\trace\test_ora_41948.trc
Trace file compatibility: 11.1.0.7
Sort options: default

       1  session in tracefile.
       4  user  SQL statements in trace file.
      10  internal SQL statements in trace file.
      14  SQL statements in trace file.
      13  unique SQL statements in trace file.
       4  SQL statements EXPLAINed using schema:
           SDE.prof$plan_table
             Default table was used.
             Table was created.
             Table was dropped.
     296  lines in trace file.
       0  elapsed seconds in trace file.

从跟踪文件看非常清楚了，果然是深度的SQL删除有问题了。

DELETE FROM "SDE".S4_IDX$ 
WHERE
 sp_id = :sp_row

这个SQL出问题了，手动进行删除，看看其执行计划。

SQL> select count(*) from s4_idx$;

  COUNT(*)
----------
   5078239

已用时间:  00: 00: 04.84

SQL> delete from s4_idx$ where sp_id='AAAWqAAAKAAAOjXAAB';

已删除 4 行。

已用时间:  00: 00: 00.61

执行计划
----------------------------------------------------------
Plan hash value: 3992397619

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

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

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

|   0 | DELETE STATEMENT      |         |     2 |   104 | 20389   (1)| 00:00:01
|

|   1 |  DELETE               | S4_IDX$ |       |       |            |
|

|*  2 |   INDEX FAST FULL SCAN| S4$_IX1 |     2 |   104 | 20389   (1)| 00:00:01
|

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


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

   2 - filter("SP_ID"='AAAWqAAAKAAAOjXAAB')


统计信息
----------------------------------------------------------
         12  recursive calls
          4  db block gets
      72638  consistent gets
          0  physical reads
        204  redo size
        910  bytes sent via SQL*Net to client
        861  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          2  sorts (memory)
          0  sorts (disk)
          4  rows processed

执行计划走的是S4$_IX1索引，但是走的是INDEX FAST FULL SCAN，正常不应该走这个索引，这个索引可能不是只在SP_ID建的索引，应该是多个字段上建的索引，查看这个这个索引如何定义的：

SQL> select dbms_metadata.get_ddl('INDEX','S4$_IX1','SDE') from dual;

DBMS_METADATA.GET_DDL('INDEX','S4$_IX1','SDE')
--------------------------------------------------------------------------------

  CREATE UNIQUE INDEX "SDE"."S4$_IX1" ON "SDE"."S4_IDX$" ("GX", "GY", "MAXX", "M
AXY", "MINX", "MINY", "SP_ID")    PCTFREE 0 INITRANS 4 MAXTRANS 255 COMPUTE STAT
ISTICS    STORAGE(INITIAL 65536 NEXT 1048576 MINEXTENTS 1 MAXEXTENTS 2147483645
  PCTINCREASE 0 FREELISTS 1 FREELIST GROUPS 1
  BUFFER_POOL DEFAULT FLASH_CACHE DEFAULT CELL_FLASH_CACHE DEFAULT)
  TABLESPACE "SDE"

果然是在多列上定义的复合索引，而且SP_ID是在索引的最后一列，因此识别度很低，这个索引不是最优的。

找到原因，解决方法就比较容易了：

需要在SP_ID字段上单独建一个索引

SQL> create index s4$_ix2 on s4_idx$(sp_id);

索引已创建。

已用时间:  00: 00: 39.43

SQL> set autot traceonly
SQL> delete from s4_idx$ where sp_id='AAAWqAAAKAAAOjXAAB';

已删除 0 行。

已用时间:  00: 00: 00.00

执行计划
----------------------------------------------------------
Plan hash value: 269070202

-----------------------------------------------------------------------------
| Id  | Operation         | Name    | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------
|   0 | DELETE STATEMENT  |         |     2 |   104 |     3   (0)| 00:00:01 |
|   1 |  DELETE           | S4_IDX$ |       |       |            |          |
|*  2 |   INDEX RANGE SCAN| S4$_IX2 |     2 |   104 |     3   (0)| 00:00:01 |
-----------------------------------------------------------------------------

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

   2 - access("SP_ID"='AAAWqAAAKAAAOjXAAB')


统计信息
----------------------------------------------------------
         12  recursive calls
          0  db block gets
         11  consistent gets
          0  physical reads
          0  redo size
        864  bytes sent via SQL*Net to client
        861  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
          0  rows processed

SQL> delete from subdltb where objectid=1;

已删除 1 行。

已用时间:  00: 00: 00.01

执行计划
----------------------------------------------------------
Plan hash value: 3736342072

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

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

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

|   0 | DELETE STATEMENT             |                  |     1 |   387 |     3
  (0)| 00:00:01 |

|   1 |  DELETE                      | SUBDLTB          |       |       |
     |          |

|   2 |   TABLE ACCESS BY INDEX ROWID| SUBDLTB          |     1 |   387 |     3
  (0)| 00:00:01 |

|*  3 |    INDEX UNIQUE SCAN         | R39_SDE_ROWID_UK |     1 |       |     2
  (0)| 00:00:01 |

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


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

   3 - access("OBJECTID"=1)


统计信息
----------------------------------------------------------
         19  recursive calls
         22  db block gets
         11  consistent gets
          0  physical reads
          0  redo size
        870  bytes sent via SQL*Net to client
        845  bytes received via SQL*Net from client
          3  SQL*Net roundtrips to/from client
          3  sorts (memory)
          0  sorts (disk)
          1  rows processed