索引优化UNDO db file sequential read等待

  • lixiaxin200319

    2015-05-16 21:57:51
  • Oracle
  • 原创

 

索引优化UNDO db file sequential read等待

环境描述：

DATABASE：ORACLE  企业版 11.2.0.4  64 位

OS： WIND7  64 位

 

 

准备测试数据：

 

create table lixia.lob_tab2 (n number,c clob)

lob (c) store as  SECUREFILE  lob_2

(nocache nologging);

 

begin

   for  i in 1..10000

   loop

      insert into  lixia.lob_tab2 (n,c) values(i,'亲亲的我将离开你，请将眼角的泪拭去');

   end loop;

   commit;

end;

/

 

开启LOB 对象的压缩属性

alter table lixia.lob_tab2 modify lob(c) (compress);

 

 

测试的PL/SQL 块

 

SQL1：在SESSION 1中执行

begin

   for  i in  1..1000 loop

       update  lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去'

       where n <=5000;

   end loop;

end;

/

 

SQL2：在SESSION 2中执行

begin

   for  i in  1..1000 loop

       update  lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去'

       where n>5000;

   end loop;

end;

/

 

 

问题：如果先在 SESSION 1中执行SQL1，然后紧接着在 SESSION 2中执行 SQL2，SQL1大概

半小时执行完了，但SQL2 在SQL1 执行完成后，还要过一个小时才能执行完；而且

查看操作系统的磁盘IO 情况，在SQL1 和SQL2同时执行时磁盘吞吐量基本维持在

5MB每秒左右，峰值偶而会冲到30MB每秒，磁盘忙碌读一直在100%左右；当SQL1

执行完后，只有SQL2在执行，磁盘IO 吞吐量在800KB每秒，磁盘忙碌读也一直100%

左右。

 

如果先在 SESSION 2中执行SQL2，然后紧接着在 SESSION 1中执行 SQL1，SQL2大概

半小时执行完了，但SQL1 在SQL2 执行完成后，还要过一个小时才能执行完；而且

查看操作系统的磁盘IO 情况，在SQL1 和SQL2同时执行时磁盘吞吐量基本维持在

5MB每秒左右，峰值偶而会冲到30MB每秒，磁盘忙碌读一直在100%左右；当SQL2

执行完后，只有SQL1在执行，磁盘IO 吞吐量在800KB每秒，磁盘忙碌读也一直100%

左右（如图1），有时磁盘忙碌度为0%（如图2）通过图2可以发现这个时候IO都是

在 UNOD 表空间上，结合在V$SESSION 视图中发现执行测试SQL的会话有大量的

db file sequential read 等待，分析SQL的执行计划是进行全表扫描，可以判定是在等

待UNDO 块。

 

结合我们测试的SQL分析，两个SQL是更新同一张表，而且都是进行全表扫描，比

如我们先执行update lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去'

where n <=5000 那么包含n<=5000记录的数据块，就被SESSION 1占了；同样的在

SESSION 2执行update lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去'

where n >5000 ，那么包含n>5000记录的数据块，就被SESSION 2占了；这个时候

SESSION 2想要读取 存放n<=5000的数据块就需要读取UNDO 块，通过撤销操作生

成CR 块，同理SESSION 1想要读取 存放n>5000的数据块就需要读取UNDO 块，通

过撤销操作生成CR 块。导致SQL性能急剧下降。

 

 

 

 


                                        图1

 

 

      

 

                      图2

 

SQL 执行计划信息：

 

select * from table(dbms_xplan.DISPLAY_CURSOR('7n2th5tax3k5z',null, 'ALLSTATS ADVANCED'));

 

PLAN_TABLE_OUTPUT

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

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

SQL_ID  7n2th5tax3k5z, child number 0

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

update   lixia.lob_tab set c='??????????????????????????????????

' where n>5000

 

Plan hash value: 2454619229

 

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

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

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

|   0 | UPDATE STATEMENT   |         |        |       |    68 (100)|          |

 

PLAN_TABLE_OUTPUT

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

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

|   1 |  UPDATE            | LOB_TAB |        |       |            |          |

|*  2 |   TABLE ACCESS FULL| LOB_TAB |   5001 |   854K|    68   (0)| 00:00:01 |

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

 

 

 

