[20231023]为什么刷新缓存后输出记录顺序发生变化6.txt

[20231023]为什么刷新缓存后输出记录顺序发生变化6.txt

--//前几天做了单表刷新缓存后输出记录顺序发生变化的情况,测试2个表的情况时遇到一个奇怪的现象。
--//我前面的测试18c,如果使用10046跟踪看不到我遇到的情况,我想使用strace跟踪,发现该机器配置使用asm,strace跟踪无法看到一
--//些细节问题。换一台19c的文件型数据库测试看看。

1.环境:
SYS@192.168.100.235:1521/orcl> @ ver1
SYS@192.168.100.235:1521/orcl> @ pr
==============================
PORT_STRING                   : x86_64/Linux 2.4.xx
VERSION                       : 19.0.0.0.0
BANNER                        : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
BANNER_FULL                   : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
Version 19.3.0.0.0
BANNER_LEGACY                 : Oracle Database 19c Enterprise Edition Release 19.0.0.0.0 - Production
CON_ID                        : 0
PL/SQL procedure successfully completed.

2.建立测试例子:
create table t1  tablespace users pctfree 99 as select level id, lpad(level, 3500, 'T1') vc from dual connect by level <= 500 order by dbms_random.random;
create table t2  tablespace users pctfree 99 as select level id, lpad(level, 3500, 'T2') vc from dual connect by level <= 500 order by dbms_random.random;
--//建立的表T1,T2非常特殊1块1条记录,这样便于后面的分析。

create index i_t1_id on t1(id) ;
create index i_t2_id on t2(id) ;

exec dbms_stats.gather_table_stats(null, 'T1', cascade=>true);
exec dbms_stats.gather_table_stats(null, 'T2', cascade=>true);

3.测试:

--//由于测试要多次刷新数据缓存,也许会对生产系统有影响,我想测试移动到dg上进行.但是我发现我还是测试不出来,在备库好像刷新
--//数据缓存无效.

SYS@192.168.100.237:1521/orcldg> alter system flush buffer_cache;
System altered.

SYS@192.168.100.237:1521/orcldg> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
         3 1T1T3      2T2T3
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
         9 1T1T9      2T2T9
        10 1T110      2T210
10 rows selected.
--//奇怪dg下无法按照顺序输出的,另外写一篇blog说明情况.

--//没有办法先在主库测试看看.
SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
        10 1T110      2T210
         9 1T1T9      2T2T9
         3 1T1T3      2T2T3
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
10 rows selected.
--//这次又与单表扫描不同id=10,9出现在前面.id=3,4出现在后面,再现我在18c上的测试.
--//在主库上测试能够再现我遇到的问题.

SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

SYS@192.168.100.235:1521/orcl> @ 10046on 12
Session altered.

SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
         3 1T1T3      2T2T3
        10 1T110      2T210
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
         9 1T1T9      2T2T9
10 rows selected.
--//一旦开启10046跟踪出现的顺序就是仅仅id=10记录在前.

SYS@192.168.100.235:1521/orcl> @ 10046off
Session altered.

SYS@192.168.100.235:1521/orcl> @ oid 245902,245903,245900,245901
owner object_name object_type SUBOBJECT_NAME CREATED             LAST_DDL_TIME       status    DATA_OBJECT_ID  OBJECT_ID
----- ----------- ----------- -------------- ------------------- ------------------- --------- -------------- ----------
SYS   I_T1_ID     INDEX                      2023-10-23 08:33:08 2023-10-23 08:33:08 VALID             245902     245902
SYS   I_T2_ID     INDEX                      2023-10-23 08:33:16 2023-10-23 08:33:16 VALID             245903     245903
SYS   T1          TABLE                      2023-10-23 08:33:00 2023-10-23 08:33:08 VALID             245900     245900
SYS   T2          TABLE                      2023-10-23 08:33:04 2023-10-23 08:33:16 VALID             245901     245901
4 rows selected.

SYS@192.168.100.235:1521/orcl> select /*+ index(t1) */ id,substr(vc,3498,3),rowid,dbms_rowid.ROWID_BLOCK_NUMBER(rowid) from  t1 where id between 1 and 10;
        ID SUBSTR ROWID              DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)
