[原创]SMON导致数据库产生大量归档日志_MySQL, Oracle及数据库讨论区_Weblogic技术|Tuxedo技术|中间件技术|Oracle论坛|JAVA论坛|Linux/Unix技术|hadoop论坛_联动北方技术论坛  
网站首页 | 关于我们 | 服务中心 | 经验交流 | 公司荣誉 | 成功案例 | 合作伙伴 | 联系我们 |
联动北方-国内领先的云技术服务提供商
»  游客             当前位置:  论坛首页 »  自由讨论区 »  MySQL, Oracle及数据库讨论区 »
总帖数
2
每页帖数
101/1页1
返回列表
0
发起投票  发起投票 发新帖子
查看: 604 | 回复: 1   主题: [原创]SMON导致数据库产生大量归档日志        上一篇   下一篇 
xiaogang.xu
注册用户
等级:上士
经验:251
发帖:13
精华:0
注册:1970-1-1
状态:离线
发送短消息息给xiaogang.xu 加好友    发送短消息息给xiaogang.xu 发消息
发表于: IP:您无权察看 2016-8-10 15:13:09 | [全部帖] [楼主帖] 楼主

一、背景

XX系统数据库201317日归档日志增长异常,导致数据库宕机。

 

二、故障分析

1、数据库归档目录

归档目录为/arch1/arch2,每个50G

 

2、数据库alert<sid>.log分析

查看相应时间点的数据库运行日志,除了因归档目录满导致归档失败,并未有其他有用信息。

Errors in file /oracle/admin/landingbj/bdump/landingbj1_arc0_856396.trc:

ORA-19502: write error on file "/arch1/landingbj_1_6282_729960074.arc", blockno 350209 (blocksize=512)

ORA-27063: number of bytes read/written is incorrect

IBM AIX RISC System/6000 Error: 28: No space left on device

 

3、归档日志生成情况

下条语句是检查每天归档日志的生成量,能反映出归档日志生成的总体概况

SELECT TRUNC(COMPLETION_TIME),

       ROUND(SUM(BLOCKS * BLOCK_SIZE) / 1024 / 1024) AS "SIZE(M)"

  FROM V$ARCHIVED_LOG

 GROUP BY TRUNC(COMPLETION_TIME)

 ORDER BY TRUNC(COMPLETION_TIME) Desc

TRUNC(COMPLETION_TIME)

SIZE(M)

2013-01-09

90948

2013-01-08

141525

2013-01-07

60097

2013-01-06

9372

2013-01-05

14269

2013-01-04

13069

2013-01-03

12247

2013-01-02

15204

2013-01-01

22688

2012-12-31

22252

2012-12-30

20220

2012-12-29

17328

2012-12-28

18122

2012-12-27

20444

2012-12-26

13985

2012-12-25

15731

2012-12-24

15254

2012-12-23

6412

2012-12-22

8281

2012-12-21

11575

2012-12-20

13466

2012-12-19

12616

2012-12-18

15010

2012-12-17

14144

2012-12-16

5606

2012-12-15

5287

2012-12-14

9693

2012-12-13

9529

2012-12-12

9227

2012-12-11

12445

2012-12-10

8134

平时每天归档日志产生量在20G以下,从17日起归档生成出现异常,达到近60G8日达到近140G

 

下条语句检查每个线程每天每小时的归档日志生成量

SELECT THREAD#,
       A.TTIME,
       SUM(C8) "08",
       SUM(C9) "09",
       SUM(C10) "10",
       SUM(C11) "11",
       SUM(C12) "12",
       SUM(C13) "13",
       SUM(C14) "14",
       SUM(C15) "15",
       SUM(C16) "16",
       SUM(C17) "17",
       SUM(C18) "18",
       SUM(C0) "00",
       SUM(C1) "01",
       SUM(C2) "02",
       SUM(C3) "03",
       SUM(C4) "04",
       SUM(C5) "05",
       SUM(C6) "06" SUM(C7) "07",
       SUM(C19) "19",
       SUM(C20) "20",
       SUM(C21) "21",
       SUM(C22) "22",
       SUM(C23) "23"
  FROM (SELECT THREAD#,
               TTIME,
               DECODE(TTHOUR, '00', 1, 0) C0,
               DECODE(TTHOUR, '01', 1, 0) C1,
               DECODE(TTHOUR, '02', 1, 0) C2,
               DECODE(TTHOUR, '03', 1, 0) C3,
               DECODE(TTHOUR, '04', 1, 0) C4,
               DECODE(TTHOUR, '05', 1, 0) C5,
               DECODE(TTHOUR, '06', 1, 0) C6,
               DECODE(TTHOUR, '07', 1, 0) C7,
               DECODE(TTHOUR, '08', 1, 0) C8,
               DECODE(TTHOUR, '09', 1, 0) C9,
               DECODE(TTHOUR, '10', 1, 0) C10,
               DECODE(TTHOUR, '11', 1, 0) C11,
               DECODE(TTHOUR, '12', 1, 0) C12,
               DECODE(TTHOUR, '13', 1, 0) C13,
               DECODE(TTHOUR, '14', 1, 0) C14,
               DECODE(TTHOUR, '15', 1, 0) C15,
               DECODE(TTHOUR, '16', 1, 0) C16,
               DECODE(TTHOUR, '17', 1, 0) C17,
               DECODE(TTHOUR, '18', 1, 0) C18,
               DECODE(TTHOUR, '19', 1, 0) C19,
               DECODE(TTHOUR, '20', 1, 0) C20,
               DECODE(TTHOUR, '21', 1, 0) C21,
               DECODE(TTHOUR, '22', 1, 0) C22,
               DECODE(TTHOUR, '23', 1, 0) C23
          FROM (SELECT THREAD#,
                       TO_CHAR(FIRST_TIME, 'YYYY-MM-DD') TTIME,
                       TO_CHAR(FIRST_TIME, 'HH24') TTHOUR
                  FROM V$LOG_HISTORY
                 WHERE (SYSDATE - FIRST_TIME < 30))) A
 GROUP BY THREAD#, TTIME
 ORDER BY TTIME DESC