优化：在 LOB_TAB2表的N 字段创建索引，然后在测试SQL上添加使用索引的提示。优化

      后，SQL执行计划使用的是索引扫描，没有UNDO 块 db file sequential read 等待，

      两个SQL几乎是同时执行完。SQL执行时监控操作系统的资源使用情况，磁盘IO吞

吐量在峰值35MB每秒（大部分时间都为峰值）（如图3），磁盘忙碌度100%左右，

CPU使用率50%（如图4），磁盘活动中IO前几名的文件中已经看不到UNDO 文件了

（如图5）。

 

Create   index  lixia.lob_tab2_indx  on  lixia.lob_tab2(n);

 

exec  dbms_stats.gather_table_stats('LIXIA','LOB_TAB2',cascade=>true);

 

 

SQL1在 SESSION 1中执行

begin

   for  i in  1..1000 loop

       update  /*+ index(lob_tab2 lob_tab2_indx)*/

       lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去'

       where n <=5000;

   end loop;

end;

/

 

SQL2：在 SESSION 2中执行

begin

   for  i in  1..1000 loop

       update /*+ index(lob_tab2 lob_tab2_indx)*/

        lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去'

       where n>5000;

   end loop;

end;

/

 

 


 

                              图 3

 

 


 

                  图  4

 

 


 

                       图  5

 

 

总结：

1、  通过索引扫描优化全表扫描，可以减少不必要的IO，在类似测试的SQL 执行场景中可以优化 UNDO 块的 db file sequential read等待。

2、  监控操作系统资源使用情况可以有效帮助定位数据库性能问题。

 

 

 

 

 

 

索引优化UNDO db file sequential read等待通过ASH定位问题

 

 

AWR 报告：

 

WORKLOAD REPOSITORY report for

DB Name

DB Id

Instance

Inst num

Startup Time

Release

RAC

ORCL

1387249021

orcl

1

02-5? -15 09:05

11.2.0.4.0

NO

 

Host Name

Platform

CPUs

Cores

Sockets

Memory (GB)

LIXIA-PC

Microsoft Windows x86 64-bit

4

2

1

1.93

 


Snap Id

Snap Time

Sessions

Cursors/Session

Begin Snap:

128

02-5? -15 12:00:09

29

1.3

End Snap:

129

02-5? -15 13:00:01

33

1.1

Elapsed:

 

59.87 (mins)

 

 

DB Time:

 

85.12 (mins)

 

 

Report Summary

Load Profile


Per Second

Per Transaction

Per Exec

Per Call

DB Time(s):

1.4

12.4

0.31

3.41

DB CPU(s):

0.7

6.0

0.15

1.65

Redo size (bytes):

1,709,875.8

14,907,984.1

 

 

Logical read (blocks):

76,587.5

667,747.3

 

 

Block changes:

7,757.0

67,631.2

 

 

Physical read (blocks):

45.9

400.3

 

 

Physical write (blocks):

99.0

862.8

 

 

Read IO requests:

43.5

378.8

 

 

Write IO requests:

83.0

723.8

 

 

Read IO (MB):

0.4

3.1

 

 

Write IO (MB):

0.8

6.7

 

 

User calls:

0.4

3.6

 

 

Parses (SQL):

2.7

23.2

 

 

Hard parses (SQL):

0.0

0.3

 

 

SQL Work Area (MB):

0.2

1.3

 

 

Logons:

0.1

0.6

 

 

Executes (SQL):

4.6

40.1

 

 

Rollbacks:

0.0

0.0

 

 

Transactions:

0.1

 

 

 

Instance Efficiency Percentages (Target 100%)

Buffer Nowait %:

100.00

Redo NoWait %:

99.99

Buffer Hit %:

99.94

In-memory Sort %:

100.00

Library Hit %:

99.83

Soft Parse %:

98.59

Execute to Parse %:

42.12

Latch Hit %:

95.76

Parse CPU to Parse Elapsd %:

14.72

% Non-Parse CPU:

99.98

Top 10 Foreground Events by Total Wait Time

Event

Waits

Total Wait Time (sec)

Wait Avg(ms)

% DB time

Wait Class

DB CPU

 

2471.7

 

48.4

 

db file sequential read

151,513

2249.3

15

44.0

User I/O

SecureFile mutex

832,545

54.4

0

1.1

Concurrency

db file scattered read

1,520

37.3

25

.7

User I/O

log file switch completion

192

25.3

132

.5

Configuration

