[20210315]理解db file parallel read等待事件4.txt

[20210315]理解db file parallel read等待事件4.txt --//上午的测试，自己有点奇怪的是前面看到的是 WAIT #140047000530088: nam='db file parallel read' ela= 212 files=1 blocks=39 requests=39 obj#=90881 tim=1615770668231443 --//后面变成了： WAIT #140047000530088: nam='db file scattered read' ela= 111 file#=4 block#=773 blocks=39 obj#=90881 tim=1615770668233113 --//开始不理解,后面想一下应该后面出现的db file scattered read，扫描的块是连续的，才会出现这样的情况。 1.环境 SCOTT@book> @ ver1 PORT_STRING                    VERSION        BANNER ------------------------------ -------------- -------------------------------------------------------------------------------- x86_64/Linux 2.4.xx            11.2.0.4.0     Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production SCOTT@book> show parameter db_file_multiblock_read_count NAME                          TYPE    VALUE ----------------------------- ------- ------- db_file_multiblock_read_count integer 128 create table t pctfree 99 as select level id, rpad('ABC', 3500, 'X') vc from dual connect by level <= 500; create index i_t_id on t(id) ; exec dbms_stats.gather_table_stats(null, 'T', cascade=>true); 2.测试： alter system flush buffer_cache ; SCOTT@book> @ 10046on 12 Session altered. SCOTT@book> select /*+ index(t) */ max (substr(vc,1,2)) from  t where id between 1 and 200; MAX ---- AB SCOTT@book> @ 10046off Session altered. ===================== PARSING IN CURSOR #140047000530088 len=78 dep=0 uid=83 oct=3 lid=83 tim=1615770668230603 hv=1658167056 ad='7bf671f0' sqlid='28mgrb1jdb7sh' select /*+ index(t) */ max (substr(vc,1,2)) from  t where id between 1 and 200 END OF STMT PARSE #140047000530088:c=2000,e=1812,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=714684053,tim=1615770668230597 EXEC #140047000530088:c=0,e=48,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=714684053,tim=1615770668230764 WAIT #140047000530088: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1615770668230831 WAIT #140047000530088: nam='db file sequential read' ela= 12 file#=4 block#=3499 blocks=1 obj#=90882 tim=1615770668230924 WAIT #140047000530088: nam='db file sequential read' ela= 9 file#=4 block#=3500 blocks=1 obj#=90882 tim=1615770668230986 WAIT #140047000530088: nam='db file parallel read' ela= 212 files=1 blocks=39 requests=39 obj#=90881 tim=1615770668231443 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ WAIT #140047000530088: nam='db file sequential read' ela= 11 file#=4 block#=555 blocks=1 obj#=90881 tim=1615770668231562 WAIT #140047000530088: nam='db file parallel read' ela= 234 files=1 blocks=39 requests=39 obj#=90881 tim=1615770668231999 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ WAIT #140047000530088: nam='db file sequential read' ela= 11 file#=4 block#=717 blocks=1 obj#=90881 tim=1615770668232202 WAIT #140047000530088: nam='db file parallel read' ela= 208 files=1 blocks=39 requests=39 obj#=90881 tim=1615770668232613 ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ WAIT #140047000530088: nam='db file sequential read' ela= 10 file#=4 block#=760 blocks=1 obj#=90881 tim=1615770668232803 WAIT #140047000530088: nam='db file scattered read' ela= 111 file#=4 block#=773 blocks=39 obj#=90881 tim=1615770668233113 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ WAIT #140047000530088: nam='db file sequential read' ela= 11 file#=4 block#=772 blocks=1 obj#=90881 tim=1615770668233402 WAIT #140047000530088: nam='db file scattered read' ela= 97 file#=4 block#=813 blocks=39 obj#=90881 tim=1615770668233694 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ WAIT #140047000530088: nam='db file sequential read' ela= 10 file#=4 block#=812 blocks=1 obj#=90881 tim=1615770668233992 FETCH #140047000530088:c=2999,e=3244,p=202,cr=202,cu=0,mis=0,r=1,dep=0,og=1,plh=714684053,tim=1615770668234126 STAT #140047000530088 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=202 pr=202 pw=0 time=3250 us)' STAT #140047000530088 id=2 cnt=200 pid=1 pos=1 obj=90881 op='TABLE ACCESS BY INDEX ROWID T (cr=202 pr=202 pw=0 time=49475 us cost=203 size=701000 card=200)' STAT #140047000530088 id=3 cnt=200 pid=2 pos=1 obj=90882 op='INDEX RANGE SCAN I_T_ID (cr=2 pr=2 pw=0 time=227 us cost=2 size=0 card=200)' WAIT #140047000530088: nam='SQL*Net message from client' ela= 241 driver id=1650815232 #bytes=1 p3=0 obj#=90881 tim=1615770668234568 FETCH #140047000530088:c=0,e=2,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=714684053,tim=1615770668234610 WAIT #140047000530088: nam='SQL*Net message to client' ela= 1 driver id=1650815232 #bytes=1 p3=0 obj#=90881 tim=1615770668234640 *** 2021-03-15 09:11:11.508 WAIT #140047000530088: nam='SQL*Net message from client' ela= 3274193 driver id=1650815232 #bytes=1 p3=0 obj#=90881 tim=1615770671508880 CLOSE #140047000530088:c=0,e=10,dep=0,type=0,tim=1615770671508991 ===================== --//从跟踪文件可以发现出现3次db file parallel read,请求的次数39. --//很奇怪的是你后面还看到nam='db file scattered read' ela= 111 file#=4 block#=773 blocks=39 obj#=90881. 3.可以验证看看： SCOTT@book> select * from dba_extents where segment_name='T'; OWNER  SEGMENT_NAME SEGMENT_TYPE TABLESPACE_NAME                 EXTENT_ID    FILE_ID   BLOCK_ID      BYTES     BLOCKS RELATIVE_FNO ------ ------------ ------------ ------------------------------ ---------- ---------- ---------- ---------- ---------- ------------ SCOTT  T            TABLE        USERS                                   0          4        552      65536          8            4 SCOTT  T            TABLE        USERS                                   1          4        560      65536          8            4 SCOTT  T            TABLE        USERS                                   2          4        672      65536          8            4 SCOTT  T            TABLE        USERS                                   3          4        688      65536          8            4 SCOTT  T            TABLE        USERS                                   4          4        696      65536          8            4 SCOTT  T            TABLE        USERS                                   5          4        712      65536          8            4 SCOTT  T            TABLE        USERS                                   6          4        720      65536          8            4 SCOTT  T            TABLE        USERS                                   7          4        728      65536          8            4 SCOTT  T            TABLE        USERS                                   8          4        736      65536          8            4 SCOTT  T            TABLE        USERS                                   9          4        744      65536          8            4 SCOTT  T            TABLE        USERS                                  10          4        752      65536          8            4 SCOTT  T            TABLE        USERS                                  11          4        760      65536          8            4 SCOTT  T            TABLE        USERS                                  12          4       3464      65536          8            4 SCOTT  T            TABLE        USERS                                  13          4       3472      65536          8            4 SCOTT  T            TABLE        USERS                                  14          4       3480      65536          8            4 SCOTT  T            TABLE        USERS                                  15          4       3488      65536          8            4 SCOTT  T            TABLE        USERS                                  16          4        768    1048576        128            4 --//768+128-1 = 895 --//file#=4 block#=773 blocks=39 obj#=90881 --//file#=4 block#=813 blocks=39 obj#=90881 --//也就是这段区域分配block是连续的，也就是当扫描区域连续时，等待事件变成了db file scattered read。 --//视乎还是按照读39块的方式，你还可以注意一个细节。 WAIT #140047000530088: nam='db file scattered read' ela= 111 file#=4 block#=773 blocks=39 obj#=90881 tim=1615770668233113 ++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++ WAIT #140047000530088: nam='db file sequential read' ela= 11 file#=4 block#=772 blocks=1 obj#=90881 tim=1615770668233402 --//后面出现的db file sequential read等待事件block#=772，而前面的是db file scattered read是block#=773。 SCOTT  T            TABLE        USERS                                  17          4        896    1048576        128            4 SCOTT  T            TABLE        USERS                                  18          4       1024    1048576        128            4 SCOTT  T            TABLE        USERS                                  19          4       1152    1048576        128            4 20 rows selected. --//从这里也可以得到一个结论，即使是INDEX RANGE SCAN回表，也有可能出现db file scattered read的情况。 4.使用strace跟踪看看。 SCOTT@book> @ spid        SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50 ---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------        253         29 55745                    DEDICATED 55746       18         10 alter system kill session '253,29' immediate; SCOTT@book> alter system flush buffer_cache ; System altered. SCOTT@book> select /*+ index(t) */ max (substr(vc,1,2)) from  t where id between 1 and 200; MAX( ---- AB         $ strace -f -p 55746 -e pread 2>&1 | tee | grep -v "8192$" Process 55746 attached - interrupt to quit pread(258, "\6\242\0\0\5\3\0\1r\\|\27\3\0\2\4\1\275\0\0\1\0\0\0\rc\1\0O\\|\27"..., 319488, 6332416) = 319488 pread(258, "\6\242\0\0-\3\0\1r\\|\27\3\0\2\4\1\275\0\0\1\0\0\0\rc\1\0O\\|\27"..., 319488, 6660096) = 319488 --//注意看读的数量不是8192.是319488,319488/8192 = 39. --//6332416/8192 = 773 --//6660096/8192 = 813 $ strace -f -p 55746 -e pread 2>&1 | tee | grep -A1 "319488$" pread(258, "\6\242\0\0\5\3\0\1r\\|\27\3\0\2\4\1\275\0\0\1\0\0\0\rc\1\0O\\|\27"..., 319488, 6332416) = 319488 pread(258, "\6\242\0\0\4\3\0\1r\\|\27\3\0\2\4\1\275\0\0\1\0\0\0\rc\1\0O\\|\27"..., 8192, 6324224) = 8192 pread(258, "\6\242\0\0-\3\0\1r\\|\27\3\0\2\4\1\275\0\0\1\0\0\0\rc\1\0O\\|\27"..., 319488, 6660096) = 319488 pread(258, "\6\242\0\0,\3\0\1r\\|\27\3\0\2\4\1\275\0\0\1\0\0\0\rc\1\0O\\|\27"..., 8192, 6651904) = 8192 --//6324224/8192 = 772 --//6651904/8192 = 812 --//信息也与跟踪转储一致。