数据库一条insert某段时间突然变慢，平均单次执行逻辑读暴增至20万，本文分享整个处理过程。

概述

某客户的数据库一条insert语句某段时间突然变慢，平均单次执行逻辑读暴增至20万，最终定位为insert时因可用空间不充足递归清理recyclebin中的对象导致，递归delete from RECYCLEBIN$，因没有合适的索引走full scan，正常情况下没有影响，但该客户的这套库SYS.RECYCLEBIN$竟然达到700M，最终导致了该问题。

这里在我的测试环境中，模拟重现该问题。

?

测试过程

1. 清空回收

?

SQL> purge dba_recyclebin;

DBA Recyclebin purged.

?

2. 创建测试表空间

?

SQL> create tablespace testtbs datafile '/home/oracle/data/testtbs.dbf' size 10m;

Tablespace created.

SQL> @df

?

TABLESPACE_NAME TotalMB UsedMB FreeMB % Used Ext Used

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

SYSAUX 350 328 22 94% YES |################### |

SYSTEM 280 271 9 97% YES |####################|

TBS 20 17 3 85% NO |################# |

TBS2 10 2 8 20% NO |#### |

TEMP 36 -64 100 -177% YES ||

TESTTBS 10 1 9 10% NO |## |

UNDOTBS1 100 48 52 48% YES |########## |

?

7 rows selected.

SQL>

?

3. 创建3个测试表

?

tmp1,tmp2 10000条记录

tmp3 空表

SQL> create table test.tmp1 tablespace testtbs as select * from dba_objects where rownum<=10000;

?

Table created.

SQL> SQL> create table test.tmp2 tablespace testtbs as select * from dba_objects where rownum<10000;

?

Table created.

SQL> SQL> create table test.tmp3 tablespace testtbs as select * from dba_objects where 1=0;

?

Table created.

?

4. 删除表 test.tmp1

?

SQL> drop table test.tmp1 ;

Table dropped.

?

5. insert sys.RECYCLEBIN$,把sys.RECYCLEBIN$ 撑大

?

SQL> insert into sys.RECYCLEBIN$ select t.* from sys.RECYCLEBIN$ t connect by level<2000000;

insert into sys.RECYCLEBIN$ select t.* from sys.RECYCLEBIN$ t connect by level<2000000

*

ERROR at line 1:

ORA-30009: Not enough memory for CONNECT BY operation

?

?

这个报错，无影响，达到撑大sys.RECYCLEBIN$的目的就行。

?

SQL> rollback;

Rollback complete.

SQL> @seg sys.RECYCLEBIN$

?

SEG_MB OWNER SEGMENT_NAME SEG_PART_NAME SEGMENT_TYPE SEG_TABLESPACE_NAME BLOCKS HDRFIL HDRBLK

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

136 SYS RECYCLEBIN$ TABLE SYSTEM 17408 13 34656

26 SYS RECYCLEBIN$_OBJ INDEX SYSTEM 3328 13 34680

23 SYS RECYCLEBIN$_TS INDEX SYSTEM 2944 13 34672

24 SYS RECYCLEBIN$_OWNER INDEX SYSTEM 3072 13 34664

?

6. 开启10046，insert test.tmp3 重现该递归清理回收站问题

?

SQL> oradebug setmypid

Statement processed.

SQL> oradebug event 10046 trace name context forever,level 12

Statement processed.

SQL> oradebug tracefile_name

/app/oracle/diag/rdbms/db19c/db19c/trace/db19c_ora_2604.trc

SQL> insert /*+gather_plan_statistics */into test.tmp3 select * from test.tmp2 ;

?

9999 rows created.

?

SQL> SQL> @x

Display execution plan for last statement for this session from library cache...

?

PLAN_TABLE_OUTPUT

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

SQL_ID 1ndf8zpn2bpsp, child number 0

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

insert /*+gather_plan_statistics */into test.tmp3 select * from

test.tmp2

?

Plan hash value: 1016474986

?

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

| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| A-Rows | A-Time | Buffers | Reads |

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

| 0 | INSERT STATEMENT | | 1 | | |

?

?

?

从上面的执行计划看到逻辑读2989，这是一个正常值。

