一次DB time抖动发现的expdp的bug(r6笔记第86天)

最近收到一封报警邮件,提示还是DB time突然提高,时间发生在早晨的时候,想必大过节的也不会有人这么卖力工作把数据库负载弄上去。

############ DB time抖动 被平均
ZABBIX-监控系统: 
------------------------------------
报警内容: DB time is too high
------------------------------------
报警级别: PROBLEM
------------------------------------
监控项目: DBtime:404 % 
------------------------------------ 
报警时间:2015.10.07-06:01:09

查看了一下快照得到的DB time,发现DB time已经被严重平均化。

Current Instance
~~~~~~~~~~~~~~~~
      DBID DB_NAME     INST_NUM INST_NAME
---------- --------- ---------- ----------------
 495508159 TESTDB               1 testdb
DB_NAME   BEGIN_SNAP   END_SNAP SNAPDATE                    LVL DURATION_MINS     DBTIME
--------- ---------- ---------- -------------------- ---------- ------------- ----------
TESTDB    75839      75840 07 Oct 2015 05:00             1            30          5
               75840      75841 07 Oct 2015 05:30             1            30          8
               75841      75842 07 Oct 2015 06:00             1            30         21
               75842      75843 07 Oct 2015 06:30             1            30          5
               75843      75844 07 Oct 2015 07:00             1            30          5
               75844      75845 07 Oct 2015 07:30             1            30          5
               75845      75846 07 Oct 2015 08:01             1            30          5
               75846      75847 07 Oct 2015 08:30             1            29          5
               75847      75848 07 Oct 2015 09:00             1            30          5
               75848      75848 07 Oct 2015 09:30             1            30          0

通过这个是看不出来数据库有明显的异常问题的,但是在短时间内确实出现了很高的抖动。我们来分析一下。

首先以快照的时间点为基准,查看在哪个时间段里是否有负载高的sql在运行。结果一抓还真是,占用了90%的比例,不得不让人怀疑

$ ksh showsnapsql.sh 75842
   SNAP_ID SQL_ID        EXECUTIONS_DELTA ELAPSED_TI PER_TOTAL
---------- ------------- ---------------- ---------- ----------
     75842 0rn7dhhuc1z2x                4 955s       91%
     75842 fydajknsuzadw           396470 23s        2%
     75842 520mkxqpf15q8           397806 11s        1%
     75842 0h6b2sajwb74n             2408 0s         0%
     75842 0k8522rmdzg4k              433 0s         0%

看看这个语句是什么来头。

$ ksh showsql.sh 0rn7dhhuc1z2x
HASH_VALUE PLAN_HASH_VALUE DISK_READS BUFFER_GETS      SORTS EXECUTIONS   CPU_TIME ELAPSED_TIME_S WAIT_TIME_EACH
---------- --------------- ---------- ----------- ---------- ---------- ---------- -------------- --------------
 885062749               0    4971881    12064454          0          4   56510410            277      220299792
SQL_FULLTEXT
----------------------------------------------------------------------------------------------------
 BEGIN
   SYS.KUPW$WORKER.MAIN('EXP_TESTDB_20151007', 'SYS');
 END;

语句是一个看似陌生的pl/sql调用,如果对这个部分心存疑虑,但是还是一知半解,我们来看看数据库日志,看看有什么发现。

可以看到黄色部分的错误。

Wed Oct 07 05:00:20 CST 2015
ALTER SYSTEM ARCHIVE LOG
Wed Oct 07 05:00:20 CST 2015
Thread 1 advanced to log sequence 78503 (LGWR switch)
  Current log# 1 seq# 78503 mem# 0: /U01/app/oracle/oradata/testdb/redo01.log
Wed Oct 07 05:00:25 CST 2015
ALTER SYSTEM ARCHIVE LOG
Wed Oct 07 05:00:25 CST 2015
Thread 1 advanced to log sequence 78504 (LGWR switch)
  Current log# 2 seq# 78504 mem# 0: /U01/app/oracle/oradata/testdb/redo02.log
Wed Oct 07 06:00:01 CST 2015
The value (30) of MAXTRANS parameter ignored.
kupprdp: master process DM00 started with pid=319, OS id=6066
         to execute - SYS.KUPM$MCP.MAIN('EXP_TESTDB_20151007', 'SYS', 'KUPC$C_1_20151007060002', 'KUPC$S_1_20151007060002', 0);
kupprdp: worker process DW01 started with worker id=1, pid=320, OS id=6074
         to execute - SYS.KUPW$WORKER.MAIN('EXP_TESTDB_20151007', 'SYS');
kupprdp: worker process DW02 started with worker id=2, pid=316, OS id=6096
         to execute - SYS.KUPW$WORKER.MAIN('EXP_TESTDB_20151007', 'SYS');