图片1.png 

限于篇幅,省略部分记录。

实例11721点开始就增长异常了,1810:00-21:00增长极快,每小时都有7G以上归档日志产生。

 

下条语句检查哪些session生成归档异常

select a.INST_ID,b.sid,round((b.VALUE)/1024/1024/1024) "GB" from gv$statname a , gv$sesstat b

where a.INST_ID=b.INST_ID and a.STATISTIC#=b.STATISTIC# and a.NAME='redo size' order by 3 desc

图片1.png 

限于篇幅,省略部分记录。

Sid=544是导致归档日志生成频繁的会话。

 

下条语句检查导致两个实例sid=544的详细信息

Select * From gv$session Where sid=544

图片1.png 

导致归档日志生成频繁的进程是SMON

 

4Oracle核心后台进程SMON介绍

System Monitor简称SMON,要完成所有“系统级”任务。它以系统级为出发点,这是一种数据库“垃圾收集器”。SMON所做的工作包括:

a、清理临时空间

b、合并空闲空间

c、执行RAC中失败节点的实例恢复

d、清理OBJ$

e、“离线”回滚段

 

5LogMiner分析归档日志

1)添加要分析的归档日志

begin

  dbms_logmnr.add_logfile(LogFileName => 'landingbj_2_5620_729960074.arc',

                          Options     => dbms_logmnr.new);

end;

/

 

2)使用在线数据字典分析

begin

  dbms_logmnr.start_logmnr(options => dbms_logmnr.DICT_FROM_ONLINE_CATALOG);

end;

/

 

3)查询分析结果

Select sql_redo From v$logmnr_contents

图片1.png 

限于篇幅,省略部分记录。

 

Select Count(*) From v$logmnr_contents Where sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'

类似select * from "SYS"."OBJ$" where ROWID = 'AAAAASAACAAAnU/ABv' for update;

的语句有2230413条,暂且将这样的语句标识为异常语句。

 

继续分析下面归档日志,按上面1)、2)、3)步执行

landingbj_2_5624_729960074.arc  类似异常语句有2131288条。

/arch1/landingbj_1_6661_729960074.arc  类似异常语句有2099627条。

/arch1/landingbj_1_6656_729960074.arc  类似异常语句有2176965条。

 

可见,SMON频繁执行类似

select * from "SYS"."OBJ$" where ROWID = 'AAAAASAACAAAnU/ABv' for update;

是导致归档日志频繁生成原因。

 

5sys.obj$for update语句分析

前面提到,SMON的其中一个作用是清理obj$数据字典基表。

OBJ$基表是一张低级数据字典表,该表几乎对库中的每个对象(表、索引、包、视图等)都包含有一行记录。很多情况下,这些条目所代表的对象是不存在的对象(non-existent),引起这种现象的一种可能的原因是对象本身已经被从数据库中删除了,但是对象条目仍被保留下来以满足消极依赖机制(negative dependency)。因为这些条目的存在会导致OBJ$表不断膨胀,这时就需要由SMON进程来删除这些不再需要的行。

SMON会在实例启动时以及启动后的每12个小时执行一次清理任务。

SMON清理obj$过程中会涉及下面语句:

select o.owner#,o.obj#,decode(o.linkname,null, decode(u.name,null,'SYS',

  u.name),o.remoteowner), o.name,o.linkname,o.namespace,o.subname