---------- ------ ------------------ ------------------------------------
         1 1T1    AAA8CMAAHAAAErrAAA                                19179
         2 1T2    AAA8CMAAHAAAEpSAAA                                19026
         3 1T3    AAA8CMAAHAAAEqKAAA                                19082
         4 1T4    AAA8CMAAHAAAEoqAAA                                18986
         5 1T5    AAA8CMAAHAAAEs6AAA                                19258
         6 1T6    AAA8CMAAHAAAEobAAA                                18971
         7 1T7    AAA8CMAAHAAAEo/AAA                                19007
         8 1T8    AAA8CMAAHAAAEsPAAA                                19215
         9 1T9    AAA8CMAAHAAAErdAAA                                19165
        10 110    AAA8CMAAHAAAEtYAAA                                19288
10 rows selected.

SYS@192.168.100.235:1521/orcl> select /*+ index(t2) */ id,substr(vc,3498,3),rowid,dbms_rowid.ROWID_BLOCK_NUMBER(rowid) from  t2 where id between 1 and 10;
        ID SUBSTR ROWID              DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID)
---------- ------ ------------------ ------------------------------------
         1 2T1    AAA8CNAAHAAAEnkAAA                                18916
         2 2T2    AAA8CNAAHAAAE4DAAA                                19971
         3 2T3    AAA8CNAAHAAAEyGAAA                                19590
         4 2T4    AAA8CNAAHAAAEyRAAA                                19601
         5 2T5    AAA8CNAAHAAAEwVAAA                                19477
         6 2T6    AAA8CNAAHAAAEztAAA                                19693
         7 2T7    AAA8CNAAHAAAE3nAAA                                19943
         8 2T8    AAA8CNAAHAAAE2WAAA                                19862
         9 2T9    AAA8CNAAHAAAE2mAAA                                19878
        10 210    AAA8CNAAHAAAEwJAAA                                19465

10 rows selected.

--//跟踪看到的情况如下:
$ egrep "FETCH|db file" /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_80563.trc
WAIT #140140023886360: nam='db file sequential read' ela= 22 file#=1 block#=321561 blocks=1 obj#=245902 tim=58766772230352  --//I_T1_ID 的root
WAIT #140140023886360: nam='db file sequential read' ela= 12 file#=1 block#=321562 blocks=1 obj#=245902 tim=58766772230436  --//I_T1_ID 的leaf
WAIT #140140023886360: nam='db file sequential read' ela= 16 file#=7 block#=19179 blocks=1 obj#=245900 tim=58766772230496   --//T1 id=1
WAIT #140140023886360: nam='db file sequential read' ela= 12 file#=1 block#=321569 blocks=1 obj#=245903 tim=58766772230563  --//I_T2_ID 的root
WAIT #140140023886360: nam='db file sequential read' ela= 12 file#=1 block#=321570 blocks=1 obj#=245903 tim=58766772230612  --//I_T2_ID 的leaf
WAIT #140140023886360: nam='db file sequential read' ela= 13 file#=7 block#=18916 blocks=1 obj#=245901 tim=58766772230665   --//T2 id=1
FETCH #140140023886360:c=451,e=451,p=6,cr=6,cu=0,mis=0,r=1,dep=0,og=1,plh=51221132,tim=58766772230726
WAIT #140140023886360: nam='db file sequential read' ela= 32 file#=7 block#=19026 blocks=1 obj#=245900 tim=58766772231503   --//T1 id=2
WAIT #140140023886360: nam='db file sequential read' ela= 12 file#=7 block#=19971 blocks=1 obj#=245901 tim=58766772231583   --//T2 id=2
WAIT #140140023886360: nam='db file sequential read' ela= 12 file#=7 block#=19082 blocks=1 obj#=245900 tim=58766772231688   --//T1 id=3
WAIT #140140023886360: nam='db file sequential read' ela= 13 file#=7 block#=19590 blocks=1 obj#=245901 tim=58766772231757   --//T2 id=3
WAIT #140140023886360: nam='db file parallel read' ela= 81 files=1 blocks=7 requests=7 obj#=245900 tim=58766772232174       --//T1 读取id=4..10
WAIT #140140023886360: nam='db file sequential read' ela= 12 file#=7 block#=19465 blocks=1 obj#=245901 tim=58766772232260   --//T2 id=10
WAIT #140140023886360: nam='db file sequential read' ela= 14 file#=7 block#=19601 blocks=1 obj#=245901 tim=58766772232374   --//T2 id=4
WAIT #140140023886360: nam='db file sequential read' ela= 11 file#=7 block#=19477 blocks=1 obj#=245901 tim=58766772232460   --//T2 id=5
WAIT #140140023886360: nam='db file sequential read' ela= 11 file#=7 block#=19693 blocks=1 obj#=245901 tim=58766772232543   --//T2 id=6
WAIT #140140023886360: nam='db file sequential read' ela= 12 file#=7 block#=19943 blocks=1 obj#=245901 tim=58766772232626   --//T2 id=7
WAIT #140140023886360: nam='db file sequential read' ela= 10 file#=7 block#=19862 blocks=1 obj#=245901 tim=58766772232701   --//T2 id=8
WAIT #140140023886360: nam='db file sequential read' ela= 9 file#=7 block#=19878 blocks=1 obj#=245901 tim=58766772232775    --//T2 id=9
FETCH #140140023886360:c=975,e=1411,p=18,cr=26,cu=0,mis=0,r=9,dep=0,og=1,plh=51221132,tim=58766772232827

