全表扫描却产生大量db file sequential read一例

简介:

开发人员在进行新系统上线前的数据校验测试时,发现一条手工执行的SQL执行了超过1小时还没有返回结果。SQL很简单:

  1. SELECT *  
  2.   FROM MOBILE_call_1204_OLD  
  3.  WHERE BILLING_NBR = '189xxxxxxxx'  
  4.    AND START_DATE = TO_DATE('2012-4-9 21:55:42''yyyy-mm-dd hh24:mi:ss')  

下面是这条SQL的真实的执行计划:

  1. -------------------------------------------------------------  
  2. | Id   | Operation          | Name                 | E-Rows |  
  3. -------------------------------------------------------------  
  4. |    0 | SELECT STATEMENT   |                      |        |  
  5. | *  1 |  TABLE ACCESS FULL | MOBILE_CALL_1204_OLD |      1 |  
  6. -------------------------------------------------------------  
  7.   
  8. Predicate Information (identified by operation id):  
  9. ---------------------------------------------------  
  10. 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的脚本):

  1. SQL> @waitprof print 4038 e 1000000  
  2.                                                                   Distinct   Avg time  
  3.     SID STATE   EVENT                         Time      Time ms     Events   ms/Event  
  4. ------- ------- -------------------------  ------- ------------ ---------- ----------  
  5.    4038 WAITING db file sequential read      99.61     4482.450        272     16.480  
  6.    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语句产生的大量单块读,又是属于什么情况呢?我们来看看单块读更细节的情况:

  1. SQL> @waitprof print 4038 e1 200000  
  2.   
  3.                                                     % Total  Total Event   Distinct   Avg time  
  4.     SID STATE   EVENT                    P1            Time      Time ms     Events   ms/Event  
  5. ------- ------- ------------------------ ------------------ ------------ ---------- ----------  
  6.    4038 WAITING db file sequential read  file#= 353   30.63      581.923        35     16.626  
  7.    4038 WAITING db file sequential read  file#= 355   28.14      534.641        40     13.366  
  8.    4038 WAITING db file sequential read  file#= 354   20.52      389.909        24     16.246  
  9.    4038 WAITING db file sequential read  file#= 3     19.63      372.942        35     10.655  
  10.    4038 WORKING On CPU / runqueue                       .66       12.616       133       .095  
  11.    4038 WAITING db file sequential read  file#= 293     .42        7.971         1      7.971  

多次执行同样的SQL,发现绝大部分的单块读发生在3、353-355这四个文件上,我们来看看这4个文件是什么:

  1. SQL> select file_id,tablespace_name from dba_data_files where file_id in (355,3,353,354);  
  2.   
  3.    FILE_ID TABLESPACE_NAME  
  4. ---------- ------------------------------  
  5.          3 UNDOTBS1  
  6.        353 UNDOTBS1  
  7.        354 UNDOTBS1  
  8.        355 UNDOTBS1  

