Oracle删除数据效率低下案例

0
分享 2018-10-31
前段时间碰到一电信客户的删除效率低下案例,处理的过程记录一下:
现场的环境:
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.

[code]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
------- ------

1 个评论

https://blog.csdn.net/liufeng1980423/article/details/81025474

要回复文章请先登录注册