Chinaunix首页 | 论坛 | 博客
  • 博客访问: 5532756
  • 博文数量: 348
  • 博客积分: 2173
  • 博客等级: 上尉
  • 技术积分: 7900
  • 用 户 组: 普通用户
  • 注册时间: 2011-08-24 17:26
个人简介

雄关漫道真如铁,而今迈步从头越。

文章存档

2022年(4)

2020年(6)

2019年(2)

2018年(2)

2017年(34)

2016年(49)

2015年(53)

2014年(47)

2013年(72)

2012年(79)

分类: DB2/Informix

2014-12-24 11:25:14

  

deadlock_pb1.txt
在日常工作过程中,发现
db2diag文件中有死锁报错信息。通过这次死锁的问题经历,主要想调查以下内容:

1、如何模拟死锁

2、死锁的问题记录会出现在哪里

3、使用db2cos监控死锁

4、使用事件监控器监控死锁

5db2cos和事件监控器对于死锁监控的个人看法

 

首先,呈上自己在工作中发现的死锁信息。附件内容为本次死锁在db2diag文件中的报错信息,检查db2diag文件中的内容,摘取其核心部分如下:

2013-07-16-00.30.18.712028+120 E1235048710A1023   LEVEL: Warning

PID     : 12386440             TID  : 44071       PROC : db2sysc 0

INSTANCE: db2pb1               NODE : 000         DB   : PB1

APPHDL  : 0-46241              APPID: 10.194.6.198.36325.130715160652

AUTHID  : SAPPB1

EDUID   : 44071                EDUNAME: db2agent (PB1) 0

FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:1

MESSAGE : ADM5501I  DB2 is performing lock escalation. The affected application

          is named "disp+work", and is associated with the workload name

          "SYSDEFAULTUSERWORKLOAD" and application ID

          "10.194.6.198.36325.130715160652"  at member "0". The total number of

          locks currently held is "106", and the target number of locks to hold

          is "53". The current statement being executed is "SELECT * FROM

          "TSP01" WHERE "RQIDENT" = ? FOR UPDATE  WITH RS USE AND KEEP

          EXCLUSIVE LOCKS -- OPTLEVEL( 5 ) -- QUERY_DEGREE( 1 ) -- SYSTEM( PB1 ,

          SAPPB1 )".

 

2013-07-16-00.30.18.864972+120 E1235049734A1061   LEVEL: Warning

PID     : 12386440             TID  : 50665       PROC : db2sysc 0

INSTANCE: db2pb1               NODE : 000         DB   : PB1

APPHDL  : 0-46400              APPID: 10.194.6.198.37613.130715174327

AUTHID  : SAPPB1

EDUID   : 50665                EDUNAME: db2agent (PB1) 0

FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:1

MESSAGE : ADM5501I  DB2 is performing lock escalation. The affected application

          is named "disp+work", and is associated with the workload name

          "SYSDEFAULTUSERWORKLOAD" and application ID

          "10.194.6.198.37613.130715174327"  at member "0". The total number of

          locks currently held is "54", and the target number of locks to hold

          is "27". The current statement being executed is "SELECT "RQIDENT",

          "RQLFDNR", "RQSUBID", "RQSAPTITLE", "RQDESC" FROM "TSP01P" WHERE

          "RQSUBID" = ?  -- OPTLEVEL( 5 ) -- QUERY_DEGREE( 1 ) -- LOCATION(

          SAPLSPRR , 2130 ) -- SYSTEM( PB1 , SAPPB1 )".

 

……………………………………..

2013-07-16-00.30.26.457541+120 E1235055520A1025   LEVEL: Warning

PID     : 12386440             TID  : 52105       PROC : db2sysc 0

INSTANCE: db2pb1               NODE : 000         DB   : PB1

APPHDL  : 0-44130              APPID: 10.194.6.198.35851.130715152332

AUTHID  : SAPPB1

EDUID   : 52105                EDUNAME: db2agent (PB1) 0

FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:1