--//执行计划如下:
Plan hash value: 51221132
-------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                             | Name    | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |
-------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                      |         |      1 |        |       |    33 (100)|          |     10 |00:00:00.01 |      32 |
|   1 |  NESTED LOOPS                         |         |      1 |      9 | 63090 |    33   (0)| 00:00:01 |     10 |00:00:00.01 |      32 |
|   2 |   NESTED LOOPS                        |         |      1 |     10 | 63090 |    33   (0)| 00:00:01 |     10 |00:00:00.01 |      22 |
|   3 |    TABLE ACCESS BY INDEX ROWID BATCHED| T1      |      1 |     10 | 35050 |    13   (0)| 00:00:01 |     10 |00:00:00.01 |      13 |
|*  4 |     INDEX RANGE SCAN                  | I_T1_ID |      1 |     10 |       |     2   (0)| 00:00:01 |     10 |00:00:00.01 |       3 |
|*  5 |    INDEX RANGE SCAN                   | I_T2_ID |     10 |      1 |       |     1   (0)| 00:00:01 |     10 |00:00:00.01 |       9 |
|   6 |   TABLE ACCESS BY INDEX ROWID         | T2      |     10 |      1 |  3505 |     2   (0)| 00:00:01 |     10 |00:00:00.01 |      10 |
-------------------------------------------------------------------------------------------------------------------------------------------

4.其它测试补充:
--//我打开statistics_level = all,也会看不到我前面观察到的情况.
SYS@192.168.100.235:1521/orcl> @ sl all
alter session set statistics_level = all;
Session altered.

SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
         3 1T1T3      2T2T3
        10 1T110      2T210
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
         9 1T1T9      2T2T9
10 rows selected.
--//如果采用dbms_monitor.session_trace_enable或者dbms_system.set_sql_trace_in_session跟踪也是一样.不再贴出.
--//下面尝试strace跟踪看看。

5.使用strace跟踪看看:
SYS@192.168.100.235:1521/orcl> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
        34      44670 10706                    DEDICATED 90782       48     101616 alter system kill session '34,44670' immediate;
--//记下spid =90782.

SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
        10 1T110      2T210
         9 1T1T9      2T2T9
         3 1T1T3      2T2T3
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
10 rows selected.
--//再次出现id=10,9在前面的情况.

# strace -fp 90782 -e pread64 -o /tmp/aa.txt
strace: Process 90782 attached
^Cstrace: Process 90782 detached

