当页导航

疑似online backup引起的数据库夯问题

最近一套OLTP交易系统反映在4日00:30-00:32有大量交易超时,之后自动就恢复了数据库版本 :DB2 9.7 FP8OS版本:AIX 7102查看了db2diag日志,看到00:30.03数据库发起了online backup,但奇怪的是实际备份从2017-06-04-00.32开始,而期间差不多2分钟时间正好是应用异常的时间。求大家...显示全部

最近一套OLTP交易系统反映在4日00:30-00:32有大量交易超时,之后自动就恢复了

数据库版本 :DB2 9.7 FP8

OS版本:AIX 7102

查看了db2diag日志,看到00:30.03数据库发起了online backup,但奇怪的是实际备份从2017-06-04-00.32开始,而期间差不多2分钟时间正好是应用异常的时间。

求大家帮忙分析,谢谢!

==db2diag日志===

2017-06-04-00.30.03.618468+480 E16655092A480      LEVEL: Info

PID     : 33751414             TID  : 95608       PROC : db2sysc 0

INSTANCE: ecifinst             NODE : 000         DB   : ECIFDB

APPHDL  : 0-20396              APPID: *LOCAL.ecifinst.170607185914

AUTHID  : ECIFINST

EDUID   : 95608                EDUNAME: db2agent (ECIFDB) 0

FUNCTION: DB2 UDB, database utilities, sqluxGetDegreeParallelism, probe:774

DATA #1 : <preformatted>

Autonomic BAR - using parallelism = 10.

2017-06-04-00.32.37.371608+480 E16655573A516      LEVEL: Info

PID     : 33751414             TID  : 95608       PROC : db2sysc 0

INSTANCE: ecifinst             NODE : 000         DB   : ECIFDB

APPHDL  : 0-20396              APPID: *LOCAL.ecifinst.170607185914

AUTHID  : ECIFINST

EDUID   : 95608                EDUNAME: db2agent (ECIFDB) 0

FUNCTION: DB2 UDB, database utilities, sqluxGetAvailableHeapPages, probe:888

DATA #1 : <preformatted>

Autonomic BAR - heap consumption.

Targetting (50%) - 25560 of 51120 pages.

2017-06-04-00.32.37.372087+480 E16656090A506      LEVEL: Info

PID     : 33751414             TID  : 95608       PROC : db2sysc 0

INSTANCE: ecifinst             NODE : 000         DB   : ECIFDB

APPHDL  : 0-20396              APPID: *LOCAL.ecifinst.170607185914

AUTHID  : ECIFINST

EDUID   : 95608                EDUNAME: db2agent (ECIFDB) 0

FUNCTION: DB2 UDB, database utilities, sqlubTuneBuffers, probe:1139

DATA #1 : <preformatted>

Autonomic backup - tuning enabled.

Using buffer size = 1024, number = 10.

2017-06-04-00.32.37.857664+480 E16656597A451      LEVEL: Info

PID     : 33751414             TID  : 95608       PROC : db2sysc 0

INSTANCE: ecifinst             NODE : 000         DB   : ECIFDB

APPHDL  : 0-20396              APPID: *LOCAL.ecifinst.170607185914

AUTHID  : ECIFINST

EDUID   : 95608                EDUNAME: db2agent (ECIFDB) 0

FUNCTION: DB2 UDB, database utilities, sqlubSetupJobControl, probe:1604

MESSAGE : Starting an online db backup.


==db2pd -latch信息==

该数据库部了个脚本会定时收集db快照,app快照,db2pd -latch,app,tra,age,api等信息,其中比较可疑的是在00:30的数据中出现了大量的latch

Database Partition 0 -- Active -- Up 6 days 15:11:19 -- Date 2017-06-04-00.30.50.219305

Latches:

Address            Holder     Waiter     Filename             LOC        LatchType            HoldCount

0x0A00030C49764788 6684       0          sqlbpacc.C           2455       SQLO_LT_SQLB_POOL_CB__readLatch 256      

0x0A00030000068A20 6684       0          sqlbilatch.C         1411       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 256      

0x0A00030C49764788 6941       0          sqlbpacc.C           2455       SQLO_LT_SQLB_POOL_CB__readLatch 256      

0x0A00030000068A20 6941       0          sqlbilatch.C         1411       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 256      

