ITPUB论坛-中国最专业的IT技术社区

 手机号登录  找回密码
 注册
查看: 1263|回复: 2

[原创] 高频率日志切换案例

[复制链接]
论坛徽章:
10
目光如炬
日期:2018-01-14 22:00:00目光如炬
日期:2017-12-17 22:00:00目光如炬
日期:2017-11-26 22:00:00火眼金睛
日期:2017-09-30 22:00:01目光如炬
日期:2017-09-03 22:00:01火眼金睛
日期:2017-09-01 17:00:07目光如炬
日期:2017-08-27 22:00:01目光如炬
日期:2017-08-20 22:00:00娜美
日期:2017-06-26 15:18:15火眼金睛
日期:2018-02-28 22:00:00
发表于 2018-3-29 18:03 | 显示全部楼层 |阅读模式
作者简介:
----------------------------------------------------
@ 孙显鹏,海天起点oracle技术专家,十年从业经验
@ 精通oracle内部原理,擅长调优和解决疑难问题
@ 致力于帮助客户解决生产中的问题,提高生产效率。
@ 爱好:书法,周易,中医。微信:sunyunyi_sun
@ 易曰:精义入神,以致用也!
@ 调优乃燮理阴阳何其难也!
-----------------------------------------------------


现象:客户反应前台应用缓慢,该现象间接性出现,后台大量出现Checkpoint not complete,运维人员添加了12个日志组,问题
依旧,寻求帮助。

redo 切换频率:

Inst
id  Day      00   02   04   06   07   08   09   10   11   12   13   14   15   16   17   18   19   20   21   22   23
---- ------ ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
   1 03-24     0    0    0    0    0    0    0    0    0    0    0    0    0  240    0    0    0  240    0    0    4
     03-25   247    1  242    0    0  240    0    0    0  240    0    0    0  240    0    0    0  239    0    0    4
     03-26   250    0  242    0    0  241    0    0    0  240    0    0    0  239    0    0    0  240    0    0    4
     03-27   241    0  242    0    0  238    0    6    3  240    0    0    0  240    0    0    0  240    0    0    4
     03-28   241    1  242    0    0  240    1    5    3  239    0    0    1  240    0    0    0  240    0    0    4
     03-29   243    1  243    0    0  240   22    0    0  240    2    0    0    0    0    0    0    0    0    0    0
   2 03-24     0    0    0    0    0    0    0    0    0    0    0    0    0  240    0    0    0  240    0    0    4
     03-25   247    1  242    0    0  240    0    0    0  240    0    0    0  240    0    0    0  239    0    0    4
     03-26   250    0  242    0    0  241    0    0    0  240    0    0    0  239    0    0    0  240    0    0    4
     03-27   241    0  242    0    0  238    0    6    3  240    0    0    0  240    0    0    0  240    0    0    4
     03-28   241    1  242    0    0  240    1    5    3  239    0    0    1  240    0    0    0  240    0    0    4
     03-29   243    1  243    0    0  240   22    0    0  240    2    0    0    0    0    0    0    0    0    0    0
****        ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
Ave:         204    1  202    0    0  200    4    2    1  200    0    0    0  200    0    0    0  200    0    0    3
Min:           0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0
Max:         250    1  243    0    0  241   22    6    3  240    2    0    1  240    0    0    0  240    0    0    4


归档日志:

Time                   SIZE(GB) Per_hour(GB) Per_min(MB)
-------------------- ---------- ------------ -----------
2018-03-29                    1            0           1
2018-03-28                    4            0           2
2018-03-27                    3            0           2
2018-03-26                    1            0           1
2018-03-25                    1            0           1
2018-03-24                    1            0           0
2018-03-23                    1            0           1
2018-03-22                    0            0           0

8 rows selected.
每天最大4g的归档,怎么如此频繁的日志切换呢?肯定是人为触发了日志切换。

看了看crontab 写法:
* */4 * * * /home/oracle/arch.sh >> /home/oracle/arch.log
每隔四小时,该小时中每分钟备份一次归档,备份脚本中存在 alter system archive log current命令。
怪不得上面统计的0点4点8点12点....每小时都切换240次归档呀!
可是这个240次是怎么产生的,alter system archive log current只是集群范围内做一次日志切换,
两个节点,应该是120才对呀.