control file sequential read

5,868

16.2

3

.3

System I/O

log file switch (checkpoint incomplete)

39

11.2

286

.2

Configuration

latch: shared pool

31,106

3.5

0

.1

Concurrency

enq: SQ - contention

42

3

70

.1

Configuration

buffer busy waits

63

1.3

20

.0

Concurrency

 

 

 

在  TOP 10  等待事件中 db file sequential read 等待事件占了44%。

 

 

 

 

 

TOP  SQL:

SQL ordered by Elapsed Time

  • Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.
  • % Total DB Time is the Elapsed Time of the SQL statement divided into the Total Database Time multiplied by 100
  • %Total - Elapsed Time as a percentage of Total DB time
  • %CPU - CPU Time as a percentage of Elapsed Time
  • %IO - User I/O Time as a percentage of Elapsed Time
  • Captured SQL account for 67.2% of Total DB Time (s): 5,107
  • Captured PL/SQL account for 96.2% of Total DB Time (s): 5,107

Elapsed Time (s)

Executions

Elapsed Time per Exec (s)

%Total

%CPU

%IO

SQL Id

SQL Module

SQL Text

2,051.27

143

14.34

40.17

7.41

92.54

1jufmmbcfsnhc

sqlplus.exe

UPDATE LIXIA.LOB_TAB2 SET C='?...

1,805.46

1

1,805.46

35.35

3.67

96.52

f2mg1hby0x164

sqlplus.exe

begin for i in 1..1000 loop up...

1,158.93

1

1,158.93

22.69

89.12

8.68

ar5tzhwbzygwy

sqlplus.exe

begin for i in 1..1000 loop up...

601.20

677

0.89

11.77

92.41

0.32

81hdggjfph3dc

sqlplus.exe

