• Oracle全表扫描导致的direct path read第一次慢第二次以后变快


    Oracle全表扫描导致的direct path read第一次慢第二次以后变快

    发现一个有趣的问题,表zkm.zkm_nocompress是我创建的一张测试表,表上没有任何索引。

    有SQL语句:select count(*) from zkm.zkm_nocompress,执行的话理所当然就是走全表扫描了。

    在我的环境上,这个SQL语句是每次都会进行物理读的,等待事件是”direct path read“,不经过db buffer cache。

    如标题所讲的,这条SQL语句第一次执行差不多需要13s左右,但是第二次以后无论是不是新开会话去执行都在3s多。

    也就是第二次以后更快一点。

    并且每隔一段时间之后这个现象又会重新开始。

    如果会话开启statistics_level=all然后两次执行这条SQL会发现,都是进行物理读。

    这就奇怪了,由于是全表扫描并且第二次以后不缓存,可以确定是使用了直接路径读的方式,

    但是都是物理读,物理读的大小又不变为啥第二次就快了?

    09:10:16 SYS@testdb01(1924)> select count(*) from zkm.zkm_nocompress;
    
      COUNT(*)
    ----------
       1592893
    
    Elapsed: 00:00:12.23
    09:10:55 SYS@testdb01(1924)> select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));
    
    PLAN_TABLE_OUTPUT
    ---------------------------------------------------------------------------------------------------------
    SQL_ID  6q9uvh9vct64n, child number 0
    -------------------------------------
    select count(*) from zkm.zkm_nocompress
    
    Plan hash value: 3202340046
    
    --------------------------------------------------------------------------------------------------------
    | Id  | Operation          | Name           | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
    --------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT   |                |      1 |        |      1 |00:00:12.21 |     310K|    310K|
    |   1 |  SORT AGGREGATE    |                |      1 |      1 |      1 |00:00:12.21 |     310K|    310K|
    |   2 |   TABLE ACCESS FULL| ZKM_NOCOMPRESS |      1 |   1592K|   1592K|00:00:12.13 |     310K|    310K|
    --------------------------------------------------------------------------------------------------------
    
    
    14 rows selected.
    
    Elapsed: 00:00:00.03
    09:11:04 SYS@testdb01(1924)> select count(*) from zkm.zkm_nocompress;
    
      COUNT(*)
    ----------
       1592893
    
    Elapsed: 00:00:03.22
    09:11:10 SYS@testdb01(1924)> select * from table(dbms_xplan.display_cursor(null,null,'allstats last'));
    
    PLAN_TABLE_OUTPUT
    -------------------------------------------------------------------------------------------------------
    SQL_ID  6q9uvh9vct64n, child number 0
    -------------------------------------
    select count(*) from zkm.zkm_nocompress
    
    Plan hash value: 3202340046
    
    --------------------------------------------------------------------------------------------------------
    | Id  | Operation          | Name           | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
    --------------------------------------------------------------------------------------------------------
    |   0 | SELECT STATEMENT   |                |      1 |        |      1 |00:00:03.22 |     310K|    310K|
    |   1 |  SORT AGGREGATE    |                |      1 |      1 |      1 |00:00:03.22 |     310K|    310K|
    |   2 |   TABLE ACCESS FULL| ZKM_NOCOMPRESS |      1 |   1592K|   1592K|00:00:03.14 |     310K|    310K|
    --------------------------------------------------------------------------------------------------------
    
    
    14 rows selected.
    
    Elapsed: 00:00:00.02

    于是前后两次会同样的会话统计发生过的等待事件以及事件发生的次数和平均时间。

    查询视图v$session_event,结果如下:

    (PS:需要注意,不支持快速计时机制的平台上,v$session_event.TIME_WAITED和v$session_event.AVERAGE_WAIT列将包含零值。如果您在这些平台之一上运行并且希望此列反映真实的等待时间,则必须在参数文件中设置TIMED_STATISTICStrue请记住,这样做会对系统性能产生很小的负面影响。我的环境默认就是true的值。)

    (PS:AVERAGE_WAIT,会话等待事件的平均时间(以百分之一秒为单位))

    第一次执行后:
    09:49:35 SYS@testdb01(1997)> select event,total_waits,average_wait from v$session_event where sid=1924;
    
    EVENT                               TOTAL_WAITS AVERAGE_WAIT
    ----------------------------------- ----------- ------------
    Disk file operations I/O                     20          .01
    enq: KO - fast object checkpoint              3          .02
    gc current block 2-way                        4          .03
    direct path read                           1874          .64
    library cache pin                             2          .02
    library cache lock                            2          .05
    SQL*Net message to client                     8            0
    SQL*Net message from client                   7       863.77
    events in waitclass Other                     1          .22
    
    9 rows selected.
    
    Elapsed: 00:00:00.00
    
    SID=1924的会话重新登录进行第二次运行(快速登出登入的SID不会变):
    09:50:47 SYS@testdb01(1997)> select event,total_waits,average_wait from v$session_event where sid=1924;
    
    EVENT                               TOTAL_WAITS AVERAGE_WAIT
    ----------------------------------- ----------- ------------
    Disk file operations I/O                     19          .01
    enq: KO - fast object checkpoint              3          .03
    direct path read                           2425          .08
    SQL*Net message to client                     8            0
    SQL*Net message from client                   7        182.1
    events in waitclass Other                     1          .18
    
    6 rows selected.
    
    Elapsed: 00:00:00.00

    其中,第一次执行的等待事件"direct path read"的总时间为1874*0.64=1199.36,实际上就是TIME_WAITED字段的值,1199.36也就是11.9936s。

    而第二次"direct path read"的总时间2425*0.08=194=1.94s。

    可以看出,主要时间是花在direct path read上,然而这是为啥?都是物理读为啥第二次的要比第一次的要快?

    难道是两次SQL执行过程中每次的"direct path read"进行多块读的时候块数不一样导致的?

    那也不应该,第二次的"direct path read"次数2425比第一次1874还多,"direct path read"发生次数少至少说明平均起来的多块读块数要多于第二次的,那应该是第一次更快才是。

    还是做了一次10046看情况:

    第一次:

    WAIT #140307048128352: nam='direct path read' ela= 4032 file number=103 first dba=694144 block cnt=128 obj#=289939 tim=1634698487631159
    WAIT #140307048128352: nam='direct path read' ela= 21069 file number=101 first dba=687873 block cnt=127 obj#=289939 tim=1634698487652742
    WAIT #140307048128352: nam='direct path read' ela= 17696 file number=80 first dba=637185 block cnt=127 obj#=289939 tim=1634698487671430
    WAIT #140307048128352: nam='direct path read' ela= 14427 file number=74 first dba=615553 block cnt=127 obj#=289939 tim=1634698487687156
    WAIT #140307048128352: nam='direct path read' ela= 2004 file number=69 first dba=751489 block cnt=127 obj#=289939 tim=1634698487690035
    WAIT #140307048128352: nam='direct path read' ela= 5011 file number=68 first dba=752256 block cnt=128 obj#=289939 tim=1634698487695448
    WAIT #140307048128352: nam='direct path read' ela= 8843 file number=10 first dba=1660288 block cnt=128 obj#=289939 tim=1634698487705309
    WAIT #140307048128352: nam='direct path read' ela= 22152 file number=105 first dba=1895809 block cnt=127 obj#=289939 tim=1634698487727882
    WAIT #140307048128352: nam='direct path read' ela= 8268 file number=101 first dba=688129 block cnt=127 obj#=289939 tim=1634698487737025
    WAIT #140307048128352: nam='direct path read' ela= 6492 file number=98 first dba=683264 block cnt=128 obj#=289939 tim=1634698487744008
    WAIT #140307048128352: nam='direct path read' ela= 11333 file number=79 first dba=639104 block cnt=128 obj#=289939 tim=1634698487756289
    WAIT #140307048128352: nam='direct path read' ela= 560 file number=74 first dba=615681 block cnt=127 obj#=289939 tim=1634698487757164
    WAIT #140307048128352: nam='direct path read' ela= 9948 file number=73 first dba=614656 block cnt=128 obj#=289939 tim=1634698487767617
    WAIT #140307048128352: nam='direct path read' ela= 6914 file number=69 first dba=751617 block cnt=127 obj#=289939 tim=1634698487775311
    WAIT #140307048128352: nam='direct path read' ela= 9914 file number=20 first dba=2468865 block cnt=127 obj#=289939 tim=1634698487786094
    WAIT #140307048128352: nam='direct path read' ela= 5982 file number=10 first dba=1663232 block cnt=128 obj#=289939 tim=1634698487792658
    WAIT #140307048128352: nam='direct path read' ela= 2576 file number=105 first dba=1895937 block cnt=127 obj#=289939 tim=1634698487796115
    WAIT #140307048128352: nam='direct path read' ela= 6034 file number=103 first dba=694912 block cnt=128 obj#=289939 tim=1634698487802656
    WAIT #140307048128352: nam='direct path read' ela= 5909 file number=101 first dba=689921 block cnt=127 obj#=289939 tim=1634698487809347
    WAIT #140307048128352: nam='direct path read' ela= 8411 file number=98 first dba=687488 block cnt=128 obj#=289939 tim=1634698487818256
    WAIT #140307048128352: nam='direct path read' ela= 3733 file number=80 first dba=647041 block cnt=127 obj#=289939 tim=1634698487822741
    WAIT #140307048128352: nam='direct path read' ela= 8669 file number=79 first dba=639360 block cnt=128 obj#=289939 tim=1634698487831905
    WAIT #140307048128352: nam='direct path read' ela= 930 file number=74 first dba=616065 block cnt=127 obj#=289939 tim=1634698487833495
    WAIT #140307048128352: nam='direct path read' ela= 10385 file number=73 first dba=615296 block cnt=128 obj#=289939 tim=1634698487844450
    WAIT #140307048128352: nam='direct path read' ela= 1095 file number=69 first dba=751745 block cnt=127 obj#=289939 tim=1634698487846292
    WAIT #140307048128352: nam='direct path read' ela= 10472 file number=68 first dba=752512 block cnt=128 obj#=289939 tim=1634698487857264
    WAIT #140307048128352: nam='direct path read' ela= 21744 file number=10 first dba=1663488 block cnt=128 obj#=289939 tim=1634698487880397
    WAIT #140307048128352: nam='direct path read' ela= 10407 file number=103 first dba=699904 block cnt=128 obj#=289939 tim=1634698487892083
    WAIT #140307048128352: nam='direct path read' ela= 772 file number=101 first dba=692737 block cnt=127 obj#=289939 tim=1634698487893573
    WAIT #140307048128352: nam='direct path read' ela= 6903 file number=98 first dba=690432 block cnt=128 obj#=289939 tim=1634698487901142
    WAIT #140307048128352: nam='direct path read' ela= 5351 file number=80 first dba=648321 block cnt=127 obj#=289939 tim=1634698487907174
    WAIT #140307048128352: nam='direct path read' ela= 3275 file number=79 first dba=645632 block cnt=128 obj#=289939 tim=1634698487911170
    WAIT #140307048128352: nam='direct path read' ela= 6376 file number=74 first dba=620417 block cnt=127 obj#=289939 tim=1634698487918287
    WAIT #140307048128352: nam='direct path read' ela= 1094 file number=73 first dba=619264 block cnt=128 obj#=289939 tim=1634698487920144
    WAIT #140307048128352: nam='direct path read' ela= 7396 file number=69 first dba=751873 block cnt=127 obj#=289939 tim=1634698487928237
    WAIT #140307048128352: nam='direct path read' ela= 4123 file number=68 first dba=752640 block cnt=128 obj#=289939 tim=1634698487933128
    WAIT #140307048128352: nam='direct path read' ela= 6368 file number=20 first dba=2469121 block cnt=127 obj#=289939 tim=1634698487940150
    WAIT #140307048128352: nam='direct path read' ela= 4715 file number=10 first dba=1666048 block cnt=128 obj#=289939 tim=1634698487945645
    WAIT #140307048128352: nam='direct path read' ela= 5093 file number=105 first dba=1896193 block cnt=127 obj#=289939 tim=1634698487951385
    WAIT #140307048128352: nam='direct path read' ela= 7545 file number=103 first dba=701568 block cnt=128 obj#=289939 tim=1634698487959672
    WAIT #140307048128352: nam='direct path read' ela= 3648 file number=101 first dba=695937 block cnt=127 obj#=289939 tim=1634698487964059
    WAIT #140307048128352: nam='direct path read' ela= 4575 file number=98 first dba=692352 block cnt=128 obj#=289939 tim=1634698487969245
    WAIT #140307048128352: nam='direct path read' ela= 6237 file number=80 first dba=650753 block cnt=127 obj#=289939 tim=1634698487976187
    WAIT #140307048128352: nam='direct path read' ela= 4244 file number=79 first dba=647552 block cnt=128 obj#=289939 tim=1634698487981165
    WAIT #140307048128352: nam='direct path read' ela= 7558 file number=74 first dba=622209 block cnt=127 obj#=289939 tim=1634698487989509
    WAIT #140307048128352: nam='direct path read' ela= 6728 file number=73 first dba=620544 block cnt=128 obj#=289939 tim=1634698487996993
    WAIT #140307048128352: nam='direct path read' ela= 1627 file number=69 first dba=752001 block cnt=127 obj#=289939 tim=1634698487999235
    WAIT #140307048128352: nam='direct path read' ela= 5020 file number=68 first dba=752768 block cnt=128 obj#=289939 tim=1634698488004972
    WAIT #140307048128352: nam='direct path read' ela= 4299 file number=20 first dba=2469505 block cnt=127 obj#=289939 tim=1634698488009895
    WAIT #140307048128352: nam='direct path read' ela= 13577 file number=105 first dba=1896321 block cnt=127 obj#=289939 tim=1634698488024766
    WAIT #140307048128352: nam='direct path read' ela= 1301 file number=103 first dba=703744 block cnt=128 obj#=289939 tim=1634698488026779
    WAIT #140307048128352: nam='direct path read' ela= 14033 file number=101 first dba=697345 block cnt=127 obj#=289939 tim=1634698488041502

    第二次:

    WAIT #140307048128352: nam='direct path read' ela= 867 file number=79 first dba=741632 block cnt=128 obj#=289939 tim=1634698533969008
    WAIT #140307048128352: nam='direct path read' ela= 808 file number=74 first dba=723841 block cnt=127 obj#=289939 tim=1634698533970297
    WAIT #140307048128352: nam='direct path read' ela= 920 file number=73 first dba=722688 block cnt=128 obj#=289939 tim=1634698533971630
    WAIT #140307048128352: nam='direct path read' ela= 2063 file number=69 first dba=758529 block cnt=127 obj#=289939 tim=1634698533973943
    WAIT #140307048128352: nam='direct path read' ela= 1457 file number=68 first dba=759296 block cnt=128 obj#=289939 tim=1634698533975863
    WAIT #140307048128352: nam='direct path read' ela= 1158 file number=20 first dba=2476673 block cnt=127 obj#=289939 tim=1634698533977809
    WAIT #140307048128352: nam='direct path read' ela= 844 file number=10 first dba=1764608 block cnt=128 obj#=289939 tim=1634698533979110
    WAIT #140307048128352: nam='direct path read' ela= 888 file number=105 first dba=1902849 block cnt=127 obj#=289939 tim=1634698533980419
    WAIT #140307048128352: nam='direct path read' ela= 842 file number=103 first dba=815488 block cnt=128 obj#=289939 tim=1634698533981759
    WAIT #140307048128352: nam='direct path read' ela= 769 file number=101 first dba=808961 block cnt=127 obj#=289939 tim=1634698533983064
    WAIT #140307048128352: nam='direct path read' ela= 784 file number=98 first dba=806144 block cnt=128 obj#=289939 tim=1634698533984380
    WAIT #140307048128352: nam='direct path read' ela= 831 file number=80 first dba=745089 block cnt=127 obj#=289939 tim=1634698533985676
    WAIT #140307048128352: nam='direct path read' ela= 937 file number=79 first dba=742272 block cnt=128 obj#=289939 tim=1634698533987047
    WAIT #140307048128352: nam='direct path read' ela= 548 file number=74 first dba=727041 block cnt=127 obj#=289939 tim=1634698533988282
    WAIT #140307048128352: nam='direct path read' ela= 858 file number=73 first dba=723072 block cnt=128 obj#=289939 tim=1634698533989604
    WAIT #140307048128352: nam='direct path read' ela= 788 file number=69 first dba=758657 block cnt=127 obj#=289939 tim=1634698533990864
    WAIT #140307048128352: nam='direct path read' ela= 825 file number=68 first dba=759424 block cnt=128 obj#=289939 tim=1634698533992169
    WAIT #140307048128352: nam='direct path read' ela= 795 file number=20 first dba=2476801 block cnt=127 obj#=289939 tim=1634698533993422
    WAIT #140307048128352: nam='direct path read' ela= 844 file number=10 first dba=1766144 block cnt=128 obj#=289939 tim=1634698533994725
    WAIT #140307048128352: nam='direct path read' ela= 859 file number=105 first dba=1902978 block cnt=126 obj#=289939 tim=1634698533995997
    WAIT #140307048128352: nam='direct path read' ela= 930 file number=103 first dba=816384 block cnt=128 obj#=289939 tim=1634698533997326
    WAIT #140307048128352: nam='direct path read' ela= 704 file number=101 first dba=810369 block cnt=127 obj#=289939 tim=1634698533998595
    WAIT #140307048128352: nam='direct path read' ela= 887 file number=98 first dba=807296 block cnt=128 obj#=289939 tim=1634698533999864
    WAIT #140307048128352: nam='direct path read' ela= 881 file number=80 first dba=745473 block cnt=127 obj#=289939 tim=1634698534001139
    WAIT #140307048128352: nam='direct path read' ela= 924 file number=79 first dba=742400 block cnt=128 obj#=289939 tim=1634698534002441
    WAIT #140307048128352: nam='direct path read' ela= 791 file number=74 first dba=728449 block cnt=127 obj#=289939 tim=1634698534003725
    WAIT #140307048128352: nam='direct path read' ela= 868 file number=73 first dba=726912 block cnt=128 obj#=289939 tim=1634698534005008
    WAIT #140307048128352: nam='direct path read' ela= 885 file number=69 first dba=758785 block cnt=127 obj#=289939 tim=1634698534006283
    WAIT #140307048128352: nam='direct path read' ela= 929 file number=68 first dba=759552 block cnt=128 obj#=289939 tim=1634698534007595
    WAIT #140307048128352: nam='direct path read' ela= 809 file number=20 first dba=2476929 block cnt=127 obj#=289939 tim=1634698534008864
    WAIT #140307048128352: nam='direct path read' ela= 897 file number=10 first dba=1767680 block cnt=128 obj#=289939 tim=1634698534010189
    WAIT #140307048128352: nam='direct path read' ela= 814 file number=105 first dba=1903105 block cnt=127 obj#=289939 tim=1634698534011436
    WAIT #140307048128352: nam='direct path read' ela= 888 file number=103 first dba=817536 block cnt=128 obj#=289939 tim=1634698534012736
    WAIT #140307048128352: nam='direct path read' ela= 839 file number=101 first dba=811137 block cnt=127 obj#=289939 tim=1634698534014017
    WAIT #140307048128352: nam='direct path read' ela= 885 file number=98 first dba=810368 block cnt=128 obj#=289939 tim=1634698534015305
    WAIT #140307048128352: nam='direct path read' ela= 847 file number=80 first dba=745857 block cnt=127 obj#=289939 tim=1634698534016592
    WAIT #140307048128352: nam='direct path read' ela= 855 file number=79 first dba=742784 block cnt=128 obj#=289939 tim=1634698534017901
    WAIT #140307048128352: nam='direct path read' ela= 874 file number=74 first dba=728577 block cnt=127 obj#=289939 tim=1634698534019176
    WAIT #140307048128352: nam='direct path read' ela= 863 file number=73 first dba=729088 block cnt=128 obj#=289939 tim=1634698534020448
    WAIT #140307048128352: nam='direct path read' ela= 842 file number=69 first dba=758913 block cnt=127 obj#=289939 tim=1634698534021739
    WAIT #140307048128352: nam='direct path read' ela= 862 file number=68 first dba=759680 block cnt=128 obj#=289939 tim=1634698534023025
    WAIT #140307048128352: nam='direct path read' ela= 935 file number=20 first dba=2477057 block cnt=127 obj#=289939 tim=1634698534024345
    WAIT #140307048128352: nam='direct path read' ela= 818 file number=10 first dba=1770368 block cnt=128 obj#=289939 tim=1634698534025612
    WAIT #140307048128352: nam='direct path read' ela= 866 file number=105 first dba=1903233 block cnt=127 obj#=289939 tim=1634698534026880
    WAIT #140307048128352: nam='direct path read' ela= 902 file number=103 first dba=821760 block cnt=128 obj#=289939 tim=1634698534028186

    可以看出,每次”direct path read“中cnt基本都在128,但是每次的ela(单位:微秒)里边第二次明显比第一次要更少。

    那么新的问题来了,为啥?这物理读已经不经过内存做缓存了,每次cnt还差不多为啥速度会这么大差别??

    其实这个影响因素已经不再Oracle数据库层面了,去和存储了解了下。

    这个数据库的存储是有用了SSD盘做了缓存盘,实际上是存储层面的缓存了。

    对于Oracle来说它还是物理读,但由于短时间内在存储层面这些数据被缓存到SSD缓存盘上,固态盘显然更快,因此虽然对Oracle来说还是物理读,但是显然速度有明显提升。

    至此。

  • 相关阅读:
    PHP和Redis实现在高并发下的抢购及秒杀功能示例详解
    quartz问题记录-missed their scheduled fire-time
    java(MyEclipse)创建webservice和测试webservice
    Redis wind7 安装
    spring boot新建项目报错总结
    spring boot新建项目启动报:Unregistering JMX-exposed beans on shutdown
    oracle安装过程和创建本地数据库
    正则表达式记录
    java continue与break区别
    Linux查看日志方法总结(1)
  • 原文地址:https://www.cnblogs.com/PiscesCanon/p/15432396.html
Copyright © 2020-2023  润新知