实际做一次看看:

    GROUP#    THREAD#  SEQUENCE#     SIZEMB    MEMBERS ARCHIVED  STATUS     MEMBER
---------- ---------- ---------- ---------- ---------- --------- ---------- --------------------------------------------------
         1          1     168175       1024          2 NO        CURRENT    +DATA/ydzydb/onlinelog/group_1.271.972034493
         1          1     168175       1024          2 NO        CURRENT    +DATA/ydzydb/onlinelog/group_1.272.972034511
         2          1     168173       1024          2 YES       INACTIVE   +DATA/ydzydb/onlinelog/group_2.266.972034521
         2          1     168173       1024          2 YES       INACTIVE   +DATA/ydzydb/onlinelog/group_2.265.972034569
         3          2     168091       1024          2 YES       INACTIVE   +REDO_LOG/ydzydb/onlinelog/group_3.256.972034249
         3          2     168091       1024          2 YES       INACTIVE   +REDO_LOG/ydzydb/onlinelog/group_3.257.972034279
         4          2     168092       1024          2 YES       ACTIVE     +REDO_LOG/ydzydb/onlinelog/group_4.258.972034289
         4          2     168092       1024          2 YES       ACTIVE     +REDO_LOG/ydzydb/onlinelog/group_4.259.972034299
         5          1     168174       1024          2 YES       ACTIVE     +DATA/ydzydb/onlinelog/group_5.262.972034649
         5          1     168174       1024          2 YES       ACTIVE     +DATA/ydzydb/onlinelog/group_5.261.972034663
         6          2     168093       1024          2 NO        CURRENT    +REDO_LOG/ydzydb/onlinelog/group_6.260.972034699
         6          2     168093       1024          2 NO        CURRENT    +REDO_LOG/ydzydb/onlinelog/group_6.261.972034711

12 rows selected.

alter system archive log current

SQL> /

    GROUP#    THREAD#  SEQUENCE#     SIZEMB    MEMBERS ARCHIVED  STATUS     MEMBER
---------- ---------- ---------- ---------- ---------- --------- ---------- --------------------------------------------------
         1          1     168175       1024          2 YES       ACTIVE     +DATA/ydzydb/onlinelog/group_1.271.972034493
         1          1     168175       1024          2 YES       ACTIVE     +DATA/ydzydb/onlinelog/group_1.272.972034511
         2          1     168176       1024          2 NO        CURRENT    +DATA/ydzydb/onlinelog/group_2.266.972034521
         2          1     168176       1024          2 NO        CURRENT    +DATA/ydzydb/onlinelog/group_2.265.972034569
         3          2     168094       1024          2 NO        CURRENT    +REDO_LOG/ydzydb/onlinelog/group_3.256.972034249
         3          2     168094       1024          2 NO        CURRENT    +REDO_LOG/ydzydb/onlinelog/group_3.257.972034279
         4          2     168092       1024          2 YES       ACTIVE     +REDO_LOG/ydzydb/onlinelog/group_4.258.972034289
         4          2     168092       1024          2 YES       ACTIVE     +REDO_LOG/ydzydb/onlinelog/group_4.259.972034299
         5          1     168174       1024          2 YES       ACTIVE     +DATA/ydzydb/onlinelog/group_5.262.972034649
         5          1     168174       1024          2 YES       ACTIVE     +DATA/ydzydb/onlinelog/group_5.261.972034663
         6          2     168093       1024          2 YES       ACTIVE     +REDO_LOG/ydzydb/onlinelog/group_6.260.972034699
         6          2     168093       1024          2 YES       ACTIVE     +REDO_LOG/ydzydb/onlinelog/group_6.261.972034711

12 rows selected.
select *
from v$log_history a
where first_time > sysdate - 1/24

     RECID      STAMP    THREAD#  SEQUENCE# FIRST_CHANGE# NEXT_CHANGE# RESETLOGS_CHANGE# RESETLOGS_TIME
---------- ---------- ---------- ---------- ------------- ------------ ----------------- --------------
    336267  972061936          1     168175     385516032    385516633            925702 03/28 17:54:44
    336268  972061938          2     168093     385516029    385516637            925702 03/28 17:54:44

