开发人员在进行新系统上线前的数据校验测试时，发现一条手工执行的SQL执行了超过1小时还没有返回结果。SQL很简单：
SELECT *
FROM MOBILE_call_1204_OLD
WHERE BILLING_NBR = '189xxxxxxxx'
AND START_DATE = TO_DATE('2012-4-9 21:55:42', 'yyyy-mm-dd hh24:mi:ss')
下面是这条SQL的真实的执行计划：
-------------------------------------------------------------
| Id | Operation | Name | E-Rows |
-------------------------------------------------------------
| 0 | SELECT STATEMENT | | |
| * 1 | TABLE ACCESS FULL | MOBILE_CALL_1204_OLD | 1 |
-------------------------------------------------------------
Predicate Information (identified by operation id):
---------------------------------------------------
1 - filter(("START_DATE"=TO_DATE(' 2012-04-09 21:55:42', 'syyyy-mm-dd hh24:mi:ss') AND "BILLING_NBR"='189xxxxxxxx'))
很显然，在这个表上建billing_nbr和start_date的复合索引，这条SQL就能很快执行完（实际上最后也建了索引）。但是这里我们要探讨的是，为什么这么一条简单的SQL语句，执行了超过1小时还没有结果。MOBILE_CALL_1204_OLD这张表的大小约为12GB，以系统的IO能力，正常情况下不会执行这么长的时间。简单地看了一下，系统的CPU以及IO压力都不高。假设单进程全表扫描表，每秒扫描50MB大小（这实际上是一个很保守的扫描速度了），那么只需要245秒就可以完成扫描。
下面来诊断一下SQL为什么会这么不正常地慢。看看会话的等待（以下会用到Oracle大牛Tanel Poder的脚本）：
SQL> @waitprof print 4038 e 1000000
Distinct Avg time
SID STATE EVENT Time Time ms Events ms/Event
------- ------- ------------------------- ------- ------------ ---------- ----------
4038 WAITING db file sequential read 99.61 4482.450 272 16.480
4038 WORKING On CPU / runqueue .39 17.550 271 .065
明明是全表扫描的SQL，为什么99%以上的等待时间是db file sequential read，即单块读？！多执行几次waitprof脚本，得到的结果是一致的（注意这里的数据，特别是平均等待时间并不一定是准确的值，这里重点关注的是等待时间的分布）。
那么SQL执行计划为全表扫描（或索引快速全扫描）的时候，在运行时会有哪些情况实际上是单块读？我目前能想到的有：
- db_file_multiblock_read_count参数设置为1
- 表或索引的大部分块在buffer cache中，少量不连续的块在磁盘上。
- 一些特殊的块，比如段头
- 行链接的块
- LOB列的索引块和cache的LOB块（虽然10046事件看不到lob索引和cache的lob的读等待，但客观上是存在的。）
那么在这条SQL语句产生的大量单块读，又是属于什么情况呢？我们来看看单块读更细节的情况：
SQL> @waitprof print 4038 e1 200000
% Total Total Event Distinct Avg time
SID STATE EVENT P1 Time Time ms Events ms/Event
------- ------- ------------------------ ------------------ ------------ ---------- ----------
4038 WAITING db file sequential read file#= 353 30.63 581.923 35 16.626
4038 WAITING db file sequential read file#= 355 28.14 534.641 40 13.366
4038 WAITING db file sequential read file#= 354 20.52 389.909 24 16.246
4038 WAITING db file sequential read file#= 3 19.63 372.942 35 10.655
4038 WORKING On CPU / runqueue .66 12.616 133 .095
4038 WAITING db file sequential read file#= 293 .42 7.971 1 7.971
多次执行同样的SQL，发现绝大部分的单块读发生在3、353-355这四个文件上，我们来看看这4个文件是什么：
SQL> select file_id,tablespace_name from dba_data_files where file_id in (355,3,353,354);
FILE_ID TABLESPACE_NAME
---------- ------------------------------
3 UNDOTBS1
353 UNDOTBS1
354 UNDOTBS1
355 UNDOTBS1
原来是UNDO表空间。那么另一个疑问就会来了，为什么在UNDO上产生了如此之多的单块读？首先要肯定的是，这条简单的查询语句，是进行的一致性读。那么在进行一致性读的过程中，会有两个动作会涉及到读UNDO块，延迟块清除和构建CR块。下面我们用另一个脚本来查看会话当时的状况：
SQL> @snapper all,out 5 3 4038
Sampling SID 4038 with interval 5 seconds, taking 3 snapshots...
setting stats to all due option = all
-- Session Snapper v3.52 by Tanel Poder @ E2SN ( http://tech.e2sn.com )
-------------------------------------------------------------------------------------------------------------------------------------
SID, USERNAME , TYPE, STATISTIC , HDELTA, HDELTA/SEC, %TIME, GRAPH
-------------------------------------------------------------------------------------------------------------------------------------
4038, BILL_MY , STAT, session logical reads , 488, 97.6,
4038, BILL_MY , STAT, user I/O wait time , 429, 85.8,
4038, BILL_MY , STAT, non - idle wait time , 429, 85.8,
4038, BILL_MY , STAT, non - idle wait count , 377, 75.4,
4038, BILL_MY , STAT, physical read total IO requests , 377, 75.4,
4038, BILL_MY , STAT, physical read total bytes , 3.13M, 625.87k,
4038, BILL_MY , STAT, cell physical IO interconnect bytes , 3.13M, 625.87k,
4038, BILL_MY , STAT, consistent gets , 488, 97.6,
4038, BILL_MY , STAT, consistent gets from cache , 488, 97.6,
4038, BILL_MY , STAT, consistent gets from cache (fastpath) , 8, 1.6,
4038, BILL_MY , STAT, consistent gets - examination , 478, 95.6,
4038, BILL_MY , STAT, logical read bytes from cache , 4M, 799.54k,
4038, BILL_MY , STAT, physical reads , 382, 76.4
4038, BILL_MY , STAT, physical reads cache , 382, 76.4,
4038, BILL_MY , STAT, physical read IO requests , 377, 75.4,
4038, BILL_MY , STAT, physical read bytes , 3.13M, 625.87k,
4038, BILL_MY , STAT, db block changes , 9, 1.8,
4038, BILL_MY , STAT, consistent changes , 469, 93.8,
4038, BILL_MY , STAT, free buffer requested , 392, 78.4,
4038, BILL_MY , STAT, CR blocks created , 10, 2,
4038, BILL_MY , STAT, physical reads cache prefetch , 5, 1,
4038, BILL_MY , STAT, shared hash latch upgrades - no wait , 375, 75,
4038, BILL_MY , STAT, calls to kcmgas , 376, 75.2,
4038, BILL_MY , STAT, redo entries , 9, 1.8,
4038, BILL_MY , STAT, redo size , 648, 129.6,
4038, BILL_MY , STAT, redo subscn max counts , 9, 1.8,
4038, BILL_MY , STAT, file io wait time , 4.3M, 860.97k,
4038, BILL_MY , STAT, data blocks consistent reads - undo records applied , 476, 95.2,
4038, BILL_MY , STAT, rollbacks only - consistent read gets , 1, .2,
4038, BILL_MY , STAT, cleanouts and rollbacks - consistent read gets , 9, 1.8,
4038, BILL_MY , STAT, immediate (CR) block cleanout applications , 9, 1.8,
4038, BILL_MY , STAT, commit txn count during cleanout , 9, 1.8,
4038, BILL_MY , STAT, cleanout - number of ktugct calls , 9, 1.8,
4038, BILL_MY , STAT, table scan rows gotten , 492, 98.4,
4038, BILL_MY , STAT, table scan blocks gotten , 10, 2,
4038, BILL_MY , STAT, heap block compress , 72, 14.4,
4038, BILL_MY , TIME, DB CPU , 60.99ms, 12.2ms, 1.2%, |@ |
4038, BILL_MY , TIME, sql execute elapsed time , 4.35s, 869.12ms, 86.9%, |@@@@@@@@@ |
4038, BILL_MY , TIME, DB time , 4.35s, 869.12ms, 86.9%, |@@@@@@@@@ |
4038, BILL_MY , WAIT, db file sequential read , 4.17s, 834.69ms, 83.5%, |@@@@@@@@@ |
4038, BILL_MY , WAIT, db file scattered read , 49.17ms, 9.83ms, 1.0%, |@ |
-- End of Stats snap 1, end=2012-05-21 22:22:16, seconds=5
...省略另两次的采样输出。
上面的结果是5秒左右的会话采样数据。再一次提醒，涉及到时间，特别要精确到毫秒的，不一定很精确，我们主要是看数据之间的对比。从上面的数据来看，会话请求了382次IO请求，单块读和多块读一共耗时4219.17ms（4.17s+49.17ms），平均每次IO耗时11ms。这个单次IO速度对这套系统的要求来说相对较慢，但也不是慢得很离谱。data blocks consistent reads - undo records applied这个统计值表示进行一致性读时，回滚的UNDO记录条数。
比这个统计值可以很明显地看出，这条SQL在执行时，为了得到一致性读，产生了大量的UNDO记录回滚。那么很显然，在这条SQL语句开始执行的时候，表上有很大的事务还没有提交。当然还有另一种可能是SQL在执行之后有新的很大的事务（不过这种可能性较小一些，因为那样的话这条SQL可能比较快就执行完了）。询问发测试的人员，称没有什么大事务运行过，耳听为虚，眼见为实：
SQL> select object_id from dba_objects where object_name='MOBILE_CALL_1204_OLD';
OBJECT_ID
----------
75858
SQL> select * from v$lock where id1=75858;
no rows selected
SQL> select * from dba_tab_modifications where table_name=upper('MOBILE_call_1204_OLD');
INSERTS UPDATES DELETES TIMESTAMP TRU DROP_SEGMENTS
---------- ---------- ---------- ------------------- --- -------------
0 162696447 0 2012-05-21 22:00:02 NO 0
这张表目前没有事务，但是曾经update了超过1.6亿条记录。最后一次DML的时间正是这条执行很慢的SQL开始运行之后的时间（这里不能说明最后一次事务量很大，也不能说明最后一次修改对SQL造成了很大影响，但是这里证明了这张表最近的确是修改过，并不是像测试人员说的那样没有修改过）。
实际上对于这张表要做的操作，我之前是类似的表上是有看过的。这张表的总行数有上亿条，而这张表由于进行数据的人工处理，需要update掉绝大部分的行，update时使用并行处理。那么这个问题到，从时间顺序上来讲，应该如下：
- 在表上有很大的事务，但是还没有提交。
- 问题SQL开始执行查询。
- 事务提交。
- 在检查SQL性能问题时，表上已经没有事务。
由于update量很大，那么UNDO占用的空间也很大，但是可能由于其他活动的影响，很多UNDO块已经刷出内存，这样在问题SQL执行时，大量的块需要将块回滚到之前的状态（虽然事务开始于查询SQL，但是是在查询SQL开始之后才提交的，一致性读的SCN比较是根据SQL开始的SCN与事务提交SCN比较的，而不是跟事务的开始SCN比较），这样需要访问到大量的UNDO块，但是UNDO块很多已经不在内存中，就不得不从磁盘读入。
对于大事务，特别是更新或DELETE数千万记录的大事务，在生产系统上尽量避免单条SQL一次性做。这造成的影响特别大，比如：
- 事务可能意外中断，回滚时间很长，事务恢复时过高的并行度可能引起负载增加。
- 表中大量的行长时间被锁住。
- 如果事务意外中断，长时间的回滚（恢复）过程中，可能严重影响SQL性能（因为查询时需要回滚块）。
- 事务还未提交时，影响SQL性能，比如本文中提到的情况。
- 消耗过多UNDO空间。
- 对于DELETE大事务，有些版本的oracle在空闲空间查找上会有问题，导致在INSERT数据时，查找空间导致过长的时间。
- 对于RAC数据库，由于一致性读的代价更大，所以大事务的危害更大。
那么，现在我们可以知道，全表扫描过程还会产生单块读的情况有，读UNDO块。
对于这条SQL，要解决其速度慢的问题，有两种方案：
- 在表上建个索引，如果类似的SQL还要多次执行，这是最佳方案。
- 取消SQL，重新执行。因为已经没有事务在运行，重新执行只是会产生事务清除，但不会回滚UNDO记录来构建一致性读块。
继续回到问题，从统计数据来看，每秒只构建了少量的一致性读块（CR block created，table scan blocks gotten这两个值均为2），每秒的table scan rows gotten值为98.4，通过dump数据块可以发现块上的行数基本上在49行左右，所以一致性读块数和行数是匹配的。session logical reads每秒为97.6，由于每回滚一条undo记录都要记录一次逻辑读，这个值跟每秒获取的行数也是匹配的（误差值很小），与data blocks consistent reads - undo records applied的值也是很接近的。问题到这儿，产生了一个疑问，就是单块读较多（超过70），因此可以推测，平均每个undo块只回滚了不到2条的undo记录，同时同一数据块上各行对应的undo记录很分散，分散到了多个undo块中，通常应该是聚集在同一个块或相邻块中，这一点非常奇怪，不过现在已经没有这个环境（undo块已经被其他事务重用），不能继续深入地分析这个问题，就留着一个疑问，欢迎探讨（一个可能的解释是块是由多个并发事务修改的，对于这个案例，不会是这种情况，因为在数据块的dump中没有过多ITL，另外更不太可能是一个块更新了多次，因为表实在很大，在短时间内不可能在表上发生很多次这样的大事务）。
在最后，我特别要提到，在生产系统上，特别是OLTP类型的系统上，尽量避免大事务。
