一次DB time抖动发现的expdp的bug
最近收到一封报警邮件，提示还是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_JXDB_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_JXDB_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_JXDB_20151007', 'SYS');
kupprdp: worker process DW02 started with worker id=2, pid=316, OS id=6096
to execute - SYS.KUPW$WORKER.MAIN('EXP_JXDB_20151007', 'SYS');
kupprdp: worker process DW03 started with worker id=3, pid=318, OS id=6098
to execute - SYS.KUPW$WORKER.MAIN('EXP_JXDB_20151007', 'SYS');
kupprdp: worker process DW04 started with worker id=4, pid=322, OS id=6100
to execute - SYS.KUPW$WORKER.MAIN('EXP_JXDB_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/jxdb/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/jxdb/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/jxdb/redo02.log
Wed Oct 07 09:29:01 CST 2015
Thread 1 advanced to log sequence 78508 (LGWR switch)
可以从错误看出这个是在尝试做一个导出的任务时抛出了错误，那么对于这个错误的解释，在mos上查了一圈，发现有一个帖子比较相近
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还是很充足的，所以应该没有这类的问题。
sys@JXDB> 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从定时任务中去除。
############ 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_JXDB_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_JXDB_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_JXDB_20151007', 'SYS');
kupprdp: worker process DW02 started with worker id=2, pid=316, OS id=6096
to execute - SYS.KUPW$WORKER.MAIN('EXP_JXDB_20151007', 'SYS');
kupprdp: worker process DW03 started with worker id=3, pid=318, OS id=6098
to execute - SYS.KUPW$WORKER.MAIN('EXP_JXDB_20151007', 'SYS');
kupprdp: worker process DW04 started with worker id=4, pid=322, OS id=6100
to execute - SYS.KUPW$WORKER.MAIN('EXP_JXDB_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/jxdb/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/jxdb/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/jxdb/redo02.log
Wed Oct 07 09:29:01 CST 2015
Thread 1 advanced to log sequence 78508 (LGWR switch)
可以从错误看出这个是在尝试做一个导出的任务时抛出了错误，那么对于这个错误的解释，在mos上查了一圈，发现有一个帖子比较相近
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还是很充足的，所以应该没有这类的问题。
sys@JXDB> 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从定时任务中去除。
正文到此结束
热门推荐
相关文章
Loading...
![[HBLOG]公众号](http://www.liuhaihua.cn/img/qrcode_gzh.jpg)
