oracle等待事件1分別用表和索引上資料的訪問來產生db file scattered read等待事件

一 我們先從一個最簡單的等待事件來進入oracle wait event world

實驗環境

Oracle Database 11g Enterprise Edition Release 11.2.0.1.0 - 64bit Production

With the Partitioning, OLAP, Data Mining and Real Application Testing options

ORACLE_HOME = /u01/app/oracle/product/11.2.0/db_1

System name:     Linux

Node name:      leonarding1.oracle.com

Release:         2.6.32-200.13.1.el5uek

Version:         #1 SMP Wed Jul 27 21:02:33 EDT 2011

Machine:        x86_64

Instance name: LEO1

Redo thread mounted by this instance: 1

Oracle process number: 21

Unix process pid: 28039, image: (TNS V1-V3)

搭建平臺：Oracle 資料庫效能最佳化藝術課程專用環境《VirtualBox+OELR5U7x86_64+Oracle11gR2》

LEO1@LEO1> select distinct sid from v$mystat;       我們要知道當前的會話id是什麼，這樣我們就可以在會話等待檢視中檢視對於id的等待事件是什麼了

       SID

-----------------

       133

LEO1@LEO1> col wait_class for a10

LEO1@LEO1> col state for a15

LEO1@LEO1> select sid,event,wait_class,state,wait_time from v$session_wait;

SID   EVENT                     WAIT_CLASS       STATE            WAIT_TIME

---------- ---------------------------------------------------------------- ---------- --------------- -------------------------

133  SQL*Net message to client     Network          WAITED SHORT TI         -1

SQL*Net message to client 這是一個非常常見的等待事件，在oracle 11g中它算做一個短等待，當客戶端與伺服器建立起會話後，伺服器就會等待客戶端傳送命令，如果此時沒有命令傳輸就會產生這個等待事件。我們舉個例子比較好理解

sqlplus  leo1/leo1  我們透過sqlplus登入資料庫，就會建立起會話，此時就會產生上述等待事件

pl/sql  Developer 軟體訪問資料庫（這也是客戶端與伺服器建立會話的過程），也會發生上述等待事件

SQL*Net（原來叫net8）是oracle自己的通訊協議，只要安裝了oracle客戶端並透過客戶端連線資料庫就會走這個協議通訊，當然就會產生基於這個協議的等待事件。（這個事件我們可以忽略）

二 分別用表和索引上資料的訪問來產生db file scattered read等待事件，等待事件需要在v$session_wait和10046 trace檔案中顯示出來，貼出整個演示過程。

db file scattered read 等待事件：是由於多資料塊讀操作產生的，當我們檢索資料時從磁碟上讀資料到記憶體中，一次I/O讀取多個資料塊，而資料塊在記憶體中是分散分佈並不是連續的，當資料塊讀取到記憶體這個過程中會產生“db file scattered read”事件

多資料塊讀場景：FTS （full table scan）     全表掃描

                IFFS （index fast full scan） 快速索引全掃描：把索引鏈切割成很多份，多塊並行讀取

LEO1@LEO1> drop table leo1 purge;                            清理環境

Table dropped.

SYS@LEO1> show parameter memory_target                      SGA=652M

NAME                                 TYPE        VALUE

------------------------------------ ----------- ----------------------------------------------

memory_target                        big integer     652M

LEO1@LEO1> create table leo1 as select * from dba_objects;        建立一張新表沒有索引

Table created.

LEO1@LEO1> select count(*) from leo1;                         統計表資料71961行

  COUNT(*)

--------------------

     71961

LEO1@LEO1> set autotrace trace exp

FTS掃描

LEO1@LEO1> select count(*) from leo1;                               oracle進行FTS掃描

Execution Plan

----------------------------------------------------------

Plan hash value: 2716644435

--------------------------------------------------------------------------

| Id  | Operation         | Name | Rows  | Bytes | Cost (%CPU)| Time     |

--------------------------------------------------------------------------

|   0 | SELECT STATEMENT  |      | 75071 |    14M|   287   (1)| 00:00:04 |

|   1 |  TABLE ACCESS FULL| LEO1 | 75071 |    14M|   287   (1)| 00:00:04 |