SQL> select *
  2  from gv$log_history a
  3  where first_time > sysdate - 1/24
  4  /

   INST_ID      RECID      STAMP    THREAD#  SEQUENCE# FIRST_CHANGE# FIRST_TIM NEXT_CHANGE# RESETLOGS_CHANGE# RESETLOGS
---------- ---------- ---------- ---------- ---------- ------------- --------- ------------ ----------------- ---------
         2     336267  972061936          1     168175     385516032 29-MAR-18    385516633            925702 28-MAR-17
         2     336268  972061938          2     168093     385516029 29-MAR-18    385516637            925702 28-MAR-17
         1     336267  972061936          1     168175     385516032 29-MAR-18    385516633            925702 28-MAR-17
         1     336268  972061938          2     168093     385516029 29-MAR-18    385516637            925702 28-MAR-17

哦 gv$log_history 视图重复记录的日志切换数。

所以我的脚本有问题应该查询v$log_history就准确了:

   THREAD# Day      00   02   04   06   07   08   09   10   11   12   13   14   15   16   17   18   19   20   21   22   23
---------- ------ ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
         1 03-24     0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0  120    0    0    2
         1 03-25   121    1  122    0    0  120    0    0    0  120    0    0    0  120    0    0    0  120    0    0    2
         1 03-26   129    0  122    0    0  120    0    0    0  120    0    0    0  120    0    0    0  120    0    0    2
         1 03-27   121    0  122    0    0  120    0    5    1  120    0    0    0  120    0    0    0  120    0    0    2
         1 03-28   121    1  122    0    0  120    1    4    1  120    0    0    1  120    0    0    0  120    0    0    2
         1 03-29   122    0  122    0    0  120   18    0    0  120    2    3    0    2    1    0    0    0    0    0    0
         2 03-24     0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0  120    0    0    2
         2 03-25   126    0  120    0    0  120    0    0    0  120    0    0    0  120    0    0    0  119    0    0    2
         2 03-26   121    0  120    0    0  121    0    0    0  120    0    0    0  119    0    0    0  120    0    0    2
         2 03-27   120    0  120    0    0  118    0    1    2  120    0    0    0  120    0    0    0  120    0    0    2
         2 03-28   120    0  120    0    0  120    0    1    2  119    0    0    0  120    0    0    0  120    0    0    2
         2 03-29   121    1  121    0    0  120    4    0    0  120    2    3    0    2    1    0    0    0    0    0    0
                  ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
Ave:               102    0  101    0    0  100    2    1    1  100    0    1    0   80    0    0    0  100    0    0    2
Min:                 0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0    0
Max:               129    1  122    0    0  121   18    5    2  120    2    3    1  120    1    0    0  120    0    0    2


这样数字就对了,每小时60分钟,2个节点,每分钟2次日志切换,那么没小时就是120次。

问题找到了修改crontab 的频率,每隔四小时执行归档备份:

0 */4 * * * /home/oracle/arch.sh >> /home/oracle/arch.log

修改后的日志切换频率:
   THREAD# Day      00   02   04   06   07   08   09   10   11   12   13   14   15   16   17   18   19   20   21   22   23
---------- ------ ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ---- ----
         1 03-29   122    0  122    0    0  120   18    0    0  120    2    3    0    2    1    0    0    0    0    0    0
         2 03-29   121    1  121    0    0  120    4    0    0  120    2    3    0    2    1    0    0    0    0    0    0

从13点开始就正常了。

建议没小时15次日志切换

其实在他自己备份归档的目录就可以看出来问题,归档日志大小不一致,有的才3m多就切换了,如下所示:

-rw-r----- 1 oracle asmadmin   3741696 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203042_92sv0cur_1_1
-rw-r----- 1 oracle asmadmin  64590336 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203041_91sv0cur_1_1
-rw-r----- 1 oracle asmadmin      7168 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203043_93sv0cur_1_1
-rw-r----- 1 oracle asmadmin     86016 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203044_94sv0cut_1_1
-rw-r----- 1 oracle asmadmin     39936 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203045_95sv0cuu_1_1
-rw-r----- 1 oracle asmadmin      6656 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203046_96sv0cuu_1_1
-rw-r----- 1 oracle asmadmin      9728 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203047_97sv0cuv_1_1
-rw-r----- 1 oracle asmadmin      8192 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203048_98sv0cuv_1_1
-rw-r----- 1 oracle asmadmin  15366144 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203050_9asv0cv0_1_1
-rw-r----- 1 oracle asmadmin 302582272 Mar 29 12:00 arch_level_0_YDZYDB_20180329_203049_99sv0cv0_1_1
-rw-r----- 1 oracle asmadmin    545792 Mar 29 12:01 arch_level_0_YDZYDB_20180329_203051_9bsv0d0p_1_1
-rw-r----- 1 oracle asmadmin     47616 Mar 29 12:01 arch_level_0_YDZYDB_20180329_203052_9csv0d0p_1_1
-rw-r----- 1 oracle asmadmin     32256 Mar 29 12:02 arch_level_0_YDZYDB_20180329_203053_9dsv0d2e_1_1
-rw-r----- 1 oracle asmadmin      4608 Mar 29 12:02 arch_level_0_YDZYDB_20180329_203054_9esv0d2e_1_1
-rw-r----- 1 oracle asmadmin     47104 Mar 29 12:03 arch_level_0_YDZYDB_20180329_203055_9fsv0d4f_1_1
-rw-r----- 1 oracle asmadmin      4096 Mar 29 12:03 arch_level_0_YDZYDB_20180329_203056_9gsv0d4f_1_1
-rw-r----- 1 oracle asmadmin     47616 Mar 29 12:04 arch_level_0_YDZYDB_20180329_203057_9hsv0d6d_1_1
-rw-r----- 1 oracle asmadmin     25600 Mar 29 12:04 arch_level_0_YDZYDB_20180329_203058_9isv0d6d_1_1
-rw-r----- 1 oracle asmadmin      3072 Mar 29 12:04 arch_level_0_YDZYDB_20180329_203059_9jsv0d6d_1_1
-rw-r----- 1 oracle asmadmin     76288 Mar 29 12:05 arch_level_0_YDZYDB_20180329_203060_9ksv0d88_1_1
-rw-r----- 1 oracle asmadmin     19968 Mar 29 12:05 arch_level_0_YDZYDB_20180329_203061_9lsv0d88_1_1
-rw-r----- 1 oracle asmadmin     33280 Mar 29 12:06 arch_level_0_YDZYDB_20180329_203062_9msv0da2_1_1
-rw-r----- 1 oracle asmadmin     86016 Mar 29 12:06 arch_level_0_YDZYDB_20180329_203063_9nsv0da2_1_1
-rw-r----- 1 oracle asmadmin    129536 Mar 29 12:07 arch_level_0_YDZYDB_20180329_203064_9osv0dbu_1_1
-rw-r----- 1 oracle asmadmin      6656 Mar 29 12:07 arch_level_0_YDZYDB_20180329_203065_9psv0dbu_1_1
-rw-r----- 1 oracle asmadmin     30208 Mar 29 12:08 arch_level_0_YDZYDB_20180329_203066_9qsv0ddp_1_1
-rw-r----- 1 oracle asmadmin      4096 Mar 29 12:08 arch_level_0_YDZYDB_20180329_203067_9rsv0ddp_1_1
-rw-r----- 1 oracle asmadmin     43520 Mar 29 12:09 arch_level_0_YDZYDB_20180329_203068_9ssv0dfm_1_1
-rw-r----- 1 oracle asmadmin      3584 Mar 29 12:09 arch_level_0_YDZYDB_20180329_203069_9tsv0dfm_1_1
-rw-r----- 1 oracle asmadmin     56832 Mar 29 12:10 arch_level_0_YDZYDB_20180329_203070_9usv0dhi_1_1
-rw-r----- 1 oracle asmadmin     74752 Mar 29 12:10 arch_level_0_YDZYDB_20180329_203071_9vsv0dhi_1_1
-rw-r----- 1 oracle asmadmin      3072 Mar 29 12:10 arch_level_0_YDZYDB_20180329_203072_a0sv0dhi_1_1
-rw-r----- 1 oracle asmadmin    385024 Mar 29 12:11 arch_level_0_YDZYDB_20180329_203073_a1sv0djd_1_1


高频率的日志切换会有什么问题呢?
日志切换会触发检查点进而触发DBWR写buffer,频繁操作DBWR写不及时,那么下一个redo log 是ACRIVE不能被重用,
alter 日志就会报 Checkpoint not complete,检查点还没有完成,DBWR没有写完该redo log对应的buffer到磁盘,
所以前台的事物就必须要等待检查点完成才能继续写自己事物的日志到redo,此时所有事物必须等待,导致应用不
可用。