MESSAGE : ADM5501I  DB2 is performing lock escalation. The affected application

          is named "disp+work", and is associated with the workload name

          "SYSDEFAULTUSERWORKLOAD" and application ID

          "10.194.6.198.35851.130715152332"  at member "0". The total number of

          locks currently held is "106", and the target number of locks to hold

          is "53". The current statement being executed is "DELETE FROM "TBTCO"

          WHERE "JOBCOUNT" = ? AND "JOBNAME" = ?  -- OPTLEVEL( 5 ) --

          QUERY_DEGREE( 1 ) -- LOCATION( RSBTCDEL2 , 1408 ) -- SYSTEM( PB1 ,

          SAPPB1 )".

 

2013-07-16-00.32.34.291211+120 E1235056546A564    LEVEL: Error

PID     : 12386440             TID  : 27588       PROC : db2sysc 0

INSTANCE: db2pb1               NODE : 000         DB   : PB1

APPHDL  : 0-46184              APPID: 10.194.6.198.36081.130715154403

FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:4

MESSAGE : ADM5503E  The escalation of "92285" locks on table "SAPPB1

          ./BI0/TINSP_LOT" to lock intent "X" has failed.  The SQLCODE is

          "-911".

……………………………………………………

2013-07-16-00.32.34.961291+120 E1235063280A540    LEVEL: Error

PID     : 12386440             TID  : 50665       PROC : db2sysc 0

INSTANCE: db2pb1               NODE : 000         DB   : PB1

APPHDL  : 0-46400              APPID: 10.194.6.198.37613.130715174327

AUTHID  : SAPPB1

EDUID   : 50665                EDUNAME: db2agent (PB1) 0

FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:4

MESSAGE : ADM5503E  The escalation of "2" locks on table "SAPPB1  .TSP01" to

          lock intent "X" has failed.  The SQLCODE is "-911".

 

2013-07-16-00.32.34.961360+120 E1235063821A540    LEVEL: Error

PID     : 12386440             TID  : 44071       PROC : db2sysc 0

INSTANCE: db2pb1               NODE : 000         DB   : PB1

APPHDL  : 0-46241              APPID: 10.194.6.198.36325.130715160652

AUTHID  : SAPPB1

EDUID   : 44071                EDUNAME: db2agent (PB1) 0

FUNCTION: DB2 UDB, data management, sqldEscalateLocks, probe:4

MESSAGE : ADM5503E  The escalation of "1" locks on table "SAPPB1  .TST03" to

          lock intent "X" has failed.  The SQLCODE is "-911".

 

2013-07-16-00.32.34.961763+120 I1235064362A557    LEVEL: Warning

PID     : 12386440             TID  : 50665       PROC : db2sysc 0

INSTANCE: db2pb1               NODE : 000         DB   : PB1

APPHDL  : 0-46400              APPID: 10.194.6.198.37613.130715174327

AUTHID  : SAPPB1

EDUID   : 50665                EDUNAME: db2agent (PB1) 0

FUNCTION: DB2 UDB, catcache support, sqlrlc_systables_fetch_from_disk, probe:60

MESSAGE : ZRC=0x80100002=-2146435070=SQLP_LDED "Dead lock detected"

          DIA8002C A deadlock has occurred, rolling back transaction.

 

基本上,与-911相关的问题,都是锁的问题,且此信息明确的表示“Dead lock detected”,检测到死锁,回滚了事务。

由此可见,确实发生了死锁。和锁等待一样,死锁也是在并发环境下会遇到的锁的问题。与锁等待的区别在于,锁等待有可能会导致日志被hold,发生日志空间不足的问题;但是dead lock由于后台存在检查死锁的db2dlock线程(V9.5后,之前是进程)用来检查死锁并选择死锁中的一个application将其干掉,以解除死锁。因此,一旦发生了死锁,db2会自动解开死锁,死锁对于我们来说,只是db2diag中的一条报错或者警告信息。然而过多的死锁,必然会导致系统响应的滞后,需要尽量避免。而死锁大部分是由于应用设计的问题,所以,取得死锁的第一手信息提供给开发人员,能够帮助开发人员从根本上解决造成死锁的逻辑问题。于是,引出了我们的另一个关注点,那就是如何搜集死锁的信息。

在讨论如何搜集死锁的信息之前,我们还需要知道如何才能模拟死锁。

 

1、如何模拟死锁

9.7上模拟死锁的方法,参见文章《在db2 9.7版本下进行DB2死锁的模拟》,在此不再累述。

 

2、死锁的问题记录会出现在哪里?