?

继续insert数据，直到表空间不够递归清理回收站

SQL> insert /*+gather_plan_statistics */into test.tmp3 select * from test.tmp2 ;

9999 rows created.

SQL> insert /*+gather_plan_statistics */into test.tmp3 select * from test.tmp2 ;

9999 rows created.

SQL> insert /*+gather_plan_statistics */into test.tmp3 select * from test.tmp2 ;

9999 rows created.

SQL> @x

Display execution plan for last statement for this session from library cache...

PLAN_TABLE_OUTPUT

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

SQL_ID 1ndf8zpn2bpsp, child number 0

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

insert /*+gather_plan_statistics */into test.tmp3 select * from

test.tmp2

?

Plan hash value: 1016474986

?

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

| Id | Operation | Name | Starts | E-Rows |E-Bytes| Cost (%CPU)| A-Rows | A-Time | Buffers | Reads |

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

| 0 | INSERT STATEMENT | | 1 | |

?

这次insert逻辑读为36872，是正常INSERT逻辑读2989的10倍以上 !!!

?

SQL> oradebug event 10046 trace name context off

Statement processed.

?

7. 观察10046递归sql

?

[oracle@test ~]$ tkprof /app/oracle/diag/rdbms/db19c/db19c/trace/db19c_ora_2604.trc tk.txt

?

TKPROF: Release 19.0.0.0.0 - Development on Wed Nov 18 20:43:10 2020

?

Copyright (c) 1982, 2019, Oracle and/or its affiliates. All rights reserved.

?

sql_id b52m6vduutr8j

delete from RecycleBin$ where bo=:1

?

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

?

SQL ID: b52m6vduutr8j Plan Hash: 716146596

?

delete from RecycleBin$

where

bo=:1

?

call count cpu elapsed disk query current rows

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

Parse 1 0.00 0.00 0 0 0 0

Execute 1 0.13 0.13 15807 16888 13 1

Fetch 0 0.00 0.00 0 0 0 0

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

total 2 0.13 0.13 15807 16888 13 1

?

Misses in library cache during parse: 1

Misses in library cache during execute: 1

Optimizer mode: CHOOSE

Parsing user id: SYS (recursive depth: 1)

Number of plan statistics captured: 1

?

Rows (1st) Rows (avg) Rows (max) Row Source Operation

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

0 0 0 DELETE RECYCLEBIN$ (cr=16888 pr=15807 pw=0 time=131249 us starts=1)

1 1 1 TABLE ACCESS FULL RECYCLEBIN$ (cr=16888 pr=15801 pw=0 time=130870 us starts=1 cost=2 size=52 card=1)

?

Elapsed times include waiting on following events:

Event waited on Times Max. Wait Total Waited

---------------------------------------- Waited ---------- ------------

db file sequential read 30 0.00 0.00

db file scattered read 1352 0.00 0.02

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

?

可以从trace中看到这样一条SQL,执行了一次，full scan,逻辑读16888，加上其它一些递归sql最终导致insert 逻辑读暴增！

?

表空间紧张，递归清理回收站大概逻辑

使用以下SQL查询该表空间中可以清理的回收站对象。按dropscn排序，最小drop的最先清理。

select obj#, type#, flags, related, bo, purgeobj, con# from RecycleBin$ where ts#=:1 and to_number(bitand(flags, 16)) = 16 order by dropscn

?

2. purge相关段

?

3. delete RecycleBin$

delete from RecycleBin$ where bo=:1

?

?

解决方法

mos上有一遍说明了purge时该递归sql的性能问题，并建议在RecycleBin$(bo)上创建索引。

Purging RECYCLEBIN Running Fosrever (Doc ID 2284986.1)

Create new index on bo column:

create index RecycleBin$_bo on RecycleBin$(bo);

?

?

2. Gather stats on RecycleBin$ table and indexes:

exec dbms_stats.gather_table_stats(ownname=>'SYS',tabname=>'RecycleBin#39;, cascade=>TRUE);

?

墨天轮原文链接：https://www.modb.pro/db/40753

作者

范计杰，云和恩墨技术顾问，5年大型ORACLE数据库维护经验，擅长性能调优、故障处理等。

?