kupprdp: worker process DW03 started with worker id=3, pid=318, OS id=6098
         to execute - SYS.KUPW$WORKER.MAIN('EXP_TESTDB_20151007', 'SYS');
kupprdp: worker process DW04 started with worker id=4, pid=322, OS id=6100
         to execute - SYS.KUPW$WORKER.MAIN('EXP_TESTDB_20151007', 'SYS');
Wed Oct 07 06:00:35 CST 2015
Thread 1 advanced to log sequence 78505 (LGWR switch)
  Current log# 3 seq# 78505 mem# 0: /U01/app/oracle/oradata/testdb/redo03.log
Wed Oct 07 06:04:40 CST 2015
Thread 1 advanced to log sequence 78506 (LGWR switch)
  Current log# 1 seq# 78506 mem# 0: /U01/app/oracle/oradata/testdb/redo01.log
Wed Oct 07 07:55:56 CST 2015
Thread 1 advanced to log sequence 78507 (LGWR switch)
  Current log# 2 seq# 78507 mem# 0: /U01/app/oracle/oradata/testdb/redo02.log
Wed Oct 07 09:29:01 CST 2015
Thread 1 advanced to log sequence 78508 (LGWR switch)

可以从错误看出这个是在尝试做一个导出的任务时抛出了错误,那么对于这个错误的解释,在mos上查了一圈,发现有一个帖子比较相近

ORA-01017 When Running EXPDP From Enterprise Manager (文档 ID 467198.1)

oracle官方的解释是

The cause of this problem has been identified in Bug:5631628. It is caused by using an user account whose password contains a '$'.

可能是用户密码中含有特殊字符导致的,但是我们这边设定的sys用户密码还没有用这个特殊字符,其他用户是否密码是否含有特殊字符自己也无从考证,因为安 全和职责的考虑,应用的数据库用户密码对dba是不透明的。但是可以确定的是这个问题是基于EM导致的,而我们使用EM还没有设定scheduler之类 的任务,所以还是不大可能。

然后怀疑是否为连接数超出导致的副作用,结果一看这个库的process还是很充足的,所以应该没有这类的问题。

> show parameter process
NAME                                 TYPE        VALUE
------------------------------------ ----------- ------------------------------
aq_tm_processes                      integer     0
db_writer_processes                  integer     2
gcs_server_processes                 integer     0
job_queue_processes                  integer     10
log_archive_max_processes            integer     2
processes                            integer     1500

继续找,最后发现一个bug和现在的问题比较符合,

DataPump Export/Import Generate Messages "The Value (30) Of Maxtrans Parameter Ignored" in Alert Log (文档 ID 455021.1)

就因为那个警告很相符,发现还有这么一个bug.

按照文档中提供的思路自己在其它环境测试了一下,创建了一个表指定maxtrans为25,结果表创建成功.

SQL> create table test001 (col001 number) initrans 10 maxtrans 25;

但是立刻查看alert日志,发现了下面一段警告

#######
Wed Oct 07 16:04:53 CST 2015
The value (25) of MAXTRANS parameter ignored.

带着一丝疑虑查看了是否存在遗留问题,发现还不少,之前有一些遗留的中间expdp的job表和中间表。

SQL> select table_name from user_tables where table_name like 'EXP%';
TABLE_NAME
------------------------------
EXP_TESTDB_20131204
EXP_TESTDB_20131027
EXP_TESTDB_20130806
EXP_TESTDB_20130705
EXP_TESTDB_20130704
EXP_TESTDB_20130703
EXP_TESTDB_20120328
EXP_TESTDB_20120325
EXP_TESTDB_20120323
EXP_TESTDB_20120322
EXP_TESTDB_20120321
EXPPKGOBJ$
EXPPKGACT$
EXPIMP_TTS_CT$
EXPDEPOBJ$
EXPDEPACT$
EXPACT$

目前为止倒没有发现相关的ora错误,但是也是隐患,还是果断删除。

好了,问题已经明确了,是在10g使用expdp导出的一个bug,为什么会在早晨有这个expdp的任务呢。

经过一番排查发现,这台服务器上设置了一个crontab,会在每天早晨做一个全库expdp备份,同时还有rman的全库备份,听起来是有冗余吧,所以也算是遗留问题,有了备库有了rman备库已经足够了,这个时候也可以考虑不用这个逻辑备份了。

那么我印象中还有一些库也是10gR2的,但是似乎从来没有收到过任何的ora错误。这是为什么呢。还是因为这些库中只有rman备库,没有做expdp的全库备份。带着好奇心在一台负载很低的10g库上尝试了一下expdp全库备份,结果发现ORA错误还是出现了。

