今天遇到一個很有意思的問題，一個開發人員反饋在測試伺服器ORACLE資料庫執行的一條簡單SQL語句非常緩慢，他寫的一個SQL沒有返回任何資料，但是耗費了幾分鐘的時間。讓我檢查分析一下原因，分析解決過後，發現事情的真相有點讓人哭笑不得，但是也是非常有意思的。我們先簡單構造一下類似的案例，當然只是簡單模擬。
假設一個同事A，建立了一個表並初始化了資料（實際環境資料量較大，有1G多的資料），但是他忘記提交了。我們簡單模擬如下：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 |
SQL> create table test_uncommit 2 as 3 select * from dba_objects where 1=0; Table created. SQL> declare rowIndex number; 2 begin 3 for rowIndex in 1..70 loop 4 insert into test_uncommit 5 select * from dba_objects; 6 end loop; 7 end; 8 / PL/SQL procedure successfully completed. SQL> |
另外一個同事B對這個表做一些簡單查詢操作，但是他不知道同事A的沒有提交INSERT語句，如下所示，查詢時間用了大概5秒多（這個因為構造的資料量不是非常大的緣故。實際場景耗費了幾分鐘）
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 |
SQL> SET TIMING ON; SQL> SET AUTOTRACE ON; SQL> SELECT COUNT(1) FROM SYS.TEST_UNCOMMIT WHERE OBJECT_ID=39; COUNT(1) ---------- 0 Elapsed: 00:00:05.38 Execution Plan ---------------------------------------------------------- Plan hash value: 970680813 ------------------------------------------------------------------------------------ | Id | Operation | Name | Rows | Bytes | Cost (%CPU)| Time | ------------------------------------------------------------------------------------ | 0 | SELECT STATEMENT | | 1 | 13 | 6931 (3)| 00:00:10 | | 1 | SORT AGGREGATE | | 1 | 13 | | | |* 2 | TABLE ACCESS FULL| TEST_UNCOMMIT | 1 | 13 | 6931 (3)| 00:00:10 | ------------------------------------------------------------------------------------ Predicate Information (identified by operation id): --------------------------------------------------- 2 - filter("OBJECT_ID"=39) Note ----- - dynamic sampling used for this statement Statistics ---------------------------------------------------------- 4 recursive calls 0 db block gets 229304 consistent gets 61611 physical reads 3806792 redo size 514 bytes sent via SQL*Net to client 492 bytes received via SQL*Net from client 2 SQL*Net roundtrips to/from client 0 sorts (memory) 0 sorts (disk) 1 rows processed SQL> |
當時是在SQL Developer工具裡面分析SQL的執行計劃，並沒有注意到redo size非常大的情況。剛開始懷疑是統計資訊不準確導致，手工收集了一下該表的統計資訊，執行的時間和執行計劃依然如此，沒有任何變化。 如果我們使用SQL*Plus，檢視執行計劃，就會看到redo size異常大，你就會有所察覺（見後面分析）
|
1 2 3 4 5 |
SQL> exec dbms_stats.gather_table_stats('SYS','TEST_UNCOMMIT'); PL/SQL procedure successfully completed. Elapsed: 00:00:12.29 |
因為ORACLE裡面的寫不阻塞讀，所以不可能是因為SQL阻塞的緣故，然後我想檢視這個表到底有多少記錄，結果亮瞎了我的眼睛，記錄數為0，但是空間用掉了852 個資料塊
|
1 2 3 4 5 6 7 |
SQL> SELECT TABLE_NAME, NUM_ROWS, BLOCKS FROM DBA_TABLES WHERE TABLE_NAME='TEST_UNCOMMIT'; TABLE_NAME NUM_ROWS BLOCKS ------------------------------ ---------- ---------- TEST_UNCOMMIT 0 852 SQL> |
於是我使用Tom大師的show_space指令碼檢查、確認該表的空間使用情況，如下所示，該表確實使用852個資料塊。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 |
SQL> set serverout on; SQL> exec show_space('TEST_UNCOMMIT'); Free Blocks............................. 852 Total Blocks............................ 896 Total Bytes............................. 7,340,032 Total MBytes............................ 7 Unused Blocks........................... 43 Unused Bytes............................ 352,256 Last Used Ext FileId.................... 1 Last Used Ext BlockId................... 88,201 Last Used Block......................... 85 PL/SQL procedure successfully completed. SQL> |
分析到這裡，那麼肯定是遇到了插入資料操作,卻沒有提交的緣故。用下面指令碼檢查發現一個會話ID為883的對這個表有一個ROW級排他鎖，而且會話還有一個事務排他鎖，那麼可以肯定這個會話執行了DML操作，但是沒有提交。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 |
SET linesize 190 COL osuser format a15 COL username format a20 wrap COL object_name format a20 wrap COL terminal format a25 wrap COL req_mode format a20 SELECT B.SID, C.USERNAME, C.OSUSER, C.TERMINAL, DECODE(B.ID2, 0, A.OBJECT_NAME, 'TRANS-' ||TO_CHAR(B.ID1)) OBJECT_NAME, B.TYPE, DECODE(B.LMODE, 0, 'WAITING', 1, 'NULL', 2, 'Row-S(SS)', 3, 'ROW-X(SX)', 4, 'SHARE', 5, 'S/ROW-X(SSX)', 6, 'EXCLUSIVE', ' OTHER') "LOCK MODE", DECODE(B.REQUEST, 0, '', 1, 'NULL', 2, 'Row-S(SS)', 3, 'ROW-X(SX)', 4, 'SHARE', 5, 'S/ROW-X(SSX)', 6, 'EXCLUSIVE', 'OTHER') "REQ_MODE" FROM DBA_OBJECTS A, V$LOCK B, V$SESSION C WHERE A.OBJECT_ID(+) = B.ID1 AND B.SID = C.SID AND C.USERNAME IS NOT NULL ORDER BY B.SID, B.ID2; |
我們在會話裡面提交後，然後重新執行這個SQL，你會發現執行計劃裡面redo size為0，這是因為redo size表示DML生成的redo log的大小，其實從上面的執行計劃分析redo size異常，就應該瞭解到一個七七八八了，因為一個正常的SELECT查詢是不會在redo log裡面生成相關資訊的。那麼肯定是遇到了DML操作，但是沒有提交。
分析到這裡，我們已經知道事情的前因後果了，解決也很容易，找到那個會話的資訊，然後定位到哪個同事，讓其提交即可解決。但是，為什麼沒有提交與提交過後的差距那麼大呢？是什麼原因呢？ 我們可以在這個案例，提交前與提交後跟蹤執行的SQL語句，如下所示。
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 |
SQL> ALTER SESSION SET SQL_TRACE=TRUE; Session altered. SQL> SELECT COUNT(1) FROM SYS.TEST_UNCOMMIT WHERE OBJECT_ID=39; COUNT(1) ---------- 0 SQL> SQL> ALTER SESSION SET SQL_TRACE=FALSE; Session altered. |
提交前上面SQL生成的跟蹤檔案為scm2_ora_8444.trc，我們使用TKPROF格式化如下： tkprof scm2_ora_8444.trc out_uncommit.txt 如下所示
提交後，在另外一個會話執行上面的SQL，然後格式化跟蹤檔案如下所示：
我們發現提交前與提交後兩者的物理讀、一致性讀有較大差別（尤其是一致性讀相差3倍多）。這個主要是因為ORACLE的一致性讀需要構造cr塊，產生了大量的邏輯讀的緣故。相關理論與概念如下：
為什麼要一致性讀,為了保持資料的一致性。如果一個事務需要修改資料塊中資料，會先在回滾段中儲存一份修改前資料和SCN的資料塊，然後再更新Buffer Cache中的資料塊的資料及其SCN，並標識其為“髒”資料。
當其他程式讀取資料塊時，會先比較資料塊上的SCN和程式自己的SCN。如果資料塊上的SCN小於等於程式本身的SCN，則直接讀取資料塊上的資料；
如果資料塊上的SCN大於程式本身的SCN，則會從回滾段中找出修改前的資料塊讀取資料。通常，普通查詢都是一致性讀。
一致性讀什麼時候需要cr塊呢，那就是select語句在發現所查詢的時間點對應的scn，與資料塊當前所的scn不一致的時候。構造cr塊的時候，首先去data buffer中去找包含資料庫前映象的undo塊，如果有直接取出構建CR塊，這時候是邏輯讀，產生邏輯IO；但是data buffer將undo資訊寫出後，就沒有需要的undo資訊，就會去undo段找所需要的前映象的undo資訊，這時候從磁碟上讀出block到buffer中，這時候產生物理讀(物理IO)