[20231023]為什麼重新整理快取後輸出記錄順序發生變化6.txt

lfree發表於2023-11-01

[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在前面的情況.
--//總之,文字不是很好表達.....


來自 “ ITPUB部落格 ” ,連結:http://blog.itpub.net/267265/viewspace-2992409/,如需轉載,請註明出處,否則將追究法律責任。

相關文章