解析跟踪日志内容 复读一致读

解析跟踪日志内容
实验：
SQL> create  table tab_05_01 as select * from dba_extents;
 
Table created
 
SQL> alter system flush buffer_cache;
 
System altered
SQL> alter system flush shared_pool;
 
System altered
SQL> exec dbms_session.set_sql_trace(true);
 
PL/SQL procedure successfully completed
 
SQL> select /* a */owner,count(1) from tab_05_01 group by owner order by owner;
 
16 rows selected
 
SQL> select /* b */owner,count(1) from tab_05_01 group by owner order by owner;
16 rows selected
SQL> select /* c */owner,count(1) from tab_05_01 group by owner order by owner;
（在另一个做delete动作后提交select）
 
16 rows selected
 
SQL> delete /* d */from tab_05_01;
 
5826 rows deleted
 
SQL> update /*f*/ tab_05_01 set wner='sys';
 
5826 rows updated
 
SQL> exec dbms_session.set_sql_trace(false);
 
PL/SQL procedure successfully completed

结果：

TKPROF: Release 10.2.0.1.0 - Production on 星期一 7月 5 23:45:26 2010

Copyright (c) 1982, 2005, Oracle.  All rights reserved.

Trace file: orcl_ora_1808.trc
Sort options: default

********************************************************************************
count    = number of times OCI procedure was executed
cpu      = cpu time in seconds executing
elapsed  = elapsed time in seconds executing
disk     = number of physical reads of buffers from disk
query    = number of buffers gotten for consistent read
current  = number of buffers gotten in current mode (usually for update)
rows     = number of rows processed by the fetch or execute call
********************************************************************************
select /* a */owner,count(1)
from
 tab_05_01 group by owner order by owner

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.01       0.02         55         57          0          16
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.02         55         57          0          16

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 

Rows     Row Source Operation
-------  ---------------------------------------------------
     16  SORT GROUP BY (cr=57 pr=55 pw=0 time=22181 us)
   5826   TABLE ACCESS FULL TAB_05_01 (cr=57 pr=55 pw=0 time=44097 us)

********************************************************************************

select /* b */owner,count(1)
from
 tab_05_01 group by owner order by owner

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.01       0.00          0         57          0          16
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.01       0.01          0         58          0          16

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 

Rows     Row Source Operation
-------  ---------------------------------------------------
     16  SORT GROUP BY (cr=57 pr=0 pw=0 time=6872 us)
   5826   TABLE ACCESS FULL TAB_05_01 (cr=57 pr=0 pw=0 time=58312 us)

********************************************************************************

select /* c */owner,count(1)
from
 tab_05_01 group by owner order by owner

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1      0.04       0.04          0       5911          0          16
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3      0.04       0.04          0       5912          0          16

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 

Rows     Row Source Operation
-------  ---------------------------------------------------
     16  SORT GROUP BY (cr=5911 pr=0 pw=0 time=42584 us)
   5826   TABLE ACCESS FULL TAB_05_01 (cr=5911 pr=0 pw=0 time=455005 us)

********************************************************************************

delete /* d */from tab_05_01

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.42       0.54          2         69       6481        5826
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.42       0.54          2         70       6481        5826

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  DELETE  TAB_05_01 (cr=124 pr=6 pw=0 time=577920 us)
   5826   TABLE ACCESS FULL TAB_05_01 (cr=57 pr=0 pw=0 time=25216481 us)

********************************************************************************

update /*f*/ tab_05_01 set wner='sys'

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          1          0           0
Execute      1      0.17       0.20          1         57       2133        5826
Fetch        0      0.00       0.00          0          0          0           0
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        2      0.17       0.20          1         58       2133        5826

Misses in library cache during parse: 1
Optimizer mode: ALL_ROWS
Parsing user id: 55 

Rows     Row Source Operation
-------  ---------------------------------------------------
      0  UPDATE  TAB_05_01 (cr=57 pr=1 pw=0 time=204674 us)
   5826   TABLE ACCESS FULL TAB_05_01 (cr=57 pr=0 pw=0 time=5085278 us)

********************************************************************************

结论：
disk  =物理读  从磁盘读入BUFFER CACHE中的块数。 例如 实例a  表tab_05_01是第一次被读取，需先加载
到BUFFER CACHE 再做一次一致读
query =一致读(consistent read) 如果在读之前没有发生其他更新或删除的且未提交操作，则就代表BUFFER CACHE
中对象数据的块数 例如 实例b 表tab_05_01的数据块已经存在于BUFFER CACHE中  否则需要到undo段中读取旧数据，
进行重组。例如实例 c
current  = db block get  number of buffers gotten in current mode (usually for update) 很明显观察 实例 d 、f
这个是发生修改或删除的动作而读取当前版本数据块 多数用于update

这三个参数同 autotrace或v$systat中的参数是一致的
其他说明：
elapsed    Total number of seconds to execute 包含了CPU消耗时间和等待时间
PARSE      Translates the SQL statement into an execution plan
EXECUTE    Executes the statement(This step modifies the data for INSERT,UPDATE, and DELETE statements.)
FETCH      Retrieves the rows returned by a query (Fetches are performed only for SELECT statements.)

进一步 理解：
Oracle accesses blocks in one of two modes, current or consistent.

A 'db block get' is a current mode get.  That is, it's the most up-to-date
copy of the data in that block, as it is right now, or currently.  There
can only be one current copy of a block in the buffer cache at any time.
Db block gets generally are used when DML changes data in the database.
In that case, row-level locks are implicitly taken on the updated rows.
There is also at least one well-known case where a select statement does
a db block get, and does not take a lock.  That is, when it does a full
table scan or fast full index scan, Oracle will read the segment header
in current mode (multiple times, the number varies based on Oracle version).

A 'consistent get' is when Oracle gets the data in a block which is consistent
with a given point in time, or SCN.  The consistent get is at the heart of
Oracle's read consistency mechanism.  When blocks are fetched in order to
satisfy a query result set, they are fetched in consistent mode.  If no
block in the buffer cache is consistent to the correct point in time, Oracle
will (attempt to) reconstruct that block using the information in the rollback
segments.  If it fails to do so, that's when a query errors out with the
much dreaded, much feared, and much misunderstood ORA-1555 "snapshot too old".

来自 “ ITPUB博客 ” ，链接：http://blog.itpub.net/21993926/viewspace-667274/，如需转载，请注明出处，否则将追究法律责任。

转载于:http://blog.itpub.net/21993926/viewspace-667274/