--------------------------------------------------------------------------

Note

-----

   - dynamic sampling used for this statement (level=2)

由於這個動作非常的快，在v$session_wait檢視中不容易捕捉到，其實我們還可以去10046事件中追蹤一下看看

10046事件分析sql執行效能

解釋：10046事件是發生在sql的執行過程中，它能夠全面分析出sql執行過程和所消耗的資源，讓你瞭解這條sql是否是最優的，10046事件有4個級別

LEVEL  1   等同於SQL_TRACE的功能

LEVEL  4   在LEVEL 1基礎上增加繫結變數資訊

LEVEL  8   在LEVEL 1基礎上增加等待事件資訊

LEVEL  12  等同於LEVEL  4+LEVEL  8，即有繫結變數資訊又有等待事件資訊

LEO1@LEO1> execute dbms_stats.gather_table_stats(ownname=>'LEO1',tabname=>'LEO1',cascade=>TRUE);

PL/SQL procedure successfully completed. 我們先做一個表分析，收集到更多的統計資訊，方便10046正確評估

SYS@LEO1> alter system flush buffer_cache;               清空data_buffer_cache，好顯示多塊讀效果

System altered.

LEO1@LEO1> alter session set events '10046 trace name context forever,level 12';  啟動10046事件定義級別12，這是最高階別，包括的資訊最全面                                 

LEO1@LEO1> select count(*) from leo1;                            FTS掃描

  COUNT(*)

-------------------

     71961

LEO1@LEO1> alter session set events '10046 trace name context off';    關閉10046事件

Session altered.

[oracle@leonarding1 trace]$ pwd

/u01/app/oracle/diag/rdbms/leo1/LEO1/trace             11g 和 10g  trace檔案所在目錄不同請注意

會話133

LEO1@LEO1> select name,value from v$diag_info where name='Default Trace File';  當前會話寫入trace檔名

NAME                                VALUE

--------------------------------------------------------   -------------------------------------------------------------------------------

Default  Trace  File                    /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_28039.trc

LEO1@LEO1> !vim /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_28039.trc  開啟trace檔案，選取部分有用資訊

*** SESSION ID:(133.6542) 2012-12-27 23:51:54.342         會話133

*** MODULE NAME:(SQL*Plus) 2012-12-27 23:51:54.342     透過sqlplus登入

select count(*) from leo1

END OF STMT

PARSE #3:c=1000,e=1375,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=4191104944,tim=1356623522426980 解析資源

EXEC #3:c=0,e=71,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4191104944,tim=1356623522427140    執行資源

WAIT #3: nam='SQL*Net message to client' ela= 12 driver id=1650815232 #bytes=1 p3=0 obj#=13482 tim=1356623522427305    第一個等待事件，原因上面已經都介紹了

WAIT #3: nam='Disk file operations I/O' ela= 49 FileOperation=2 fileno=5 filetype=2 obj#=73707 tim=1356623522427604

WAIT #3: nam='db file sequential read' ela= 19 file#=5 block#=1458 blocks=1 obj#=73707 tim=1356623522427658

WAIT #3: nam='db file scattered read' ela= 36 file#=5 block#=1459 blocks=5 obj#=73707 tim=1356623522427878

WAIT #3: nam='db file scattered read' ela= 35 file#=5 block#=1464 blocks=8 obj#=73707 tim=1356623522428146

WAIT #3: nam='db file scattered read' ela= 26 file#=5 block#=1473 blocks=7 obj#=73707 tim=1356623522428643

WAIT #3: nam='db file scattered read' ela= 27 file#=5 block#=1480 blocks=8 obj#=73707 tim=1356623522428908

WAIT #3: nam='db file scattered read' ela= 278 file#=5 block#=1489 blocks=7 obj#=73707 tim=1356623522429449

WAIT #3: nam='db file scattered read' ela= 28 file#=5 block#=1496 blocks=8 obj#=73707 tim=1356623522429728

引數解釋：

File#：訪問資料檔案號

LEO1@LEO1> select file#,name from v$datafile where file#=5;

     FILE#        NAME

