[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
--//信息也与跟踪转储一致。