9/28号，业务部门发现一条sql运行时间突然增长，原来只需1秒，现在要10秒左右。
database 10.2.0.4 rac 2node
server aix 5.3
语句如下：
update J_ORGANIZATION c
set c.MODIFY_TIME = sysdate, c.MODIFY_EMPL_ID = 1111
where 1 = 1
and c.ORG_ID ='BJ0000270551'
and c.DEAL_STATUS = '1' ；
检查执行计划，发现没有显著影响性能
Rows Execution Plan
------- ---------------------------------------------------
0 UPDATE STATEMENT MODE: ALL_ROWS
1 UPDATE OF 'J_ORGANIZATION'
1 TABLE ACCESS MODE: ANALYZED (BY GLOBAL INDEX ROWID) OF
'J_ORGANIZATION' (TABLE) PARTITION:ROW LOCATION
1 INDEX MODE: ANALYZED (UNIQUE SCAN) OF 'UNI_ORG_ID' (INDEX
(UNIQUE))
做了10046在trace中发现多了条sql
UPDATE BDP_ZQINFO.J_OUT_ORG_FOR_TRS B SET OPER_TYPE = 0, CREATE_TIME = SYSDATE
WHERE
EXISTS (SELECT 1 FROM BDP_ZQINFO.J_OUT_ORG_FOR_TRS A WHERE A.ORG_SERIAL_ID =
B.ORG_SERIAL_ID AND B.ORG_SERIAL_ID = :B1 );
这个是触发器生成，触发器语句如下：
CREATE OR REPLACE TRIGGER T_UPD_J_ORGANIZATION
before update of modify_time -- synchro_status
on J_ORGANIZATION
for each row
declare
org_serialid number:=:old.org_serial_id;
org_prov varchar2(8):=:old.prov_region_code;
begin
-- dbms_output.put_line('bbbbbbbbbbbbbbbbbbb');
/* IF
:old.synchro_status=1 and :new.synchro_status=0 OR
:old.synchro_status is null and :new.synchro_status=0
THEN*/
sp_j_out_org_for_trs(org_serialid,org_prov);
EXCEPTION
WHEN OTHERS THEN
-- Consider logging the error and then re-raise
RAISE;
-- END IF;
end T_UPD_J_ORGANIZATION;
/
这个update应是最先运行，J_OUT_ORG_FOR_TRS表为list分区（字段为PROV_REGION_CODE） 约有4百多万行，
其中字段ORG_SERIAL_ID索引J_OUT_ORG_FOR_TRS_ID为 global normal index，索引信息如下：
OWNER INDEX_NAME INDEX_TYPE TABLE_OWNER TABLE_NAME BLEVEL LEAF_BLOCKS DISTINCT_KEYS AVG_LEAF_BLOCKS_PER_KEY AVG_DATA_BLOCKS_PER_KEY CLUSTERING_FACTOR STATUS NUM_ROWS SAMPLE_SIZE LAST_ANALYZED
BDP_ZQINFO IDX_ORGANIZATION_1 NORMAL BDP_ZQINFO J_ORGANIZATION 3 154,241 18,181,606 1 1 17,794,548 VALID 18,307,431 131,394 10-05-2012 23:34:12
BDP_ZQINFO J_OUT_ORG_FOR_TRS_ID NORMAL BDP_ZQINFO J_OUT_ORG_FOR_TRS 2 15,188 4,429,794 1 1 3,576,204 VALID 4,491,419 330,908 10-01-2012 22:24:58
此条sql执行计划如下：
WORKLOAD REPOSITORY SQL Report
Snapshot Period Summary
DB Name DB Id Instance Inst num Release RAC Host
BSTTEST 1834441837 bsttest1 1 10.2.0.4.0 YES olap1
Snap Id Snap Time Sessions Cursors/Session
Begin Snap: 35139 08-10月-12 13:00:32 231 1.7
End Snap: 35140 08-10月-12 14:00:49 249 1.7
Elapsed: 60.28 (mins)
DB Time: 212.30 (mins)
SQL Summary
SQL Id Elapsed Time (ms) Module Action SQL Text
av6s7vnuqkhh6 100,066 UPDATE J_OUT_ORG_FOR_TRS B SET OPER_TYPE = 0, CREATE_TIME = SYSDATE W...
Back to Top
SQL ID: av6s7vnuqkhh6
1st Capture and Last Capture Snap IDs refer to Snapshot IDs witin the snapshot range
UPDATE J_OUT_ORG_FOR_TRS B SET OPER_TYPE = 0, CREATE_TIME = SYSDATE WH...
# Plan Hash Value Total Elapsed Time(ms) Executions 1st Capture Snap ID Last Capture Snap ID
1 1602621420 100,066 14 35140 35140
Back to Top
Plan 1(PHV: 1602621420)
Plan Statistics
Execution Plan
Back to Top
Plan Statistics
% Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
Stat Name Statement Total Per Execution % Snap Total
Elapsed Time (ms) 100,066 7,147.57 0.79
CPU Time (ms) 97,695 6,978.23 1.18
Executions 14
Buffer Gets 335,669 23,976.36 0.09
Disk Reads 39 2.79 0.00
Parse Calls 5 0.36 0.00
Rows 40 2.86
User I/O Wait Time (ms) 173
Cluster Wait Time (ms) 2,632
Application Wait Time (ms) 0
Concurrency Wait Time (ms) 22
Invalidations 0
Version Count 5
Sharable Mem(KB) 27
Back to Plan 1(PHV: 1602621420)
Back to Top
Execution Plan
Id Operation Name Rows Bytes Cost (%CPU) Time Pstart Pstop
0 UPDATE STATEMENT 11M(100)
1 UPDATE J_OUT_ORG_FOR_TRS
2 FILTER
3 PARTITION LIST ALL 3843K 65M 4486 (3) 00:00:54 1 32
4 TABLE ACCESS FULL J_OUT_ORG_FOR_TRS 3843K 65M 4486 (3) 00:00:54 1 32
5 FILTER
6 INDEX RANGE SCAN J_OUT_ORG_FOR_TRS_ID 1 7 3 (0) 00:00:01
Back to Plan 1(PHV: 1602621420)
Back to Top
其中走了全表，花费大量时间，问如何优化？
下面是详细的trace文件：
/oracle/orabase/admin/bsttest/udump/bsttest1_ora_1421390.trc
Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bit Production
With the Partitioning, Real Application Clusters, OLAP, Data Mining
and Real Application Testing options
ORACLE_HOME = /oracle/orabase/product/10g/olap
System name: AIX
Node name: olap1
Release: 3
Version: 5
Machine: 00C6A8824C00
Instance name: bsttest1
Redo thread mounted by this instance: 1
Oracle process number: 156
Unix process pid: 1421390, image: oracle@olap1 (TNS V1-V3)
*** ACTION NAME:() 2012-10-08 13:25:14.174
*** MODULE NAME:(SQL*Plus) 2012-10-08 13:25:14.174
*** SERVICE NAME:(SYS$USERS) 2012-10-08 13:25:14.174
*** SESSION ID:(819.44232) 2012-10-08 13:25:14.174
WAIT #2: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=50576422823402
*** 2012-10-08 13:25:24.664
WAIT #2: nam='SQL*Net message from client' ela= 10235104 driver id=1650815232 #bytes=1 p3=0 obj#=-1 tim=50576433067587
WAIT #1: nam='library cache lock' ela= 277 handle address=504403169219121680 lock address=504403168553346632 100*mode+namespace=301 obj#=-1 tim=50576433068658
=====================
PARSING IN CURSOR #2 len=227 dep=1 uid=0 oct=3 lid=0 tim=50576433069481 hv=2190775527 ad='8ad0f328'
select u.name,o.name, t.update$, t.insert$, t.delete$, t.enabled from obj$ o,user$ u,trigger$ t where t.baseobject=:1 and t.obj#=o.obj# and o.owner#=u.user# and bitand(property,16)=0 and bitand(property,8)=0 order by o.obj#
END OF STMT
PARSE #2:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=50576433069477
BINDS #2:
kkscoacd
Bind#0
oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
oacflg=00 fl2=0001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=1104edb68 bln=22 avl=04 flg=05
value=182495
EXEC #2:c=0,e=146,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=50576433069691
FETCH #2:c=0,e=328,p=0,cr=15,cu=0,mis=0,r=1,dep=1,og=4,tim=50576433070035
FETCH #2:c=0,e=4,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=4,tim=50576433070074
FETCH #2:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,tim=50576433070107
STAT #2 id=1 cnt=2 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=15 pr=0 pw=0 time=352 us)'
STAT #2 id=2 cnt=2 pid=1 pos=1 obj=0 op='NESTED LOOPS (cr=15 pr=0 pw=0 time=294 us)'
STAT #2 id=3 cnt=2 pid=2 pos=1 obj=0 op='NESTED LOOPS (cr=11 pr=0 pw=0 time=248 us)'
STAT #2 id=4 cnt=2 pid=3 pos=1 obj=81 op='TABLE ACCESS BY INDEX ROWID TRIGGER$ (cr=3 pr=0 pw=0 time=169 us)'
STAT #2 id=5 cnt=2 pid=4 pos=1 obj=125 op='INDEX RANGE SCAN I_TRIGGER1 (cr=1 pr=0 pw=0 time=116 us)'
STAT #2 id=6 cnt=2 pid=3 pos=2 obj=18 op='TABLE ACCESS BY INDEX ROWID OBJ$ (cr=8 pr=0 pw=0 time=79 us)'
STAT #2 id=7 cnt=2 pid=6 pos=1 obj=36 op='INDEX UNIQUE SCAN I_OBJ1 (cr=6 pr=0 pw=0 time=29 us)'
STAT #2 id=8 cnt=2 pid=2 pos=2 obj=22 op='TABLE ACCESS CLUSTER USER$ (cr=4 pr=0 pw=0 time=39 us)'
STAT #2 id=9 cnt=2 pid=8 pos=1 obj=11 op='INDEX UNIQUE SCAN I_USER# (cr=2 pr=0 pw=0 time=13 us)'
=====================
PARSING IN CURSOR #1 len=155 dep=0 uid=5 oct=6 lid=5 tim=50576433073227 hv=500046959 ad='8de25730'
update BDP_ZQINFO.J_ORGANIZATION c set c.MODIFY_TIME = sysdate, c.MODIFY_EMPL_ID = 1111 where 1 = 1 and c.ORG_ID ='BJ0000270551' and c.DEAL_STATUS = '1'
END OF STMT
PARSE #1:c=0,e=5500,p=0,cr=15,cu=0,mis=1,r=0,dep=0,og=1,tim=50576433073224
BINDS #1:
WAIT #1: nam='db file sequential read' ela= 189 file#=179 block#=277463 blocks=1 obj#=183635 tim=50576433073777
WAIT #2: nam='library cache lock' ela= 301 handle address=504403169246502016 lock address=504403168550871736 100*mode+namespace=301 obj#=183635 tim=50576433074697
=====================
PARSING IN CURSOR #2 len=183 dep=1 uid=138 oct=6 lid=138 tim=50576433074784 hv=896090630 ad='1e6739b8'
UPDATE J_OUT_ORG_FOR_TRS B SET OPER_TYPE = 0, CREATE_TIME = SYSDATE WHERE EXISTS (SELECT 1 FROM J_OUT_ORG_FOR_TRS A WHERE A.ORG_SERIAL_ID = B.ORG_SERIAL_ID AND B.ORG_SERIAL_ID = :B1 )
END OF STMT
PARSE #2:c=0,e=511,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=50576433074781
BINDS #2:
kkscoacd
Bind#0
oacdty=02 mxl=22(21) mxlc=00 mal=00 scl=00 pre=00
oacflg=13 fl2=206001 frm=00 csi=00 siz=24 off=0
kxsbbbfp=110562a00 bln=22 avl=06 flg=09
value=-23145297
WAIT #2: nam='gc current grant busy' ela= 559 p1=442 p2=296026 p3=33619969 obj#=184185 tim=50576433356596
WAIT #2: nam='gc current block 2-way' ela= 321 p1=30 p2=90709 p3=16777217 obj#=184219 tim=50576433357396
WAIT #2: nam='gc current block 2-way' ela= 514 p1=122 p2=50469 p3=33554433 obj#=184219 tim=50576433358061
WAIT #2: nam='gc current block 2-way' ela= 521 p1=122 p2=50461 p3=33554433 obj#=184219 tim=50576433358753
WAIT #2: nam='gc cr block 2-way' ela= 466 p1=189 p2=73366 p3=1 obj#=184187 tim=50576434468561
WAIT #2: nam='gc current block 2-way' ela= 613 p1=317 p2=239612 p3=1 obj#=184190 tim=50576437055206
WAIT #2: nam='gc cr block 2-way' ela= 654 p1=319 p2=228768 p3=1 obj#=184190 tim=50576437392221
WAIT #2: nam='gc cr block 2-way' ela= 333 p1=319 p2=228994 p3=1 obj#=184190 tim=50576437697191
WAIT #2: nam='gc current block 2-way' ela= 361 p1=361 p2=270819 p3=1 obj#=184190 tim=50576437997483
WAIT #2: nam='gc cr block busy' ela= 912 p1=363 p2=459877 p3=1 obj#=184191 tim=50576438627331
WAIT #2: nam='gc cr block 2-way' ela= 358 p1=87 p2=230733 p3=1 obj#=184192 tim=50576439432074
WAIT #2: nam='gc cr block 2-way' ela= 385 p1=366 p2=121340 p3=1 obj#=184199 tim=50576441543979
WAIT #2: nam='gc cr block 2-way' ela= 428 p1=366 p2=121393 p3=1 obj#=184199 tim=50576441854612
WAIT #2: nam='gc cr block 2-way' ela= 377 p1=366 p2=121412 p3=1 obj#=184199 tim=50576441864739
WAIT #2: nam='gc current block 2-way' ela= 408 p1=366 p2=121509 p3=1 obj#=184199 tim=50576442172533
WAIT #2: nam='gc cr block 2-way' ela= 392 p1=366 p2=121653 p3=1 obj#=184199 tim=50576442467808
*** 2012-10-08 13:25:37.010
EXEC #2:c=11740000,e=12049484,p=0,cr=23912,cu=7,mis=0,r=1,dep=1,og=1,tim=50576445124325
EXEC #1:c=11750000,e=12051323,p=1,cr=23916,cu=10,mis=0,r=1,dep=0,og=1,tim=50576445124609
WAIT #1: nam='SQL*Net message to client' ela= 3 driver id=1650815232 #bytes=1 p3=0 obj#=184199 tim=50576445124710
*** 2012-10-08 13:26:08.750
WAIT #1: nam='SQL*Net message from client' ela= 30995944 driver id=1650815232 #bytes=1 p3=0 obj#=184199 tim=50576476120696
STAT #1 id=1 cnt=1 pid=0 pos=1 obj=0 op='UPDATE J_ORGANIZATION (cr=23916 pr=1 pw=0 time=12051201 us)'
STAT #1 id=2 cnt=1 pid=1 pos=1 obj=182495 op='TABLE ACCESS BY GLOBAL INDEX ROWID J_ORGANIZATION PARTITION: ROW LOCATION ROW LOCATION (cr=4 pr=1 pw=0 time=428 us)'
STAT #1 id=3 cnt=1 pid=2 pos=1 obj=183635 op='INDEX UNIQUE SCAN UNI_ORG_ID (cr=3 pr=1 pw=0 time=409 us)'
=====================
PARSING IN CURSOR #1 len=56 dep=0 uid=5 oct=42 lid=5 tim=50576476121198 hv=1729844458 ad='0'
alter session set events '10046 trace name context off'
END OF STMT
PARSE #1:c=0,e=173,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=50576476121194
EXEC #1:c=0,e=120,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=50576476121370
Edited by: 小电工II on 2012-10-7 下午11:43