------------------------------------------------------------------------------------------------------------------------------------------

        5        /u01/app/oracle/oradata/LEO1/leo1_01.dbf

Block#：訪問起始資料塊號

Blocks：讀取了多少個資料塊

例  1458+1=1459 –> 1459+5=1464 一直讀取到1496號，可見這些資料塊在檔案中都是連續存放的，讀取機制都是多塊讀，符合產生“db file scattered read”等待事件的條件

LEO1@LEO1> select sid,event,total_waits,time_waited from v$session_event;  顯示累計會話等待事件統計資訊

SID EVENT                              TOTAL_WAITS TIME_WAITED

---------- ---------------------------------------------------------------- ----------- ---------------

133 db file scattered read                  31           0             等待了31次

可以看到這個會話生命週期中經歷了哪些等待

小提示：當你長時間使用sqlplus登入資料庫時在做上面的10046實驗，你可能會發現在trace檔案中只有SQL*Net message to client沒有db file scattered read，解決方法是退出來重新登陸這樣就可以看見db file scattered read了。

IFFS掃描

LEO1@LEO1> select distinct sid from v$mystat;                          我的會話id還是133

       SID

--------------------

       133

LEO1@LEO1> create index idx_leo1 on leo1(object_id);         在表leo1欄位object_id新增一個B-tree索引

Index created.

LEO1@LEO1> select table_name,index_name from user_indexes where table_name='LEO1';  

TABLE_NAME                     INDEX_NAME

------------------------------ ------------------------------

LEO1                           IDX_LEO1

LEO1@LEO1> execute dbms_stats.gather_table_stats(ownname=>'LEO1',tabname=>'LEO1',cascade=>TRUE);

PL/SQL procedure successfully completed.這次分析是把表和索引一起分析一遍，收集索引和表的統計資訊，CBO評估

LEO1@LEO1> set autotrace trace exp

LEO1@LEO1> select count(object_id) from leo1;                            oracle進行IFFS掃描

Execution Plan

----------------------------------------------------------

Plan hash value: 1365721260

-----------------------------------------------------------------------------------------------------------------------------

| Id  | Operation             | Name     | Rows  | Bytes | Cost (%CPU)| Time

--------------------------------------------------------------------------------

|   0 | SELECT STATEMENT      |          |     1 |     5 |    45   (0)| 00:00:01

|   1 |  SORT AGGREGATE     |          |     1 |     5 |            |

|   2 |   INDEX FAST FULL SCAN| IDX_LEO1 | 71961 |   351K|    45   (0)| 00:00:01

-----------------------------------------------------------------------------------------------------------------------------

LEO1@LEO1> set autotrace off

當有索引之後就開始走IFFS快速索引全掃描了，原理是把這個索引鏈切割成多個區域，多塊並行讀取，既然是多塊讀那麼也可以產生db file scattered read事件。

LEO1@LEO1> alter system flush buffer_cache;                      再次清空data_buffer_cache

System altered.

LEO1@LEO1> set serveroutput on                                             開啟螢幕輸出

LEO1@LEO1> create or replace procedure p1                       建立一個儲存過程p1，迴圈3000次

as

     leo number;

begin

     for i in 1..3000

     loop

         select count(object_id) into leo from leo1;

     end loop;

     dbms_output.put_line('successfully');                        

end;

/

  2    3    4    5    6    7    8    9   10   11  

Procedure created.

LEO1@LEO1> alter system flush buffer_cache;     每次重新測試的時候一定要提前清空data_buffer_cache，因為如果資料已經在記憶體中那麼就不會在去訪問磁碟的檔案了，也就發生不了“db file scattered read”這個等待事件，切記切記！

LEO1@LEO1> execute p1;

Successfully                                                 當看到“successfully”表明這個p1執行完畢

PL/SQL procedure successfully completed.

會話157

LEO1@LEO1> select sid,event,wait_class,p1,p1text,p2,p2text,p3,p3text from v$session_wait where event like '% db file scattered read %';

SID EVENT               WAIT_CLASS    P1 P1TEXT    P2  P2TEXT     P3  P3TEXT

