事情是这样的,客户有一套核心的10g业务数据库,需要针对个别大表删除2年前的归档数据,这些表都是普通的堆表(heap table),没有使用分区或其他技术。因为考虑到不能影响在线业务,所以不能使用insert append/rename的方式来加速删除,只能老老实实地在匿名PL/SQL块里通过rowid批量删除数据,虽然慢一些但还是能接受的,具体的PL/SQL块如下:
DECLARE CURSOR table_name_cur IS SELECT /*+ FULL(a) */ a.rowid from table_name a where time_column<required_date table_name_rec table_name_cur%ROWTYPE; row_number number; BEGIN row_number :=0; OPEN table_name_cur; LOOP FETCH table_name_cur INTO table_name_rec; IF table_name_cur%NOTFOUND THEN commit; EXIT; END IF; delete from table_name WHERE rowid = table_name_rec.rowid; row_number := row_number + 1; if (mod (row_number,1000) =0) then insert into delete_rows values (row_number); commit; end if; END LOOP; insert into delete_rows values (row_number); commit; CLOSE table_name_cur; END; /
可以看到以上使用一个游标FULL SCAN目标数据表取出所需删除行的rowid,之后在循环中不断fetch出rowid并实际删除数据。
问题出在一张不是非常大的LG表上(不超过10GB),删除这张LG表消耗的时间超过10个小时,而其他更大的表删除也仅用2-3个小时。
针对这一反常现象,客户对删除操作做了10046 level8的跟踪,因为整个删除过程比较长,所以仅 trace了一小段时间,因为这个trace并不完整所以没有办法使用tkprof工具分析该trace。没办法,就分析裸trace信息吧。
从trace内容来看,该时段内主要的等待是db file sequence read(简称DFSR)即数据文件单块读事件,一开始以为是表上有链式行/迁移行造成了大量的DFSR,但客户日常有对该表执行chained rows analyze,没有发现该表上有明显的chained/migrated rows问题。
具体观察该DFSR事件的p1/p2 obj#参数发现这些数据文件单块读主要是针对该LG表的2个索引的,而且最为奇怪的是其中一个索引单块读的频率远多于另外一个索引,比例大约为60:1。这2个索引的差异表现,让我意识到得问题的所在,查看dba_indexes索引视图发现最近一次分析是在4/18日,而2个索引统计信息间最大的差异不在于索引大小,而在于clustering_factor也就是我们说的聚集因子, LG表上大约有6000万条数据,索引A的clustering_factor为170万,而索引B的clustering_factor达到了3400万,即2个索引的聚集因子差20倍,显然这时因为索引A上column更为有序(可能是sequence)而索引B上的字段较为随机造成了这种反差。
因为一开始使用FULL SCAN目标数据表来获取所需的ROWID,所以在实际删除前相关数据行所在的表数据块已经被FULL SCAN读取到buffer cache中了,FULL SCAN使用scattered read多块读,在这里不是主要的性能瓶颈。最主要的问题在于,假设一个table data block中有20行数据,对于clustering_factor较低的索引A而言可能这20行数据都映射到索引的一个leaf block中,而对于clustering_factor很高的索引B而言可能这20行数据需要映射到20个leaf block中,那么如果我们要删除这个数据块中的20行数据,就需要访问索引A上的1个leaf块和索引B上的20个leaf块,因为这些都是历史归档数据,所以日常已经没有业务访问这些old leaf block了,所以这部分的叶子块几乎不会在buffer cache中,服务进程需要把它们”一一”(这里真的是一一,一次读一块)从disk上读取到缓存中;最糟糕的还不止于此,因为实例的buffer cache有限,索引B上的leaf block在读入后可能很快被踢出buffer cache,而因为table与索引B间数据的无序性,这些leaf block可能需要在后续的删除中再次访问,这将对索引B的物理读取代价大大放大了。这种代价反映在Oracle wait interface上就是用户频繁地看到针对某个索引的”db file sequential read”等待事件。
我们通过还原现场,来深入了解一下clustering factor对于删除的影响:
首先要构建一张有一列极端有序,而一列极端无序的数据表 SQL> select * from v$version; BANNER ---------------------------------------------------------------- Oracle Database 10g Enterprise Edition Release 10.2.0.4.0 - 64bi PL/SQL Release 10.2.0.4.0 - Production CORE 10.2.0.4.0 Production TNS for Linux: Version 10.2.0.4.0 - Production NLSRTL Version 10.2.0.4.0 - Production SQL> create table sample nologging tablespace users as select rownum t1 from dual connect by level<=900000; Table created. SQL> alter table sample add t2 number; Table altered. SQL> update sample set t2=dbms_random.value(1,999999999999999); 900000 rows updated. SQL> commit; Commit complete. SQL> create index ind_t1 on sample(t1) nologging; Index created. SQL> create index ind_t2 on sample(t2) nologging; Index created. SQL> exec dbms_stats.gather_table_stats('MACLEAN','SAMPLE',cascade=>TRUE); PL/SQL procedure successfully completed. SQL> select blocks,NUM_ROWS from dba_tables where table_name='SAMPLE'; BLOCKS NUM_ROWS ---------- ---------- 13213 900000 SQL> select CLUSTERING_FACTOR,LEAF_BLOCKS,DISTINCT_KEYS,index_name from dba_indexes where table_name='SAMPLE'; CLUSTERING_FACTOR LEAF_BLOCKS DISTINCT_KEYS INDEX_NAME ----------------- ----------- ------------- ------------------------------ 899782 4148 896896 IND_T2 14975 2004 900000 IND_T1 /* 以上构建了一张90万行的数据表,共13213个block T1列通过序列产生,较为有序 T2列通过随机数产生,无序 ind_t1索引构建在t1列上,clustering_factor较低14975,接近表上数据块的总数 ind_t2索引构建在t2列上,clustering_factor为899782,接近表上数据行的总数 */ SQL> alter session set events '10046 trace name context forever,level 8'; Session altered. SQL> set timing on; DECLARE CURSOR table_name_cur IS SELECT /*+ FULL(a) */ a.rowid from sample a where t1<=900000; table_name_rec table_name_cur%ROWTYPE; row_number number; BEGIN row_number :=0; OPEN table_name_cur; LOOP FETCH table_name_cur INTO table_name_rec; IF table_name_cur%NOTFOUND THEN commit; EXIT; END IF; delete from sample WHERE rowid = table_name_rec.rowid; row_number := row_number + 1; if (mod (row_number,1000) =0) then insert into delete_rows values (row_number); commit; end if; END LOOP; insert into delete_rows values (row_number); commit; CLOSE table_name_cur; END; / Elapsed: 00:03:28.52 观察其trace文件,可以发现在多次EXEC/FETCH后就会紧跟一个db file sequential read等待事件 众所周知db file sequential read等待事件在如v$session/V$session/v$active_session_history 等动态性能视图中的p1代表file号,p2为block号,p3为读取block总数,一般为1 而在10046 trace中可以直接看到file#,block#,blocks和obj#,为了分辨单块读的对象,可以直接从obj#了解 SQL> select object_id,object_name,object_type from dba_objects where object_name in ('SAMPLE','IND_T1','IND_T2'); OBJECT_ID OBJECT_NAME OBJECT_TYPE ---------- -------------------- ------------------- 1307548 IND_T1 INDEX 1307549 IND_T2 INDEX 1307547 SAMPLE TABLE WAIT #3: nam='db file sequential read' ela= 283 file#=6 block#=3311 blocks=1 obj#=1307549 tim=1275797217728516 EXEC #3:c=999,e=349,p=1,cr=2,cu=8,mis=0,r=1,dep=1,og=1,tim=1275797217728552 FETCH #2:c=0,e=5,p=0,cr=1,cu=0,mis=0,r=1,dep=1,og=1,tim=1275797217728578 EXEC #3:c=0,e=49,p=0,cr=1,cu=8,mis=0,r=1,dep=1,og=1,tim=1275797217728641 FETCH #2:c=0,e=4,p=0,cr=1,cu=0,mis=0,r=1,dep=1,og=1,tim=1275797217728663 EXEC #3:c=0,e=36,p=0,cr=1,cu=8,mis=0,r=1,dep=1,og=1,tim=1275797217728712 FETCH #2:c=0,e=3,p=0,cr=1,cu=0,mis=0,r=1,dep=1,og=1,tim=1275797217728732 WAIT #3: nam='db file sequential read' ela= 205 file#=6 block#=3956 blocks=1 obj#=1307549 tim=1275797217728979 EXEC #3:c=0,e=265,p=1,cr=1,cu=8,mis=0,r=1,dep=1,og=1,tim=1275797217729010 FETCH #2:c=0,e=5,p=0,cr=1,cu=0,mis=0,r=1,dep=1,og=1,tim=1275797217729036 [oracle@rh2 udump]$ cat g10r2_ora_5190.trc|grep "db file sequential read"|wc -l 72395 [oracle@rh2 udump]$ cat g10r2_ora_5190.trc|grep "db file sequential read"|grep 1307549|wc -l 67721 [oracle@rh2 udump]$ cat g10r2_ora_5190.trc|grep "db file sequential read"|grep 1307548|wc -l 3878 /* 以上object_id 1307549对应为较高clustering_factor的索引IND_T2, 该索引发生了绝大多数db file sequential read等待 而object_id 1307548对应为较低clustering_factor的索引IND_T1, 该索引发生了较少量的db file sequential read等待 */ SQL> select sql_id,executions,disk_reads,user_io_wait_time/1000000,elapsed_time/1000000 2 from v$sql 3 where sql_text='DELETE FROM SAMPLE WHERE ROWID = :B1 '; SQL_ID EXECUTIONS DISK_READS USER_IO_WAIT_TIME/1000000 ELAPSED_TIME/1000000 ------------- ---------- ---------- ------------------------- -------------------- 31m4m2drt2t5m 900000 74936 67.862581 147.743482 [oracle@rh2 udump]$ tkprof g10r2_ora_5190.trc 5190.tkf sys=no DELETE FROM SAMPLE WHERE ROWID = :B1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 900000 78.67 147.73 74936 916440 6401613 900000 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 900001 78.67 147.73 74936 916440 6401613 900000 Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer mode: ALL_ROWS Parsing user id: 64 (recursive depth: 1) 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 21.99 21.99 db file sequential read 72362 0.05 67.60 db file scattered read 543 0.00 0.25 log file switch completion 29 0.97 5.81 free buffer waits 268 0.01 2.83 latch: cache buffers lru chain 3 0.00 0.00 latch: object queue header operation 5 0.00 0.00 log file switch (checkpoint incomplete) 22 0.97 8.46 latch: In memory undo latch 2 0.00 0.00 latch: cache buffers chains 1 0.00 0.00
可能是受限于固化的思维,在我的潜意识中总是觉得clustering_factor聚集因子只会影响select查询语句,而忽略了其对update/delete操作的影响;事实是clustering_factor(注意它只是一个统计信息指标,而非参数)反映了数据在表中的随机分布程度,当表上的数据分布无序时表和索引间的交叉访问将显得很糟糕,这种交叉访问并不局限于查询语句(一个典型可能是INDEX RANGE SCAN-TABLE ACCESS BY INDEX ROWID),也可能发生在DML操作所隐含的维护索引操作中。
显然除了通过以某些列的顺序整理表外没有太好的方法来降低clustering_factor,但实际上这样做是不可能的。首先定期有序化整理的成本过高了,其次如果表上有多个单列上的不同索引,如我们上述演示中的t1、t2列,如果以t2列的顺序整理表那么一个很可能的结果是t1列上的索引的clustering factor猛增,如:
SQL> create table ordered_sample nologging tablespace users as select * From sample order by t2; Table created. SQL> truncate table sample; Table truncated. SQL> insert /*+ append */ into sample select * from ordered_sample; 900000 rows created. SQL> commit; Commit complete. SQL> exec dbms_stats.gather_table_stats('MACLEAN','SAMPLE',cascade=>TRUE); PL/SQL procedure successfully completed. SQL> select clustering_factor,index_name from dba_indexes where table_name='SAMPLE'; CLUSTERING_FACTOR INDEX_NAME ----------------- ------------------------------ 899782 IND_T1 3983 IND_T2 /* 可以看到ind_t2所以的clustering_factor的确下降了,换得的是ind_t1对应的增长 */
针对由该clustering_factor引起的低效率批量delete/update操作,我们可以通过以下措施减少”db file sequential read”等待的出现:
- 通过keep cache保留池等技术将clustering_factor过高的索引缓存住,以避免频繁地单块物理读,从而提高性能
- 如果你正在执行一个大作业,那么可以暂时将clustering_factor过高的索引drop掉,在完成操作后再重建该索引,这样起到加速作业的目的
rebuild重建索引在以上案例的情景中获益并不大。
另外”db file sequential read”单块读等待是一种最为常见的物理IO等待事件,这里的sequential指的是将数据块读入到相连的内存空间中(contiguous memory space),而不是指所读取的数据块是连续的。该wait event可能在以下情景中发生:
- 最为常见的是执行计划中包含了INDEX FULL SCAN/UNIQUE SCAN,此时出现”db file sequential read”等待是预料之中的,一般不需要我们去特别关注
- 当执行计划包含了INDEX RANGE SCAN-(“TABLE ACCESS BY INDEX ROWID”/”DELETE”/”UPDATE”),服务进程将按照”访问索引->找到rowid->访问rowid指定的表数据块并执行必要的操作”顺序访问index和table,每次物理读取都会进入”db file sequential read”等待,且每次读取的都是一个数据块;这种情况下clustering_factor将发挥其作用,需要我们特别去关注,本例中提及的解决方法对这种情景也有效
- Extent boundary,假设一个Extent区间中有33个数据块,而一次”db file scattered read”多块读所读取的块数为8,那么在读取这个区间时经过4次多块读取后,还剩下一个数据块,但是请记住多块读scattered read是不能跨越一个区间的(span an extent),此时就会单块读取并出现”db file scattered read”。这是一种正常现象,一般不需要额外关注
- 假设某个区间内有8个数据块,它们可以是块a,b,c,d,e,f,g,h,恰好当前系统中除了d块外的其他数据块都已经被缓存在buffer cache中了,而这时候恰好要访问这个区间中的数据,那么此时就会单块读取d这个数据块,并出现”db file sequential read”等待。注意这种情况不仅于表,也可能发生在索引上。这是一种正常现象,一般不需要额外关注
- chained/migrated rows即链式或迁移行,这里我们不介绍链式行的形成原因,chained/migrated rows会造成服务进程在fetch一行记录时需要额外地单块读取,从而出现”db file sequential read”。这种现象需要我们特别去关注,因为大量的链式/迁移行将导致如FULL SCAN等操作极度恶化(以往的经验是一张本来全表扫描只需要30分钟的表,在出现大量链式行后,全表扫描需要数个小时),同时也会对其他操作造成不那么明显的性能影响。可以通过监控v$sysstat视图中的”table fetch continued row”操作统计来了解系统中链式/迁移行访问的情况,还可以通过DBA_TBALES视图中的CHAIN_CNT来了解表上的链式/迁移行情况,当然这要求定期收集表上的统计信息;如果没有定期收集的习惯,那么可以配合@?/rdbms/admin/utlchain脚本和analyze table list chained rows 命令来获取必要的链式行信息
- 创建Index entry,显然当对表上执行INSERT操作插入数据时,虽然在执行计划中你看不到过多的细节,但实际上我们需要利用索引来快速验证表上的某些约束是否合理,还需要在索引的叶子块中插入相关的记录,此时也可能出现”db file sequential read”等待事件,当然这还和具体的插入的方式有关系。这是一种正常现象,一般不需要额外关注
- 针对表上的UPDATE/DELETE,不同于之前提到的”INDEX RANGE SCAN-UPDATE/DELETE”,如果我们使用rowid去更新或删除数据时,服务进程会先访问rowid指向的表块(注意是先访问table block)上的行数据,之后会根据该行上的具体数据去访问索引叶子块(注意Oracle并不知道这些leaf block在哪里,所以这里同样要如range-scan/unique-scan那样去访问index branch block),这些访问都将会是单块读取,并会出现’db file sequential read’,完成必要的读取后才会执行更新或删除的实际EXEC操作,如下例:
以下trace中,obj#=1307547为sample表,而obj#=1307549为sample表上的唯一一个索引
PARSING IN CURSOR #10 len=58 dep=0 uid=64 oct=6 lid=64 tim=1275805024007795 hv=505118268 ad='d387e470'
update sample set t2=t2+1 where rowid='AAE/OzAAEAAANUEAAQ'
END OF STMT
PARSE #10:c=1999,e=3016,p=1,cr=1,cu=0,mis=1,r=0,dep=0,og=1,tim=1275805024007787
WAIT #10: nam='db file sequential read' ela= 314 file#=4 block#=54532 blocks=1 obj#=1307547 tim=1275805024008308
WAIT #10: nam='db file sequential read' ela= 206 file#=6 block#=20 blocks=1 obj#=1307549 tim=1275805024009235
WAIT #10: nam='db file sequential read' ela= 206 file#=6 block#=742 blocks=1 obj#=1307549 tim=1275805024009496
WAIT #10: nam='db file sequential read' ela= 207 file#=6 block#=24 blocks=1 obj#=1307549 tim=1275805024009750
EXEC #10:c=2000,e=2297,p=6,cr=2,cu=8,mis=0,r=1,dep=0,og=1,tim=1275805024010210 --实际的UPDATE发生在这里
当大量执行这类UPDATE/DELETE操作时将需要频繁地交叉访问表和索引,如果恰好表上的某个索引有较高的clustering_factor的话,那么就会形成本例中的这种性能问题了。实际上当表上有较多索引时,使用rowid来批量update/delete数据这种方式是不被推荐的,仅当表上没有索引时才可能十分高效。如果你坚持要这样做,那么可以参照上面提到的建议。
8.BUG!BUG!已知在9i RAC及10g中使用ASM的情况下,存在引发在适用情况下不使用”scattered read”多块读而去使用”sequential read”的BUG。如果你的问题和上述情景都不匹配,但又有大量的”db file sequential read”等待事件,那么你有可能遇到bug了。在这里列出部分已知bug:
Bug# | Version Affected |
Bug 7243560 – High “db file sequential read” IO times when using ASM | 10.2.0.4/11.1.0.7 |
Bug 7243560: RAPID INCREASE IN DB FILE SEQUENTIAL READ AFTER MOVING TO ASM | 10.2.0.3 |
Bug 9711810: EXCESSIVE DB FILE SEQUENTIAL READS WITH NON COMPLIANT BUFFER CACHE ON RAC | 9.2.0.8 |
Bug 9276739: INSERT STATEMENT HAS SLOW PERFORMANCE WITH DB FILE SEQUENTIAL READ | 10.2.0.4 |
Bug 8625100: EXCESSIVE DB FILE SEQUENTIAL READ ON UNDO | 10.2.0.4 |
Bug 8669544: HIGH DB FILE SEQUENTIAL READ AND GC CR DISK READ WAIT EVENTS DURING FULL SCAN | 10.2.0.4 |
Bug 7427133: AN INSERT CAUSES LOTS OF ‘DB FILE SEQUENTIAL READ’ WAITS FOR THE INDEX BLOCKS | 9.2.0.8 |
Bug 8493139: INCREASE IN DB FILE SEQUENTIAL READ WAITEVENT AFTER MIGRATING TO 10 RAC/ASM | 10.2.0.4 |
Bug 5882268: PERFORMANCE ISSUE WITH ‘DB FILE SEQUENTIAL READ’ | 10.2.0.2 |
Bug 7415702: LOTS OF ‘DB FILE SEQUENTIAL READ’ ON UNDO | 10.2.0.3 |
Bug 5607724: 10202 DB FILE SEQUENTIAL READ THRICE AFTER UPGRADE FROM 9I | 10.2.0.2 |