0x0A00030C49764788 7198       0          sqlbpacc.C           2455       SQLO_LT_SQLB_POOL_CB__readLatch 256      

0x0A00030000068A20 7198       0          sqlbilatch.C         1411       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 256      

0x0A00030C49764788 7455       0          sqlbpacc.C           2455       SQLO_LT_SQLB_POOL_CB__readLatch 256      

0x0A00030000068A20 7455       0          sqlbilatch.C         1411       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 256      

。。。(省略大量latch等待,都是SQLO_LT_SQLB_POOL_CB__readLatch和SQLO_LT_SQLB_POOL_MAP_CB__range_latch )     

0x0A00030C49764788 88926      0          sqlbpacc.C           1636       SQLO_LT_SQLB_POOL_CB__readLatch 1         

0x0A00030000068A20 88926      0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1         

0x0A00030C497671A8 90211      0          sqlbpacc.C           1636       SQLO_LT_SQLB_POOL_CB__readLatch 1         

0x0A00030F534BD320 90211      0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1         

0x0A00030C49764788 90468      0          sqlbpacc.C           1636       SQLO_LT_SQLB_POOL_CB__readLatch 1         

0x0A00030000068A20 90468      0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1         

0x0A00030C497671A8 91496      0          sqlbpacc.C           1636       SQLO_LT_SQLB_POOL_CB__readLatch 1         

0x0A00030F534BD320 91496      0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1         

0x0A000300000D94D0 95608      0          sqlbpool.C           13685      SQLO_LT_SQLB_CLNR_PAUSE_CB__preventSuspendLatch 1         

0x0A00030001450930 95608      0          sqlbflush.C          119        SQLO_LT_SQLB_RuntimeBPDefs__rtBPLatch 1         

0x0A0003000145D470 95608      0          sqlbbuffers.C        2639       SQLO_LT_SQLB_BufferPool__prevBPDCachingLatch 1         

0x0A00030C49764798 95608      0          sqlbpacc.C           2476       SQLO_LT_SQLB_POOL_CB__writeLatch 1         

0x0A00030000068A20 95608      0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1         

0x0A00030C497671A8 96636      0          sqlbpacc.C           1636       SQLO_LT_SQLB_POOL_CB__readLatch 1         

0x0A00030F534BD320 96636      0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1         

。。。(省略一部分latch等待,都是SQLO_LT_SQLB_POOL_CB__readLatch和SQLO_LT_SQLB_POOL_MAP_CB__range_latch )        

0x0A00030C497671A8 119521     0          sqlbpacc.C           1636       SQLO_LT_SQLB_POOL_CB__readLatch 1         

0x0A00030F534BD320 119521     0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1     

如上95608的latch等待比较特别,95608对应的app是online backup的会话。

收起
希望获得:具体解决, 原理分析

5回答

icycastleicycastle数据库管理员 , 浦发银行
0x0A000300000D94D0 95608      0          sqlbpool.C           13685      SQLO_LT_SQLB_CLNR_PAUSE_CB__preventSuspendLatch 1    ...显示全部

0x0A000300000D94D0 95608      0          sqlbpool.C           13685      SQLO_LT_SQLB_CLNR_PAUSE_CB__preventSuspendLatch 1         

0x0A00030001450930 95608      0          sqlbflush.C          119        SQLO_LT_SQLB_RuntimeBPDefs__rtBPLatch 1         

0x0A0003000145D470 95608      0          sqlbbuffers.C        2639       SQLO_LT_SQLB_BufferPool__prevBPDCachingLatch 1         

0x0A00030C49764798 95608      0          sqlbpacc.C           2476       SQLO_LT_SQLB_POOL_CB__writeLatch 1         

0x0A00030000068A20 95608      0          sqlbilatch.C         1407       SQLO_LT_SQLB_POOL_MAP_CB__range_latch 1     

这些latch是什么意思,哪位大神帮忙解释下,谢谢。

收起
 2017-06-07
icycastleicycastle数据库管理员 , 浦发银行
关于latch含义,IBM工程师给出了解释SQLO_LT_SQLB_CLNR_PAUSE_CB__preventSuspendLatch: 在备份数据库时,为了防止database的挂起(suspend)和deadlatch的发生,需要获取该latch (Grab the "prevent suspend" latch) SQLO_LT_SQLB_RuntimeBPDefs__rtBPLatch: 为了保证在backup过程中,b...显示全部