在知道如何模拟死锁后,下一个需要解决的问题,就是,发生了死锁,其报错信息会记录在哪里?

其实,这也是困扰我的一个问题。如文章开篇所示,在db2diag中,是会记录死锁的问题信息(sqlcode  -911 reason code 2),在生产环境中,我也确实从db2diag中找到了这样的信息(如附件所示)。但是,个人在进行模拟死锁时,虽然在模拟的CLP端爆出了检查到死锁,回滚事务(SQL0911N  The current transaction has been rolled back because of a deadlock or timeout.  Reason code "2".  SQLSTATE=40001),但是,自己始终没有在db2diag.log中找到类似的信息。不清楚是因为自己的马虎还是根本就没有,所以,此处,暂时作为一个悬案…...初步结论是,相信死锁信息会被输出到db2diag中(有待继续验证)。所以,如果在db2diag中发现了大量的-911waring或者error,可以考虑是存在死锁(或锁等)等锁的问题。

 

3、使用db2cos进行监控死锁

由于死锁的问题记录具体放在那里,自己并没有调查清楚,所以,无法提供给开发人员具体的参考信息(即使真的在db2diag中,里面提供的信息也是支离破碎的,参见开篇)。因此,为了协助开发人员进行问题的定位和解决,我们需要更详细的信息,使用db2cos回调脚本,就是其中的一种方法。

在《在db2 9.7版本下进行DB2死锁的模拟》一文中,已经提到了,使用db2cos回调脚本,可以用来进行死锁的信息的捕获(锁等信息的捕获也可以用此脚本)。当db2cos被调用时,db2diag中会有明显的记录说明db2cos被调用,信息如下:

2013-07-22-10.45.49.938442+120 I18677A467         LEVEL: Event

PID     : 16121922             TID  : 9255        PROC : db2sysc 0

INSTANCE: db2test              NODE : 000         DB   : SAMPLE

APPHDL  : 0-168                APPID: *LOCAL.db2test.130722083625

AUTHID  : DB2TEST

EDUID   : 9255                 EDUNAME: db2agent (SAMPLE) 0

FUNCTION: DB2 UDB, trace services, pdInvokeCalloutScript, probe:20

STOP    : Completed invoking /home/db2test/sqllib/adm/db2cos

所以,使用db2cos进行第一时间的死锁信息的捕获,是可行的,其捕获的信息的输出位置是db2dump目录下的名为...cos.txt,具体的使用方法如下:

首先,把sqllib/bin/db2cos这个文件拷贝到sqllib/adm/下面,然后,修改db2cos中的Locktimeout段,像这样

"LOCKTIMEOUT")

      echo "Lock Timeout Caught"                                     >> $logfile

      if [ ! -n "$database" ]

      then

         db2pd -inst                                                 >> $logfile

      else

         db2pd -db $database -inst                                   >> $logfile

      fi

   ;;

把else那一段换成db2pd -db $database -locks -transaction -agents -application -dynamic,dbname写上数据库的名字;然后执行db2pdcfg -catch locktimeout

,然后,发生locktimeout的时候,去db2diag文件所在的目录,会生成一个文件命名规则是...cos.txt,里面就有上面的db2pd执行的内容,就能得到一些可以参考的信息了

 

注意,一旦执行了db2pdcfg -catch locktimeout,以后每次的死锁都会被检测到并调用db2cos脚本进行处理,可以使用如下命令查看当前的开关状态:

$ db2pdcfg -catch status

Error Catch #1

   Sqlcode:        0

   ReasonCode:     0

   ADMCode:        0

   DiagText:

   ZRC:            -2146435070

   ECF:            0

   Component ID:   0

   LockName:       Not Set

   LockType:       Not Set

   Current Count:  2

   Max Count:      255

   Bitmap:         0x4A1

   Action:         Error code catch flag enabled

   Action:         Execute /home/db2test/sqllib/adm/db2cos callout script

   Action:         Produce stack trace in db2diag.log

 

如果想关闭开关,使用db2pdcfg -catch clear

$ db2pdcfg -catch clear

All error catch flag settings cleared.

$ db2pdcfg -catch status

All error catch flag settings cleared.

 