# cat /tmp/aa.txt
90782 pread64(256, "\6\242\0\0\31\350D\0Q\5\257#\v\0\1\4^\222\0\0\2@F\0\216\300\3\0P\5\257#"..., 8192, 2634227712) = 8192
90782 pread64(256, "\6\242\0\0\32\350D\0Q\5\257#\v\0\2\4'R\0\0\2\0\0\0\216\300\3\0P\5\257#"..., 8192, 2634235904) = 8192
90782 pread64(257, "\6\242\0\0\353J\300\1!\375\256#\v\0\2\4\316\336\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 157114368) = 8192
90782 pread64(256, "\6\242\0\0!\350D\0\222\16\257#\v\0\1\4_\252\0\0\2@F\0\217\300\3\0\221\16\257#"..., 8192, 2634293248) = 8192
90782 pread64(256, "\6\242\0\0\"\350D\0\222\16\257#\v\0\2\4\200\351\0\0\2\0\0\0\217\300\3\0\221\16\257#"..., 8192, 2634301440) = 8192
90782 pread64(257, "\6\242\0\0\344I\300\1\216\0\257#\v\0\2\4\230\334\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 154959872) = 8192
90782 pread64(257, "\6\242\0\0RJ\300\1\32\375\256#\v\0\2\4\366\335\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155860992) = 8192
90782 pread64(257, "\6\242\0\0\3N\300\1\255\0\257#\v\0\2\4\246\336\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 163602432) = 8192
90782 pread64(257, "\6\242\0\0\33J\300\1\32\375\256#\v\0\2\4\272\331\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155410432) = 8192
90782 pread64(257, "\6\242\0\0*J\300\1\32\375\256#\v\0\2\4\211\333\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155533312) = 8192
90782 pread64(257, "\6\242\0\0?J\300\1\32\375\256#\v\0\2\4\221\330\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155705344) = 8192
90782 pread64(257, "\6\242\0\0\212J\300\1!\375\256#\v\0\2\4\250\334\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 156319744) = 8192
90782 pread64(257, "\6\242\0\0\335J\300\1!\375\256#\v\0\2\4\360\326\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 156999680) = 8192
90782 pread64(257, "\6\242\0\0\17K\300\1#\375\256#\v\0\2\4\240\327\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 157409280) = 8192
90782 pread64(257, "\6\242\0\0:K\300\1#\375\256#\v\0\2\4\232\332\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 157761536) = 8192
90782 pread64(257, "\6\242\0\0XK\300\1$\375\256#\v\0\2\4\221\337\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 158007296) = 8192
90782 pread64(257, "\6\242\0\0\tL\300\1\235\0\257#\v\0\2\4\311\334\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 159457280) = 8192
90782 pread64(257, "\6\242\0\0\25L\300\1\235\0\257#\v\0\2\4\275\330\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 159555584) = 8192
90782 pread64(257, "\6\242\0\0\206L\300\1\243\0\257#\v\0\2\4\244\337\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 160481280) = 8192
90782 pread64(257, "\6\242\0\0\221L\300\1\244\0\257#\v\0\2\4\262\330\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 160571392) = 8192
90782 pread64(257, "\6\242\0\0\355L\300\1\244\0\257#\v\0\2\4\315\332\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 161325056) = 8192
90782 pread64(257, "\6\242\0\0\226M\300\1\255\0\257#\v\0\2\4\271\324\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 162709504) = 8192
90782 pread64(257, "\6\242\0\0\246M\300\1\255\0\257#\v\0\2\4\212\325\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 162840576) = 8192
90782 pread64(257, "\6\242\0\0\347M\300\1\255\0\257#\v\0\2\4\310\333\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 163373056) = 8192

--//抽取第5个字段就是偏移量,删除)字符,然后除以8192换算从成块号。
#  awk '{print $5}' /tmp/aa.txt | sed 's/)$//' | xargs -IQ bash -c "echo Q/8192| bc"
321561   --//I_T1_ID 的root,注我的索引建立在system表空间上了,可以发现前面的文件句柄不同。
321562   --//I_T1_ID 的leaf
19179    --//T1 id=1
321569   --//I_T2_ID 的root
321570   --//I_T2_ID 的leaf
18916    --//T2 id=1
19026    --//T1 id=2
19971    --//T2 id=2
~~~~~~~~~~~~~~~~~~~~~~
18971  --//T1 id=6
18986    --//T1 id=4
19007    --//T1 id=7
19082    --//T1 id=3
19165    --//T1 id=9
19215    --//T1 id=8
19258    --//T1 id=5
19288    --//T1 id=10
--//以上8块是db file parallel read ,id=3..10,你也可以发现实际上db file parallel read读取的块是离散的,但是按照从小到大顺序读取.
19465    --//T2 id=10
19477    --//T2 id=5
19590    --//T2 id=3
19601    --//T2 id=4
19693    --//T2 id=6
19862    --//T2 id=8
19878    --//T2 id=9
19943    --//T2 id=7
--//以上7块还是是db file parallel read,我为什么这么猜测,有两个原因.
--//补充:这里巧合了T2 id=10的数据块正好是这些块中最小的数据块.实际上T2 id=10的是db file sequential read.看我后面的补充测试.
--//1.读取block顺序按照从小到大排列
--//2.并没有按照以前看到的nested loop 的输出顺序.
--//这样如果验证测试出现2次db file parallel read,就能证明我的判断是否正确.

--//从跟踪文件抽取访问的块号。
# egrep "db file" /u01/app/oracle/diag/rdbms/orcl/orcl/trace/orcl_ora_80563.trc | awk '{print $10}' | cut -d"=" -f2
321561   --//I_T1_ID 的root
321562   --//I_T1_ID 的leaf
19179    --//T1 id=1
321569   --//I_T2_ID 的root
321570   --//I_T2_ID 的leaf
18916    --//T2 id=1
19026    --//T1 id=2
19971    --//T2 id=2
19082    --//T1 id=3
19590    --//T2 id=3
7        --//T1 读取id=4..10,db file parallel read 这里仅仅看到读取7块,10046跟踪不知道具体那些块.
19465    --//T2 id=10
19601    --//T2 id=4
19477    --//T2 id=5
19693    --//T2 id=6
19943    --//T2 id=7
19862    --//T2 id=8
19878    --//T2 id=9
--//开启10046看到的情况.

6.验证过程:
--//退出重新登录:
--//session 1:
SYS@192.168.100.235:1521/orcl> @ spid
       SID    SERIAL# PROCESS                  SERVER    SPID       PID  P_SERIAL# C50
---------- ---------- ------------------------ --------- ------ ------- ---------- --------------------------------------------------
       864      10584 11060                    DEDICATED 105105      51      72774 alter system kill session '864,10584' immediate;

--//在另外会话执行,session 2:
SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=864 and event ='db file parallel read';
no rows selected

--//session 1:
SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
        10 1T110      2T210
         9 1T1T9      2T2T9
         3 1T1T3      2T2T3
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
10 rows selected.


SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=864 and event ='db file parallel read';
       SID       SEQ#     EVENT# EVENT                  P1TEXT             P1 P2TEXT          P2 P3TEXT      P3  WAIT_TIME WAIT_TIME_MICRO TIME_SINCE_LAST_WAIT_MICRO     CON_ID
---------- ---------- ---------- ---------------------- ---------- ---------- ------- ---------- ---------- --- ---------- --------------- -------------------------- ----------
       864          2        184 db file parallel read  files               1 blocks           7 requests     7          0             115                        255          0
       864          5        184 db file parallel read  files               1 blocks           8 requests     8          0             191                        366          0
--//可以发现出现2次db file parallel read.
--//唯一判断错误的地方就是一次requests=7,另外一次requests=8,为什么?

--//测试statistics_level = all  与 statistics_level = TYPICAL的情况:
--//session 2:
SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

--//session 1:
SYS@192.168.100.235:1521/orcl> @ sl all
alter session set statistics_level = all;
Session altered.

SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
         3 1T1T3      2T2T3
        10 1T110      2T210
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
         9 1T1T9      2T2T9
10 rows selected.
--//打开statistics_level = all看不到我遇到的情况。

--//session 2:
SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=864 and event ='db file parallel read';
       SID       SEQ#     EVENT# EVENT                 P1TEXT             P1 P2TEXT         P2 P3TEXT      P3  WAIT_TIME WAIT_TIME_MICRO TIME_SINCE_LAST_WAIT_MICRO     CON_ID
---------- ---------- ---------- --------------------- ---------- ---------- ------ ---------- ---------- --- ---------- --------------- -------------------------- ----------
       864          8        184 db file parallel read files               1 blocks          7 requests     7          0             111                        207          0
--//可以发现出现1次db file parallel read.
--//注意: V$SESSION_WAIT_HISTORY 仅仅保留最后10个等待事件,上面的测试应该不会错过.

--//session 2:
SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

--//session 1:
SYS@192.168.100.235:1521/orcl> @ sl TYPICAL
alter session set statistics_level = TYPICAL;
Session altered.

SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t1 t2) use_nl(t2) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
        ID VC1        VC2
---------- ---------- ----------
         1 1T1T1      2T2T1
         2 1T1T2      2T2T2
        10 1T110      2T210
         9 1T1T9      2T2T9
         3 1T1T3      2T2T3
         4 1T1T4      2T2T4
         5 1T1T5      2T2T5
         6 1T1T6      2T2T6
         7 1T1T7      2T2T7
         8 1T1T8      2T2T8
10 rows selected.

--//session 2:
SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=864 and event ='db file parallel read';
 SID  SEQ#  EVENT# EVENT                 P1TEXT P1 P2TEXT  P2 P3TEXT      P3  WAIT_TIME WAIT_TIME_MICRO TIME_SINCE_LAST_WAIT_MICRO     CON_ID
---- ----- ------- --------------------- ------ -- ------ --- ---------- --- ---------- --------------- -------------------------- ----------
 864     1     184 db file parallel read files   1 blocks   7 requests     7          0             133                        139          0
 864     4     184 db file parallel read files   1 blocks   8 requests     8          0             119                        220          0
--//可以发现出现2次db file parallel read.

7.补充测试:
--//修改提示看看,先访问T2表。
--//sesion 1:
SYS@192.168.100.235:1521/orcl> alter system flush buffer_cache;
System altered.

--//sesion 2:
SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=2866 and event ='db file parallel read';
no rows selected

--//sesion 1:
SYS@192.168.100.235:1521/orcl> SELECT /*+ leading (t2 t1) use_nl(t1) */ t1.id,substr(t1.vc,3496,5) vc1,substr(t2.vc,3496,5) vc2 FROM t1 , t2 WHERE t1.id = t2.id AND t1.id between 1 and 10;
 ID VC1        VC2
--- ---------- ----------
  1 1T1T1      2T2T1
  2 1T1T2      2T2T2
 10 1T110      2T210
  9 1T1T9      2T2T9
  3 1T1T3      2T2T3
  4 1T1T4      2T2T4
  5 1T1T5      2T2T5
  6 1T1T6      2T2T6
  7 1T1T7      2T2T7
  8 1T1T8      2T2T8
10 rows selected.
--//效果一样.

SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=2866 and event ='db file parallel read';
 SID  SEQ#  EVENT# EVENT                 P1TEXT P1 P2TEXT P2 P3TEXT   P3  WAIT_TIME WAIT_TIME_MICRO TIME_SINCE_LAST_WAIT_MICRO     CON_ID
---- ----- ------- --------------------- ------ -- ------ -- -------- -- ---------- --------------- -------------------------- ----------
2866     1     184 db file parallel read files   1 blocks  7 requests  7          9           89661                        359          0
2866     4     184 db file parallel read files   1 blocks  8 requests  8         15          151183                        245          0

# strace -fp 80649 -e pread64 -o /tmp/aa1.txt
strace: Process 80649 attached
^Cstrace: Process 80649 detached

# cat /tmp/aa1.txt
80649 pread64(256, "\6\242\0\0!\350D\0\222\16\257#\v\0\1\4_\252\0\0\2@F\0\217\300\3\0\221\16\257#"..., 8192, 2634293248) = 8192
80649 pread64(256, "\6\242\0\0\"\350D\0\222\16\257#\v\0\2\4\200\351\0\0\2\0\0\0\217\300\3\0\221\16\257#"..., 8192, 2634301440) = 8192
80649 pread64(258, "\6\242\0\0\344I\300\1\216\0\257#\v\0\2\4\230\334\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 154959872) = 8192
80649 pread64(256, "\6\242\0\0\31\350D\0Q\5\257#\v\0\1\4^\222\0\0\2@F\0\216\300\3\0P\5\257#"..., 8192, 2634227712) = 8192
80649 pread64(256, "\6\242\0\0\32\350D\0Q\5\257#\v\0\2\4'R\0\0\2\0\0\0\216\300\3\0P\5\257#"..., 8192, 2634235904) = 8192
80649 pread64(258, "\6\242\0\0\353J\300\1!\375\256#\v\0\2\4\316\336\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 157114368) = 8192
80649 pread64(258, "\6\242\0\0\3N\300\1\255\0\257#\v\0\2\4\246\336\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 163602432) = 8192
80649 pread64(258, "\6\242\0\0RJ\300\1\32\375\256#\v\0\2\4\366\335\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155860992) = 8192
80649 pread64(258, "\6\242\0\0\tL\300\1\235\0\257#\v\0\2\4\311\334\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 159457280) = 8192
80649 pread64(258, "\6\242\0\0\25L\300\1\235\0\257#\v\0\2\4\275\330\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 159555584) = 8192
80649 pread64(258, "\6\242\0\0\206L\300\1\243\0\257#\v\0\2\4\244\337\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 160481280) = 8192
80649 pread64(258, "\6\242\0\0\221L\300\1\244\0\257#\v\0\2\4\262\330\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 160571392) = 8192
80649 pread64(258, "\6\242\0\0\355L\300\1\244\0\257#\v\0\2\4\315\332\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 161325056) = 8192
80649 pread64(258, "\6\242\0\0\226M\300\1\255\0\257#\v\0\2\4\271\324\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 162709504) = 8192
80649 pread64(258, "\6\242\0\0\246M\300\1\255\0\257#\v\0\2\4\212\325\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 162840576) = 8192
80649 pread64(258, "\6\242\0\0\347M\300\1\255\0\257#\v\0\2\4\310\333\0\0\1\0\0\0\215\300\3\0x\0\257#"..., 8192, 163373056) = 8192
80649 pread64(258, "\6\242\0\0XK\300\1$\375\256#\v\0\2\4\221\337\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 158007296) = 8192
80649 pread64(258, "\6\242\0\0\33J\300\1\32\375\256#\v\0\2\4\272\331\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155410432) = 8192
80649 pread64(258, "\6\242\0\0*J\300\1\32\375\256#\v\0\2\4\211\333\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155533312) = 8192
80649 pread64(258, "\6\242\0\0?J\300\1\32\375\256#\v\0\2\4\221\330\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 155705344) = 8192
80649 pread64(258, "\6\242\0\0\212J\300\1!\375\256#\v\0\2\4\250\334\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 156319744) = 8192
80649 pread64(258, "\6\242\0\0\335J\300\1!\375\256#\v\0\2\4\360\326\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 156999680) = 8192
80649 pread64(258, "\6\242\0\0\17K\300\1#\375\256#\v\0\2\4\240\327\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 157409280) = 8192
80649 pread64(258, "\6\242\0\0:K\300\1#\375\256#\v\0\2\4\232\332\0\0\1\0\0\0\214\300\3\0\362\374\256#"..., 8192, 157761536) = 8192

# awk '{print $5}' /tmp/aa1.txt | sed 's/)$//' | xargs -IQ bash -c "echo Q/8192| bc"
321569  --//I_T1_ID 的root,注我的索引建立在system表空间上了,可以发现前面的文件句柄不同。
321570  --//I_T1_ID 的leaf
18916   --//T2 id=1
321561  --//I_T2_ID 的root
321562  --//I_T2_ID 的leaf
19179   --//T1 id=1
19971   --//T2 id=2
19026   --//T1 id=2
~~~~~~~~~~~~~~~~~~~~
19465   --//T2 id=10
19477   --//T2 id=5
19590   --//T2 id=3
19601   --//T2 id=4
19693   --//T2 id=6
19862   --//T2 id=8
19878   --//T2 id=9
19943   --//T2 id=7
~~~~~~~~~~~~~~~~~~
--//以上8块是db file parallel read ,id=3..10,你也可以发现实际上db file parallel read读取的块是离散的,但是按照从小到大顺序读取.
19288   --//T1 id=10
--//注意,T1=10的数据块号是19288.也就是这块应该是db file sequential read.
18971   --//T1 id=6
18986   --//T1 id=4
19007   --//T1 id=7
19082   --//T1 id=3
19165   --//T1 id=9
19215   --//T1 id=8
19258   --//T1 id=5
--//以上7块是db file parallel read ,id=3..9,你也可以发现实际上db file parallel read读取的块是离散的,但是按照从小到大顺序读取.
--//我建立的表T2正好巧合T2=10的数据块是id=3..10最小数据块.

SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=2866 ;
 SID SEQ# EVENT# EVENT                       P1TEXT            P1 P2TEXT     P2 P3TEXT    P3  WAIT_TIME WAIT_TIME_MICRO TIME_SINCE_LAST_WAIT_MICRO     CON_ID
---- ---- ------ --------------------------- --------- ---------- ------ ------ --------- -- ---------- --------------- -------------------------- ----------
2866    1    184 db file parallel read       files              1 blocks      7 requests   7          0            1799                        272          0
2866    2    562 PGA memory operation                     1114112             2            0          0             144                         70          0
2866    3    179 db file sequential read     file#              7 block#  19288 blocks     1          0              79                         76          0
2866    4    184 db file parallel read       files              1 blocks      8 requests   8          0            1077                        271          0
2866    5    562 PGA memory operation                     1114112             1            0          0              48                         34          0
2866    6    441 SQL*Net message to client   driver id 1413697536 #bytes      1            0          0               1                         48          0
2866    7    179 db file sequential read     file#              7 block#  19026 blocks     1          0              81                         71          0
2866    8    179 db file sequential read     file#              7 block#  19971 blocks     1          0             140                        115          0
2866    9    445 SQL*Net message from client driver id 1413697536 #bytes      1            0          0             626                        139          0
2866   10    179 db file sequential read     file#              7 block#  19179 blocks     1          0              73                         39          0
10 rows selected.

--//因为V$SESSION_WAIT_HISTORY仅仅记录会话最后10个等待事件,循环使用,db file parallel read 的blocks=7出现在前面很正常.

--//还有一个线索可以证明我的判断,过滤event like 'db%',order by seq# desc,视乎出现等待事件从SEQ#=1开始插入.
SYS@192.168.100.235:1521/orcl> select * from V$SESSION_WAIT_HISTORY where sid=2866 and event like 'db%' order by seq# desc;
 SID SEQ# EVENT# EVENT                       P1TEXT            P1 P2TEXT     P2 P3TEXT    P3  WAIT_TIME WAIT_TIME_MICRO TIME_SINCE_LAST_WAIT_MICRO     CON_ID
---- ---- ------ --------------------------- --------- ---------- ------ ------ --------- -- ---------- --------------- -------------------------- ----------
2866   10    179 db file sequential read     file#              7 block#  19179 blocks     1          0              73                         39          0
2866    8    179 db file sequential read     file#              7 block#  19971 blocks     1          0             140                        115          0
2866    7    179 db file sequential read     file#              7 block#  19026 blocks     1          0              81                         71          0
2866    4    184 db file parallel read       files              1 blocks      8 requests   8          0            1077                        271          0
2866    3    179 db file sequential read     file#              7 block#  19288 blocks     1          0              79                         76          0
2866    1    184 db file parallel read       files              1 blocks      7 requests   7          0            1799                        272          0
6 rows selected.
--//注意看访问P2参数:
19179   --//T1 id=1
19971   --//T2 id=2
19026   --//T1 id=2
--//出现 db file parallel read  8块.
19288   --//T1 id=10
--//出现 db file parallel read  7块.
--//与strace跟踪看到的顺序一致.

5.解析:
--//测试到这里,我没给出解析.我前面给出的解析如下:

--//我当时做到这里db file parallel read最大请求blocks的数量是127(注:这个很容易测试出来),而且还与arraysize参数有关。
--//oracle执行时先从索引收集rowid,确定那些文件与数据块要读取,按照文件号与块号排序,抽取数据块进入缓存后,按照索引的读取顺
--//序数据块(不然不是这样的顺序输出),当然已经在数据缓存的块记录优先填充.当读取数量达到arraysize或者没有剩余记录时输出结
--//果,而最后1条记录会优先输出,这样就会出现前面id=10优先输出的情况.

--//这样t1.id=10做db file sequential read 连接取出另外t2个表的t2.id=10的记录.

--//而第2次db file parallel read,id=3..9,这样id=9的优先输出,这样就是了id=10,9在前面的情况.
--//总之,文字不是很好表达.....


热门相关:高甜预警:我家影后超猛的   帝国远征   仙城之王   高甜预警:我家影后超猛的   我家影后超甜的