关于latch含义,IBM工程师给出了解释

SQLO_LT_SQLB_CLNR_PAUSE_CB__preventSuspendLatch: 在备份数据库时,为了防止database的挂起(suspend)和deadlatch的发生,需要获取该latch (Grab the "prevent suspend" latch)

SQLO_LT_SQLB_RuntimeBPDefs__rtBPLatch: 为了保证在backup过程中,bufferpool不会被drop,需要获取该latch

SQLO_LT_SQLB_BufferPool__prevBPDCachingLatch: 在将Bufferpool中的dirty page写到磁盘的时候,需要获取该latch

SQLO_LT_SQLB_POOL_CB__writeLatch: 在写bufferpool时,需要获取该latch

SQLO_LT_SQLB_POOL_MAP_CB__range_latch: 是在需要读取连续批量数据时,在tablespace中map(管理page的usage)中某一范围(从page low到page high)的latch,比如backup等操作。

收起
 2017-06-14
icycastleicycastle数据库管理员 , 浦发银行
在目前没有确切数据的情况下,IBM老朱给了一些经验借鉴,供参考:某一个客户也发生过类似问题,当时由于是9.7的数据库,无法track bufferpool上的hot page的latch,但是从仅有的几次stack信息看到是在bufferpool的page latch上存在等待,后来发现该环境由于CPU虚拟的比较厉害,因此NUM_I...显示全部

在目前没有确切数据的情况下,IBM老朱给了一些经验借鉴,供参考:

某一个客户也发生过类似问题,当时由于是9.7的数据库,无法track bufferpool上的hot page的latch,但是从仅有的几次stack信息看到是在bufferpool的page latch上存在等待,后来发现该环境由于CPU虚拟的比较厉害,因此NUM_IOCLEANERS的auto设置导致过大,达到96个,修改了page cleaner的个数并启用主动页清除DB2_USE_ALTERNATE_PAGE_CLEANING后,问题不再发生,而从你们输出来看db2pfchr的个数非常多。建议检查下NUM_IOCLEANERS设置了多少以及有没有启用APC。

查看了我们的参数设置,觉得这次的问题与NUM_IOCLEANERS设置可能有关。

收起
 2017-06-14
icycastleicycastle数据库管理员 , 浦发银行
查看信息中心关于NUM_IOCLEANERS参数设置的说明--DB2 9.7If this parameter is set to AUTOMATIC, the number of page cleaners started will be based on the number of logical CPU cores configured on the current machine, as well as the number of local logical...显示全部

查看信息中心关于NUM_IOCLEANERS参数设置的说明

--DB2 9.7

If this parameter is set to AUTOMATIC, the number of page cleaners started will be based on the number of logical CPU cores configured on the current machine, as well as the number of local logical database partitions in a partitioned database environment. There will always be at least one page cleaner started when this parameter is set to AUTOMATIC.

The number of page cleaners to start when this parameter is set to AUTOMATIC will be calculated using the following formula:

number of page cleaners = max( ceil( # CPUs / # local logical DPs ) - 1, 1 )

--DB2 10.5

If this parameter is set to AUTOMATIC, the number of page cleaners started will be based on the number of physical CPU cores configured on the current machine, as well as the number of local logical database partitions in a partitioned database environment. There will always be at least one page cleaner started when this parameter is set to AUTOMATIC.

The number of page cleaners to start when this parameter is set to AUTOMATIC will be calculated using the following formula:

number of page cleaners = max( ceil( # CPUs / # local logical DPs ) - 1, 1 )

在DB2 9.7和10版本下,NUM_IOCLEANERS参数如果设置为AUTOMATIC,DB2自动调优时参考的CPU是有区别的,9.7版本是按照逻辑CPU计算的,10.1/10.5版本是按照物理CPU计算的,为什么会有这样的改变呢?到底哪种设置方法较优?

收起
 2017-06-14
匪徒易真匪徒易真数据库管理员 , 匪徒易真
你也遇到数据库备份导致整个系统hang了? 是备份开始的前30s吗?显示全部

你也遇到数据库备份导致整个系统hang了? 是备份开始的前30s吗?

收起
 4天前

撰写回答

提问者

icycastle数据库管理员, 浦发银行
发布59
回答43

相关问题