---------- ---------------------------------------------------------------- ----------------- ---------- ---------- ---------------

133 db file scattered read     User I/O     5  file#      2562 block#      42  blocks

在157會話中當對133的儲存過程p1執行過程中，馬上檢視v$session_wait檢視，才能捕捉到“db file scattered read”，如果執行完畢了就看不到這個等待事件了，切記切記切記！

SID：133  會話號

EVENT：db file scattered read  等待事件名

P1：5     資料檔案號

P1TEXT：  對p1引數的解釋

P2：2562  訪問起始資料塊號

P2TEXT：  對p2引數的解釋

P3：42    讀取了42個資料塊

P3TEXT：  對p3引數的解釋

可知索引上資料的訪問也會產生db file scattered read等待事件

LEO1@LEO1> alter system flush buffer_cache;                 再次清空data_buffer_cache

System altered.

10046 trace檔案中顯示出來

LEO1@LEO1> alter session set events '10046 trace name context forever,level 12';   啟動10046事件

Session altered.

LEO1@LEO1> select count(object_id) from leo1;                               IFFS掃描

COUNT(OBJECT_ID)

---------------------------

           71961

LEO1@LEO1> alter session set events '10046 trace name context off';              關閉10046事件

Session altered.

LEO1@LEO1> select name,value from v$diag_info where name='Default Trace File';  當前會話寫入trace檔名

NAME            VALUE

--------------------------------------------------------------------------------

Default Trace File   /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_6327.trc

LEO1@LEO1> !vim /u01/app/oracle/diag/rdbms/leo1/LEO1/trace/LEO1_ora_6327.trc    開啟trace檔案，看中間部分

PARSING IN CURSOR #2 len=33 dep=0 uid=85 ct=3 lid=85 tim=1356681643167307 hv=2452024216 ad='80fee680' sqlid='cvf96jk92duws'               sql解析的資源

select count(object_id) from leo1

END OF STMT

PARSE #2:c=2000,e=1284,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=1365721260,tim=1356681643167301

EXEC #2:c=0,e=67,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1365721260,tim=1356681643167478

WAIT #2: nam='SQL*Net message to client' ela= 7 driver id=1650815232 #bytes=1 p3=0 obj#=0 tim=1356681643167583

sequential read：表示索引的入口（根 -> 分支 -> 葉子）逐步的深入，所以是順序讀

WAIT #2: nam='db file sequential read' ela= 20 file#=5 block#=7618 blocks=1 obj#=73708 tim=1356681643167705

scattered read：表示葉子批次多資料塊讀，資料塊在檔案中也是連續存放，可以一次讀5塊 8塊 7塊等

WAIT #2: nam='db file scattered read' ela= 100 file#=5 block#=7619 blocks=5 obj#=73708 tim=1356681643168128

WAIT #2: nam='db file scattered read' ela= 27 file#=5 block#=7624 blocks=8 obj#=73708 tim=1356681643168608

WAIT #2: nam='db file scattered read' ela= 30 file#=5 block#=7633 blocks=7 obj#=73708 tim=1356681643170140

WAIT #2: nam='db file scattered read' ela= 31 file#=5 block#=7640 blocks=8 obj#=73708 tim=1356681643170853

WAIT #2: nam='db file scattered read' ela= 25 file#=5 block#=7649 blocks=7 obj#=73708 tim=1356681643171787

WAIT #2: nam='db file scattered read' ela= 26 file#=5 block#=7656 blocks=8 obj#=73708 tim=1356681643172541

WAIT #2: nam='db file scattered read' ela= 28 file#=5 block#=7665 blocks=7 obj#=73708 tim=1356681643174215

WAIT #2: nam='db file scattered read' ela= 164 file#=5 block#=7672 blocks=8 obj#=73708 tim=1356681643175184

小結：可以看出不論FTS還是IFFS，只要走多資料塊讀就會產生“db file scattered read”等待事件，我們可以開多個並行來加快資料檢索速度，儘量減少這種等待事件的發生，有資源消耗就會有等待事件，我們只能儘量減少而不可避免。

2012.12.28
天津&winter
分享技術~成就夢想
Blog：