alter 日志:
Thu Mar 29 12:00:16 2018
Archived Log entry 335999 added for thread 1 sequence 168048 ID 0xfc447fdf dest 1:
Thu Mar 29 12:01:05 2018
ALTER SYSTEM ARCHIVE LOG
Thu Mar 29 12:01:07 2018
Thread 1 cannot allocate new log, sequence 168050
Checkpoint not complete
  Current log# 1 seq# 168049 mem# 0: +DATA/ydzydb/onlinelog/group_1.271.972034493
  Current log# 1 seq# 168049 mem# 1: +DATA/ydzydb/onlinelog/group_1.272.972034511
Thread 1 advanced to log sequence 168050 (LGWR switch)
  Current log# 2 seq# 168050 mem# 0: +DATA/ydzydb/onlinelog/group_2.266.972034521
  Current log# 2 seq# 168050 mem# 1: +DATA/ydzydb/onlinelog/group_2.265.972034569
Thu Mar 29 12:01:11 2018
Archived Log entry 336002 added for thread 1 sequence 168049 ID 0xfc447fdf dest 1:
Thu Mar 29 12:01:15 2018
ALTER SYSTEM ARCHIVE LOG
Thread 1 cannot allocate new log, sequence 168051
Checkpoint not complete
  Current log# 2 seq# 168050 mem# 0: +DATA/ydzydb/onlinelog/group_2.266.972034521
  Current log# 2 seq# 168050 mem# 1: +DATA/ydzydb/onlinelog/group_2.265.972034569
Thu Mar 29 12:01:18 2018
Thread 1 advanced to log sequence 168051 (LGWR switch)
  Current log# 5 seq# 168051 mem# 0: +DATA/ydzydb/onlinelog/group_5.262.972034649
  Current log# 5 seq# 168051 mem# 1: +DATA/ydzydb/onlinelog/group_5.261.972034663
Archived Log entry 336003 added for thread 1 sequence 168050 ID 0xfc447fdf dest 1:
Thu Mar 29 12:02:04 2018
ALTER SYSTEM ARCHIVE LOG
Thu Mar 29 12:02:07 2018
Thread 1 cannot allocate new log, sequence 168052
孙显鹏


论坛徽章:
2
授权会员
日期:2005-10-30 17:05:33秀才
日期:2015-10-19 15:50:39
发表于 2018-4-4 10:16 | 显示全部楼层
学习了 谢谢

使用道具 举报

回复
论坛徽章:
73
2010新春纪念徽章
日期:2010-03-01 11:06:132011新春纪念徽章
日期:2011-02-18 11:43:332012新春纪念徽章
日期:2012-01-04 11:55:422013年新春福章
日期:2013-02-25 14:51:242014年新春福章
日期:2014-02-18 16:44:08马上有车
日期:2015-01-19 09:45:33最佳人气徽章
日期:2012-03-13 17:39:18ITPUB季度 技术新星
日期:2012-11-27 10:16:10问答徽章
日期:2013-10-23 15:13:22林肯
日期:2013-11-02 08:34:46
发表于 2018-4-4 14:21 | 显示全部楼层
每分钟备份一次归档?谁特么定的备份策略

使用道具 举报

回复

您需要登录后才可以回帖 登录 | 注册

本版积分规则

TOP技术积分榜 社区积分榜 徽章 电子杂志 团队 统计 虎吧 老博客 知识索引树 读书频道 积分竞拍 文本模式 帮助
  ITPUB首页 | ITPUB论坛 | 数据库技术 | 企业信息化 | 开发技术 | 微软技术 | 软件工程与项目管理 | IBM技术园地 | 行业纵向讨论 | IT招聘 | IT文档 | IT博客
  ChinaUnix | ChinaUnix博客 | ChinaUnix论坛 | SAP ERP系统
CopyRight 1999-2011 itpub.net All Right Reserved. 北京盛拓优讯信息技术有限公司版权所有 联系我们 网站律师 隐私政策 知识产权声明
京ICP备16024965号 北京市公安局海淀分局网监中心备案编号:11010802021510 广播电视节目制作经营许可证:编号(京)字第1149号
  
快速回复 返回顶部 返回列表