UPDATE /*+ index(lob_tab2 lob_...

600.92

0

 

11.77

92.40

0.32

aq04bsn5jr6p2

sqlplus.exe

begin for i in 1..1000 loop up...

599.97

677

0.89

11.75

89.85

0.54

3x16mrc6czygk

sqlplus.exe

UPDATE /*+ index(lob_tab2 lob_...

599.30

0

 

11.73

89.85

0.54

bxsks654356cd

sqlplus.exe

begin for i in 1..1000 loop up...

246.75

1

246.75

4.83

34.79

63.39

8d4db57ymtcjx

sqlplus.exe

begin for i in 1..100 loop upd...

215.58

2

107.79

4.22

83.23

10.04

drycyqc6cjtnu

sqlplus.exe

begin for i in 1..100 loop upd...

152.29

12

12.69

2.98

5.46

82.98

djs2w2f17nw2z

 

DECLARE job BINARY_INTEGER := ...

104.57

60

1.74

2.05

1.70

97.83

6gvch1xu9ca3g

 

DECLARE job BINARY_INTEGER := ...

 

 

 

SQL ordered by Reads

  • %Total - Physical Reads as a percentage of Total Disk Reads
  • %CPU - CPU Time as a percentage of Elapsed Time
  • %IO - User I/O Time as a percentage of Elapsed Time
  • Total Disk Reads: 164,904
  • Captured SQL account for 86.5% of Total

Physical Reads

Executions

Reads per Exec

%Total

Elapsed Time (s)

%CPU

%IO

SQL Id

SQL Module

SQL Text

133,451

143

933.22

80.93

2,051.27

7.41

92.54

1jufmmbcfsnhc

sqlplus.exe

UPDATE LIXIA.LOB_TAB2 SET C='?...

119,614

1

119,614.00

72.54

1,805.46

3.67

96.52

f2mg1hby0x164

sqlplus.exe

begin for i in 1..1000 loop up...

14,033

1

14,033.00

8.51

246.75

34.79

63.39

8d4db57ymtcjx

sqlplus.exe

begin for i in 1..100 loop upd...

9,396

12

783.00

5.70

152.29

5.46

82.98

djs2w2f17nw2z

 

DECLARE job BINARY_INTEGER := ...

6,769

1

6,769.00

4.10

1,158.93

89.12

8.68

ar5tzhwbzygwy

sqlplus.exe

begin for i in 1..1000 loop up...

4,368

12

364.00

2.65

2.27

33.65

64.83

bhcs6xq8tmz44

 

INSERT INTO STATS$MEMORY_RESIZ...

4,239

60

70.65

2.57

104.57

1.70

97.83

6gvch1xu9ca3g

 

DECLARE job BINARY_INTEGER := ...

1,646

51

32.27

1.00

16.89

1.66

97.88

3am9cfkvx7gq1

 

CALL MGMT_ADMIN_DATA.EVALUATE_...

1,634

2

817.00

0.99

215.58

83.23

10.04

drycyqc6cjtnu

sqlplus.exe

begin for i in 1..100 loop upd...

507

1

507.00

0.31

2.40

14.27

67.58

6ajkhukk78nsr

 

begin prvt_hdm.auto_execute( :...

 

 

 

 

SQL_ID 为 1jufmmbcfsnhc和f2mg1hby0x164排在IO等待的首位。但是只是通过TOP  SQL还无法定位后执行的SQL为什么会比先执行的SQL慢一个多小时。

 

下面我们分析 ASH:

ASH Report For ORCL/orcl 

(1 Report Target Specified)

DB Name

DB Id

Instance

Inst num

Release

RAC

Host

ORCL

1387249021

orcl

1

11.2.0.4.0

NO

LIXIA-PC

 

CPUs

SGA Size

Buffer Cache

Shared Pool

ASH Buffer Size

4

398M (100%)

92M (23.1%)

252M (63.3%)

8.0M (2.0%)

 


Sample Time

Data Source

Analysis Begin Time:

02-May-15 12:00:00

V$ACTIVE_SESSION_HISTORY

Analysis End Time:

02-May-15 13:00:00

V$ACTIVE_SESSION_HISTORY

Elapsed Time:

60.0 (mins)

 

Sample Count:

2,418

 

Average Active Sessions:

0.67

 

Avg. Active Session per CPU:

0.17

 

Report Target:

WAIT_CLASS like 'User I/O'

38.8% of total database activity

 

 

Top Events

Back to Top

Top User Events

Event

Event Class

% Event

Avg Active Sessions

db file sequential read

User I/O

93.59

0.63

db file scattered read

User I/O

1.99

0.01

Back to Top Events 
Back to Top

Top Background Events

Event

Event Class

% Activity

Avg Active Sessions

Disk file operations I/O

User I/O

2.23

0.02

db file sequential read

User I/O

1.28

0.01

Back to Top Events 
Back to Top

Top Event P1/P2/P3 Values

Event

% Event

P1 Value, P2 Value, P3 Value

% Activity

Parameter 1

Parameter 2

Parameter 3

db file sequential read

94.87

"4","14126","1"

0.21

file#

block#

blocks

Disk file operations I/O

2.23

"5","0","3"

1.61

FileOperation

fileno

filetype

db file scattered read

2.07

"4","14089","2"

0.12

file#

block#

blocks

 

 

 

 

Top SQL Command Types

  • 'Distinct SQLIDs' is the count of the distinct number of SQLIDs with the given SQL Command Type found over all the ASH samples in the analysis period

SQL Command Type

Distinct SQLIDs

% Activity

Avg Active Sessions

UPDATE

13

85.81

0.58

INSERT

47

5.96

0.04

SELECT

43

3.80

0.03

 

 

 

Top SQL

Back to Top

Top SQL with Top Events

SQL ID

Planhash

Sampled # of Executions

% Activity

Event

% Event

Top Row Source

% RwSrc

SQL Text

1jufmmbcfsnhc

3658329773

22

78.99

db file sequential read

78.95

TABLE ACCESS - FULL

78.95

UPDATE LIXIA.LOB_TAB2 SET C='?...

gczwvqmk99c8h

3658329773

116

5.75

db file sequential read

4.09

TABLE ACCESS - FULL

3.93

UPDATE LIXIA.LOB_TAB2 SET C='?...

gczwvqmk99c8h

3658329773

116

5.74855252274607113316790736145574855252

db file scattered read

1.65

TABLE ACCESS - FULL

1.65


Complete List of SQL Text

SQL Id

SQL Text

1jufmmbcfsnhc

UPDATE LIXIA.LOB_TAB2 SET C='??????????????????????????????????' WHERE N <=5000

gczwvqmk99c8h

UPDATE LIXIA.LOB_TAB2 SET C='??????????????????????????????????' WHERE N>5000

 

 

 

Top DB Files

  • With respect to Cluster and User I/O events only.

File ID

% Activity

Event

% Event

File Name

Tablespace

3

81.10

db file sequential read

81.10

E:\APP\ADMINISTRATOR\ORADATA\ORCL\UNDOTBS01.DBF

UNDOTBS1

5

5.09

db file sequential read

4.88

E:\APP\ADMINISTRATOR\ORADATA\ORCL\PERFSTAT.DBF

PERFSTAT

4

4.51

db file sequential read

2.81

E:\APP\ADMINISTRATOR\ORADATA\ORCL\USERS01.DBF

USERS

4

4.50785773366418527708850289495450785773

db file scattered read

1.70

E:\APP\ADMINISTRATOR\ORADATA\ORCL\USERS01.DBF

USERS

2

2.77

db file sequential read

2.73

E:\APP\ADMINISTRATOR\ORADATA\ORCL\SYSAUX01.DBF

SYSAUX

1

2.61

db file sequential read

2.44

E:\APP\ADMINISTRATOR\ORADATA\ORCL\SYSTEM01.DBF

SYSTEM

 

 

在 TOP  DB   FILE中排在第一为的是UNDO 文件，结合我们测试的SQL分析，两个SQL是更新同一张表，而且都是进行全表扫描，比如我们先执行update lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去' where n <=5000 那么包含n<=5000记录的数据块，就被

SESSION 1占了；同样的在SESSION 2执行update lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去' where n >5000 ，那么包含n>5000记录的数据块，就被SESSION 2占了；这个时候SESSION 2想要读取 存放n<=5000的数据块就需要读取UNDO 块，通过撤销操作生成CR 块，同理SESSION 1想要读取 存放n>5000的数据块就需要读取UNDO 块，通过撤销操作生成CR 块。导致SQL性能急剧下降。

 

 

 

 

 

索引优化UNDO db file sequential read等待—通过dba_hist_active_sess_history视图定位问题

 

1、TOP 10 等待事件

select *  from (

select  EVENT,count(1),sum(TIME_WAITED)

from dba_hist_active_sess_history

where SNAP_ID in(138,129)

group by EVENT order by sum(TIME_WAITED) desc

) where  rownum<11;

 

EVENT                                                COUNT(1) SUM(TIME_WAITED)

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

db file sequential read                                   226         13267218

control file sequential read                               25          3555759

log file parallel write                                    16          1594626

db file scattered read                                      6           645357

Disk file operations I/O                                    5           639647

control file parallel write                                 6           507623

db file parallel write                                     11           474569

log file sequential read                                    3           333631

read by other session                                       1           290836

enq: SQ - contention                                        1           245658

 

 

2、分析排在第一位的 db file sequential read  等待事件

1)分析等待是是什么文件，这里等待时间最长的是三号文件

select event,p1,SUM(TIME_WAITED) from dba_hist_active_sess_history

where SNAP_ID in(138,129)

  and event='db file sequential read'

group by event,p1

order by SUM(TIME_WAITED);

 

EVENT                                                      P1 SUM(TIME_WAITED)

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

db file sequential read                                     4           166242

db file sequential read                                     2           239759

db file sequential read                                     1           981666

db file sequential read                                     5          1306932

db file sequential read                                     3         10572619

 

2) 查下三号文件是什么类型文件，查询结果显示是UNDO 表空间数据文件。

select file_name,file_id,TABLESPACE_NAME  from dba_data_files where file_id=3;

 

FILE_NAME                                                                 FILE_ID TABLESPACE_NAME

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

E:\APP\ADMINISTRATOR\ORADATA\ORCL\UNDOTBS01.DBF                                 3 UNDOTBS1

 

 

3) 结合我们测试的SQL分析，两个SQL是更新同一张表，而且都是进行全表扫描，比如我们先执行

update lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去' where n <=5000

那么包含n<=5000记录的数据块，就被SESSION 1占了；同样的在SESSION 2执行

update lixia.lob_tab2 set c='亲亲的我将离开你，请将眼角的泪拭去' where n >5000 ，

那么包含n>5000记录的数据块，就被SESSION 2占了；这个时候SESSION 2想要读取 存放n<=5000

的数据块就需要读取UNDO 块，通过撤销操作生成CR 块，同理SESSION 1想要读取 存放n>5000的数

据块就需要读取UNDO 块，通过撤销操作生成CR 块。导致SQL性能急剧下降。

请使用浏览器的分享功能分享到微信等