Tue Oct 06 03:30:27 CST 2015
Thread 1 advanced to log sequence 2170 (LGWR switch)
  Current log# 1 seq# 2170 mem# 0: /U01/app/oracle/oradata/acctestdb/redo01.log
Tue Oct 06 07:23:58 CST 2015
Thread 1 advanced to log sequence 2171 (LGWR switch)
  Current log# 2 seq# 2171 mem# 0: /U01/app/oracle/oradata/acctestdb/redo02.log
Wed Oct 07 01:10:35 CST 2015
Thread 1 advanced to log sequence 2172 (LGWR switch)
  Current log# 3 seq# 2172 mem# 0: /U01/app/oracle/oradata/acctestdb/redo03.log
Wed Oct 07 03:30:01 CST 2015
The value (30) of MAXTRANS parameter ignored.
kupprdp: master process DM00 started with pid=27, OS id=22201
         to execute - SYS.KUPM$MCP.MAIN('SYS_EXPORT_FULL_01', 'SYS', 'KUPC$C_1_20151007033001', 'KUPC$S_1_20151007033001', 0);
kupprdp: worker process DW01 started with worker id=1, pid=29, OS id=22203
         to execute - SYS.KUPW$WORKER.MAIN('SYS_EXPORT_FULL_01', 'SYS');
Wed Oct 07 09:00:12 CST 2015
Thread 1 advanced to log sequence 2173 (LGWR switch)
  Current log# 1 seq# 2173 mem# 0: /U01/app/oracle/oradata/acctestdb/redo01.log   

所以分析了这个问题,也进一步论证了,这个问题对于实际的数据还是没有直接影响,但是根据实际需要,其实还是有备库,rman备份就够了。

所以这个问题就需要进一步进行确认,把expdp从定时任务中去除。

原文发布于微信公众号 - 杨建荣的学习笔记(jianrong-notes)

原文发表时间:2015-10-12

本文参与腾讯云自媒体分享计划,欢迎正在阅读的你也加入,一起分享。

发表于

我来说两句

0 条评论
登录 后参与评论

相关文章

来自专栏Android源码框架分析

Android后台杀死系列之二:ActivityManagerService与App现场恢复机制

本篇是Android后台杀死系列的第二篇,主要讲解ActivityMangerService是如何恢复被后台杀死的进程的(基于4.3 ),在开篇 Fragmen...

78940
来自专栏杨建荣的学习笔记

三封报警邮件的分析(r6笔记第95天)

今天收到3封报警邮件,从邮件内容中的报警情况来看,还是比较反常的。需要引起关注,找到原因处理。 这个库是一个历史库,库中的数据非常庞大,几十亿数据的表还是有好几...

29240
来自专栏Kubernetes

kube-proxy工作原理

kube-proxy & service必要说明 说到kube-proxy,就不得不提到k8s中service,下面对它们两做简单说明: kube-proxy其...

1.9K120
来自专栏杨建荣的学习笔记

ASM无法启动的问题分析(二)(r7笔记第88天)

第一篇的内容可以参考。ASM无法启动的问题分析(一),有不少的朋友给了一些建议,我也糅合了进来。一并感谢。 当然重启服务发现CSSD服务是Online,但是AS...

415100
来自专栏Kubernetes

原 荐 Flannel是如何工作的

Author: xidianwangtao@gmail.com 概述 最近我们的TaaS平台遇到很多的网络问题,事实证明“contiv + ovs + v...

1.7K110
来自专栏FreeBuf

EE 4GEE Mini本地提权漏洞(CVE-2018-14327)分析

我在前段时间从买了一个4G调制解调器。这是一个便携式4G WiFi移动宽带调制解调器。有一天,我查看了安装在电脑上的用于故障排除的服务,我看到了一个奇怪的服务,...

10230
来自专栏乐沙弥的世界

使用 SQLNET.EXPIRE_TIME 清除僵死连接

    数据库连接的客户端异常断开后,其占有的相应并没有被释放,如从v$session视图中依旧可以看到对应的session处于inactive,且对应的服务器...

32820
来自专栏gaoqin31

基于php+shell的发布系统

  一个比较完善的发布系统首先肯定是要能发布文件,其次当发布出现问题时要能支持撤销,避免长时间无法解决问题影响产品的正常运营。 对于发布脚本语言如PHP,she...

15820
来自专栏向治洪

android PakageManagerService启动流程分析

PakageManagerService的启动流程图 ? 1.PakageManagerService概述 PakageManagerService是andro...

574100
来自专栏码匠的流水账

解决jd-gui在Sierra下闪退问题

在升级了mac操作系统到Sierra版本之后,之前的jd-gui就闪退了,本文就讲述一下如何解决这个问题。

28410

扫码关注云+社区

领取腾讯云代金券