from

 user$ u, obj$ o where u.user#(+)=o.owner# and o.type#=:1 and not exists

  (select p_obj# from dependency$ where p_obj# = o.obj#) order by o.obj# for

  update

obj$基表字段的解释可以从sql.bsq文件中获得,关于type#的解释,我们可以从中得到:
图片1.png

type#=10表示的是non-existant类型的对象,SMON要清理的就是sys.obj$.type#=10的记录。

 

1923时,执行下面操作

分析landingbj_2_5620_729960074.arc归档日志,产生v$logmnr_contents

执行下面5条语句

Select count(1) From v$logmnr_contents Where sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'  

查询结果:1805063

 

Select count(a.obj#) From sys.obj$ a,v$logmnr_contents b 

Where b.sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'And a.type#<>10 And a.rowid=b.row_id  

查询结果为:0

 

Select count(b.scn) From sys.obj$ a,v$logmnr_contents b 

Where b.sql_redo Like 'select * from "SYS"."OBJ$" where ROWID =% for update;'And a.type#=10 And a.rowid=b.row_id  

查询结果:1785965

 

Select count(Distinct a.obj#) From sys.obj$ a,v$logmnr_contents b Where b.sql_redo Like 'select * from "SYS"."OBJ$" 

where ROWID =% for update;'And a.type#=10 And a.rowid=b.row_id 

 查询结果:440646

  

select count(1) from obj$ where (name,owner#) in ( select o.name,u.user# from user$ u, obj$ o

where u.user# (+)=o.owner# and o.type#=10 and not exists (select p_obj# from

dependency$ where p_obj# = o.obj#) );  

查询结果:440600

通过几个查询后能够判断:在v$logmnr_contents里存在的类似select * from "SYS"."OBJ$" where ROWID = 'AAAAASAACAAAnU/ABv' for update; 都是SMON清理obj$发出的,同时SMON需要清理的记录还有440600条。

 

11010:0010:30,分别查询两次下面语句,该语句的作用是SMON还需要清理obj$的记录。

select count(1) from obj$ where (name,owner#) in ( select o.name,u.user# from user$ u, obj$ o

where u.user# (+)=o.owner# and o.type#=10 and not exists (select p_obj# from

dependency$ where p_obj# = o.obj#) );   

得到的查询结果:408958条和407765条,可见,SMON清理obj$的速度是很慢的,结合923时查询结果(440646条),obj$10小时左右时间仅仅清理被4万条左右记录,速度较慢。

 

三、建议和总结

根据上面分析,17日归档日志频繁生成是由于oracle核心后台进程SMON导致,同时SMON清理sys.obj$速度极慢,极有可能触发BUG导致。

建议:

1)、适当增大归档目录空间大小,增加归档目录/arch1/arch2100G

2)、优化备份策略,及时备份归档日志并删除备份前的归档日志;

3)、联系oracle原厂工程师确认:SMON进程清理obj$为何会产生如此大量的归档日志,清理obj$的速度为何如此之慢,,是否触发BUG

4)、手动清理obj$,参考MOS文档,

SMON Consumes High CPU With Excessive Redo Log Generation [ID 1073704.1]

Smon Cleanup Preventing Job Processes From Executing [ID 340128.1]

 

这种方式存在一定的风险,因此在执行前,数据库必须做全备。具体步骤如下:

1、在参数文件中设置10052 event,来禁用smon清理obj$表的功能

EVENT="10052 trace name context forever, level 65535"

2、重启数据库到restricted模式。

3、通过下面的语句进行obj$表的清理

SQL> delete from obj$ where (name,owner#) in ( select o.name,u.user# from user$ u, obj$ o where u.user# (+)=o.owner# and o.type#=10 and not exists (select p_obj# from dependency$ where p_obj# = o.obj#) );

SQL> commit;

4、关闭数据库(必须shutdown abort

5、从参数文件中移除10052 event的相关设置

6、启动数据库,并实时监控数据库alert日志是否出现异常。

7、做个full export操作,验证数据库的稳固性。





赞(0)    操作        顶端 
联动小白
注册用户
等级:新兵
经验:61
发帖:0
精华:0
注册:2015-5-27
状态:离线
发送短消息息给联动小白 加好友    发送短消息息给联动小白 发消息
发表于: IP:您无权察看 2018-6-6 1:33:53 | [全部帖] [楼主帖] 2  楼

为了方便大家阅读,我对文章中命令来解释一下吧!

File-->as:File

User-->id:User

希望能对大家有帮助!^_^ By:坚持不懈的小白

-- 来自: 北京联动北方科技有限公司



赞(0)    操作        顶端 
总帖数
2
每页帖数
101/1页1
返回列表
发新帖子
请输入验证码: 点击刷新验证码
您需要登录后才可以回帖 登录 | 注册
技术讨论