原来是UNDO表空间。那么另一个疑问就会来了,为什么在UNDO上产生了如此之多的单块读?首先要肯定的是,这条简单的查询语句,是进行的一致性读。那么在进行一致性读的过程中,会有两个动作会涉及到读UNDO块,延迟块清除和构建CR块。下面我们用另一个脚本来查看会话当时的状况:

  1. SQL> @snapper all,out 5 3 4038  
  2. Sampling SID 4038 with interval 5 seconds, taking 3 snapshots...  
  3. setting stats to all due option = all  
  4.   
  5. -- Session Snapper v3.52 by Tanel Poder @ E2SN ( http://tech.e2sn.com )  
  6.   
  7. -------------------------------------------------------------------------------------------------------------------------------------  
  8.     SID, USERNAME  , TYPE, STATISTIC                                                 ,     HDELTA, HDELTA/SEC,    %TIME, GRAPH  
  9. -------------------------------------------------------------------------------------------------------------------------------------  
  10.    4038, BILL_MY   , STAT, session logical reads                                     ,        488,       97.6,  
  11.    4038, BILL_MY   , STAT, user I/O wait time                                        ,        429,       85.8,  
  12.    4038, BILL_MY   , STAT, non - idle wait time                                      ,        429,       85.8,  
  13.    4038, BILL_MY   , STAT, non - idle wait count                                     ,        377,       75.4,  
  14.    4038, BILL_MY   , STAT, physical read total IO requests                           ,        377,       75.4,  
  15.    4038, BILL_MY   , STAT, physical read total bytes                                 ,      3.13M,    625.87k,  
  16.    4038, BILL_MY   , STAT, cell physical IO interconnect bytes                       ,      3.13M,    625.87k,  
  17.    4038, BILL_MY   , STAT, consistent gets                                           ,        488,       97.6,  
  18.    4038, BILL_MY   , STAT, consistent gets from cache                                ,        488,       97.6,  
  19.    4038, BILL_MY   , STAT, consistent gets from cache (fastpath)                     ,          8,        1.6,  
  20.    4038, BILL_MY   , STAT, consistent gets - examination                             ,        478,       95.6,  
  21.    4038, BILL_MY   , STAT, logical read bytes from cache                             ,         4M,    799.54k,  
  22.    4038, BILL_MY   , STAT, physical reads                                            ,        382,       76.4  
  23.    4038, BILL_MY   , STAT, physical reads cache                                      ,        382,       76.4,  
  24.    4038, BILL_MY   , STAT, physical read IO requests                                 ,        377,       75.4,  
  25.    4038, BILL_MY   , STAT, physical read bytes                                       ,      3.13M,    625.87k,  
  26.    4038, BILL_MY   , STAT, db block changes                                          ,          9,        1.8,  
  27.    4038, BILL_MY   , STAT, consistent changes                                        ,        469,       93.8,  
  28.    4038, BILL_MY   , STAT, free buffer requested                                     ,        392,       78.4,  
  29.    4038, BILL_MY   , STAT, CR blocks created                                         ,         10,          2,  
  30.    4038, BILL_MY   , STAT, physical reads cache prefetch                             ,          5,          1,  
  31.    4038, BILL_MY   , STAT, shared hash latch upgrades - no wait                      ,        375,         75,  
  32.    4038, BILL_MY   , STAT, calls to kcmgas                                           ,        376,       75.2,  
  33.    4038, BILL_MY   , STAT, redo entries                                              ,          9,        1.8,  
  34.    4038, BILL_MY   , STAT, redo size                                                 ,        648,      129.6,  
  35.    4038, BILL_MY   , STAT, redo subscn max counts                                    ,          9,        1.8,  
  36.    4038, BILL_MY   , STAT, file io wait time                                         ,       4.3M,    860.97k,  
  37.    4038, BILL_MY   , STAT, data blocks consistent reads - undo records applied       ,        476,       95.2,  
  38.    4038, BILL_MY   , STAT, rollbacks only - consistent read gets                     ,          1,         .2,  
  39.    4038, BILL_MY   , STAT, cleanouts and rollbacks - consistent read gets            ,          9,        1.8,  
  40.    4038, BILL_MY   , STAT, immediate (CR) block cleanout applications                ,          9,        1.8,  
  41.    4038, BILL_MY   , STAT, commit txn count during cleanout                          ,          9,        1.8,  
  42.    4038, BILL_MY   , STAT, cleanout - number of ktugct calls                         ,          9,        1.8,  
  43.    4038, BILL_MY   , STAT, table scan rows gotten                                    ,        492,       98.4,  
  44.    4038, BILL_MY   , STAT, table scan blocks gotten                                  ,         10,          2,  
  45.    4038, BILL_MY   , STAT, heap block compress                                       ,         72,       14.4,  
  46.    4038, BILL_MY   , TIME, DB CPU                                                    ,    60.99ms,     12.2ms,     1.2%, |@         |  
  47.    4038, BILL_MY   , TIME, sql execute elapsed time                                  ,      4.35s,   869.12ms,    86.9%, |@@@@@@@@@ |  
  48.    4038, BILL_MY   , TIME, DB time                                                   ,      4.35s,   869.12ms,    86.9%, |@@@@@@@@@ |  
  49.    4038, BILL_MY   , WAIT, db file sequential read                                   ,      4.17s,   834.69ms,    83.5%, |@@@@@@@@@ |  
  50.    4038, BILL_MY   , WAIT, db file scattered read                                    ,    49.17ms,     9.83ms,     1.0%, |@         |  
  51. --  End of Stats snap 1, end=2012-05-21 22:22:16, seconds=5  
  52. ...省略另两次的采样输出。  

上面的结果是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可能比较快就执行完 了)。询问发测试的人员,称没有什么大事务运行过,耳听为虚,眼见为实:

  1. SQL> select object_id from dba_objects where object_name='MOBILE_CALL_1204_OLD';  
  2.   
  3.  OBJECT_ID  
  4. ----------  
  5.      75858  
  6.   
  7. SQL> select * from v$lock where id1=75858;  
  8.   
  9. no rows selected  
  10.   
  11. SQL> select * from dba_tab_modifications where table_name=upper('MOBILE_call_1204_OLD');  
  12.   
  13.    INSERTS    UPDATES    DELETES TIMESTAMP           TRU DROP_SEGMENTS  
  14. ---------- ---------- ---------- ------------------- --- -------------  
  15.          0  162696447          0 2012-05-21 22:00:02 NO              0  

这张表目前没有事务,但是曾经update了超过1.6亿条记录。最后一次DML的时间正是这条执行很慢的SQL开始运行之后的时间(这里不能说明 最后一次事务量很大,也不能说明最后一次修改对SQL造成了很大影响,但是这里证明了这张表最近的确是修改过,并不是像测试人员说的那样没有修改过)。

实际上对于这张表要做的操作,我之前是类似的表上是有看过的。这张表的总行数有上亿条,而这张表由于进行数据的人工处理,需要update掉绝大部分的行,update时使用并行处理。那么这个问题到,从时间顺序上来讲,应该如下:

  1. 在表上有很大的事务,但是还没有提交。
  2. 问题SQL开始执行查询。
  3. 事务提交。
  4. 在检查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,要解决其速度慢的问题,有两种方案:

  1. 在表上建个索引,如果类似的SQL还要多次执行,这是最佳方案。
  2. 取消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类型的系统上,尽量避免大事务。

http://www.laoxiong.net/full-table-scan-but-lots-of-db-file-sequential-read%E4%B8%80%E4%BE%8B.html





本文转自 vfast_chenxy 51CTO博客,原文链接:http://blog.51cto.com/chenxy/896545,如需转载请自行联系原作者
目录
相关文章
0322理解db file parallel read等待事件2
[20180322]理解db file parallel read等待事件2.txt --//上个星期的学习:http://blog.itpub.net/267265/viewspace-2151973/ https://docs.
1149 0
|
关系型数据库 Oracle Linux
0316理解db file parallel read等待事件
[20180316]理解db file parallel read等待事件.txt --//一直对db file parallel read等待事件不理解,因为在实际系统中很少遇到这样的等待事件.
1208 0

热门文章

最新文章