今天遇到一個很有意思的問題,一個開發人員反饋在測試伺服器ORACLE資料庫執行的一條簡單SQL語句非常緩慢,他寫的一個SQL沒有返回任何數據,但是耗費了幾分鐘的時間。讓我檢查分析一下原因,分析解決過後,發現事情的真相有點讓人哭笑不得,但是也是非常有意思的。我們先簡單構造一下類似的案例,當然只是簡單模... ...
今天遇到一個很有意思的問題,一個開發人員反饋在測試伺服器ORACLE資料庫執行的一條簡單SQL語句非常緩慢,他寫的一個SQL沒有返回任何數據,但是耗費了幾分鐘的時間。讓我檢查分析一下原因,分析解決過後,發現事情的真相有點讓人哭笑不得,但是也是非常有意思的。我們先簡單構造一下類似的案例,當然只是簡單模擬。
假設一個同事A,創建了一個表並初始化了數據(實際環境數據量較大,有1G多的數據),但是他忘記提交了。我們簡單模擬如下:
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秒多(這個因為構造的數據量不是非常大的緣故。實際場景耗費了幾分鐘)
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異常大,你就會有所察覺(見後面分析)
SQL> exec dbms_stats.gather_table_stats('SYS','TEST_UNCOMMIT');
PL/SQL procedure successfully completed.
Elapsed: 00:00:12.29
因為ORACLE裡面的寫不阻塞讀,所以不可能是因為SQL阻塞的緣故,然後我想查看這個表到底有多少記錄,結果亮瞎了我的眼睛,記錄數為0,但是空間用掉了852 個數據塊
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個數據塊。
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操作,但是沒有提交。
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',
&n