但是,通过这个脚本来看,实际上,只是在发生死锁的时候,执行了我们定义的db2pd的内容(db2pd -db $database -locks -transaction -agents -application -dynamic ,如果我们愿意,修改脚本,完全可以在发生死锁的时候,让脚本给我输出一个“hello world”……换句话说,这个脚本,只是在发生死锁的时候,进行调用,执行你让他做的事情。

于是,就有新的问题了,我们知道,发生了死锁,也知道发生这些死锁的一些由db2pd输出的信息,如果说这些信息不够,或者说,想再从其他方面进行检测收集呢?

这个时候,就有另外一个工具来配合了,那就是死锁的事件监控器

 

4、使用事件监控器监控死锁

首先,创建死锁事件监控器(deadlock event monitor),并设置其生效:

$ mkdir deadlock_info

$ cd deadlock_info/

$ pwd

/home/db2test/deadlock_info

$ db2 "create event monitor dlockvm for deadlocks with details history write to file '/home/db2test/deadlock_'"

DB20000I  The SQL command completed successfully.

$ db2 commit

DB20000I  The SQL command completed successfully.

$ db2 set event monitor dlockvm state=1

DB20000I  The SQL command completed successfully.

其次,模拟死锁现象:

 

CLP1

$ db2 +c "insert into t21 values('bbb')"

DB20000I  The SQL command completed successfully.

 

CLP2

$ db2 +c "insert into t11 values('aaa')"

DB20000I  The SQL command completed successfully.

 

CLP1:

$ db2 +c "select * from t11"

 

COL1

----------

 

  0 record(s) selected.

 

 

CLP2

$ db2 +c "select * from t21"

SQL0911N  The current transaction has been rolled back because of a deadlock

or timeout.  Reason code "2".  SQLSTATE=40001

 

死锁现象出现。

 

再次,关闭死锁事件监控器,并将结果输出到一个文本文件中:

 

$ db2 flush event monitor dlockvm

DB20000I  The SQL command completed successfully.

$ db2 set event monitor dlockvm state=0

DB20000I  The SQL command completed successfully.

$ pwd

/home/db2test/deadlock_info

$ ls

00000000.evt  db2event.ctl

$

$ db2evmon -path /home/db2test/deadlock_info > deadlock.txt

 

Reading /home/db2test/deadlock_info/00000000.evt ...

$ ls

00000000.evt  db2event.ctl  deadlock.txt

 

 

最后,进行死锁结果的分析:
deadlock.txt

这个文件(deadlock.txt)的内容,可丰富了……具体的每段的意思,可以参考信息中心。

5db2cos和事件监控器对于死锁监控的个人看法

由于死锁本身会被db2dlock检测并干掉,所以,对于我们来说,死锁只是一个瞬时的现象,能够做到的是,知道发生了死锁,并抓到相应的信息。因此,从这个角度来看,个人比较倾向于这样处理:

首先,查看db2diag中,是不是有-911的报错;

其次,使用快照,抓取数据库快照中与锁相关的信息,像上例,从快照中抓取可以看到如下信息:

$ db2 get snapshot for database on sample | grep -i lock

Locks held currently                       = 0

Lock waits                                 = 2

Time database waited on locks (ms)         = 13683

Lock list memory in use (Bytes)            = 25344

Deadlocks detected                         = 1

Lock escalations                           = 0

Exclusive lock escalations                 = 0

Agents currently waiting on locks          = 0

Lock Timeouts                              = 0

Block IOs                                  = Not Collected

Pages from block IOs                       = Not Collected

Internal rollbacks due to deadlock         = 1

Number of MDC table blocks pending cleanup = 0

    Memory Pool Type                           = Lock Manager Heap

如果有很多的死锁或锁相关的内容,可以先使用db2cos

再次,使用db2cos,个人认为,这个工具的开销比事件监控器要小,所以,优先采用这种做法进行信息的收集会比较好一些,如果收集的信息还不够全面,再使用事件监控器;

最后,如果感觉db2pd收集的信息不够,那就用死锁事件监控器吧。

 

结论:进行锁的问题的诊断,自己没有参与很多,所以,只是将可能的信息收集方法和自己遇到类似问题的处理思路记录了下来。如果有幸参与类似工作,再进行验证和详细记录。

 

 

阅读(7705) | 评论(0) | 转发(0) |
给主人留下些什么吧!~~