[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在前面的情况.
--//总之,文字不是很好表达.....
--//前几天做了单表刷新缓存后输出记录顺序发生变化的情况，测试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在前面的情况.
--//总之,文字不是很好表达.....
