一个长事务引起的血案——Informix长事务回滚失败引起的阻塞故障处理

注意点：增加逻辑日志一定要看清如下命令，不要按照惯性增加！
onparams –a –d llogdbs –s 500000 –i

原文 http://www.cnblogs.com/haoxiaobo/archive/2013/01/10/2854973.html

Informix 11.5数据库，双机hdr热备。这是背景。

我们提供的服务有：成都做网站、成都网站建设、成都外贸网站建设、微信公众号开发、网站优化、网站认证、平乐ssl等。为上1000家企事业单位解决了网站和推广的问题。提供周到的售前咨询和贴心的售后服务，是有科学管理、有技术的平乐网站制作公司

这两天出了个事情：由于一个大事务引起了逻辑日志耗尽，导致数据库状态进入出现了叫做“长事务阻塞Blocked:LONGTX”的状态中，停止服务。本文分析其原理与解决办法。

1 长事务阻塞的原理

当事务开始时，数据会在在所在的逻辑日志文件中记录一个检查点Check Point，事务运行时，这个检查点及之后的逻辑日志都处于未提交状态，要被保留一直到事务提交或是回滚，这些逻辑日志才能标志为使用过，并能再次被循环利用。

如果事务中的操作很多，事务就会跨多个逻辑日志文件。当事务使用的逻辑日志文件超过一定量后，就判断为“长事务”。因为事务回滚也是需要使用逻辑日志的，所以，当数据库发现长事务使用的逻辑日志数目到达“回滚折返点”时，这就意味着如果继续执行事务，剩下的事务可能不足以保证此长事务回滚，数据库就会中断事务执行，并立即回滚。

但因为回滚过程也是需要使用逻辑日志的，在回滚中一但出现逻辑日志不够用的情况，回滚操作用完了剩余的逻辑日志文件，却还没有回滚完成，数据库就会发生“长事务阻塞”。这种情况会出现在一个长事务回退时，另一个事务又快速消耗剩余日志等情况下。

注意这里的逻辑日志不够用指得不是有没有ontape –c备份过，而是指因为事务的起始检查点在第N个逻辑日志文件里，而现在已经执行到了第N-1个逻辑日志文件里（informix的逻辑文件是循环的，执行到N-1号就意味着追了尾了），也就是所有的逻辑日志文件都处于未提交状态，但是当前事务还是不够用，这种情况下，就算所有的日志文件都已经被ontape –c备份过了，也不能被再次利用，因为事务的回滚或是提交还没有完成。

请参考 http://www.ibm.com/developerworks/cn/data/library/techarticles/dm-1001haodh/index.html

2 现象与检查

在这时候，如果你检查数据库的状态，会是如下的样子：

infodb% onstat - IBM Informix Dynamic Server Version11.50.FC6 -- On-Line (Prim LONGTX) -- Up 35 days 16:41:40 -- 3920896 Kbytes Blocked:LONGTX

可以执行onstat –x来检查事务情况

infodb% onstat -x

IBM Informix Dynamic Server Version9.40.FC7 -- On-Line (LONGTX) -- Up 35 days 16:41:56 -- 3920896 Kbytes Blocked:LONGTX
Transactions
address          flags userthread       locks  beginlg curlog  logposit   isol    retrys coord
1c8b2b298        A---- 1c8ae9850        0      0       0       0x0        COMMIT  0 1c8b2b508        A---- 1c8aea078        0      0       0       0x0        COMMIT  0 1cd4d7918        A-B-- 1d44fdcb0        2      119408  119507  0x39722c   DIRTY   0 1cd4d8068        A---- 1cd576e38        1      0       0       0x0        COMMIT  0 1cd4d82d8        A---- 1cd577660        1      0       0       0x0        DIRTY   0

注意其中的flags为 “A-B—“ 的事务，B状态表示begined, 说明这个事务还在执行中。注意他的beginlg也就是开始时的逻辑日志文件号为119408，而当前的日志已经到了119507, 两者相差减加1就是100，正是这个informix系统里所设置的日志数量（您的系统可能不同），这说明这个事务把所有的逻辑日志文件全部用完了。

如果执行onstat –l检查逻辑日志文件的使用情况，会看到下面的情况：

2a273c368 27 U-B----  119506   7:250053            12500    12500   100.00 2a273c3d028 U---C--  119507   7:262553            12500        0    18.50 2a273c43829 U-B---L 119408   7:275053            12500     2313   100.00 2a273c4a030 U-B----  119409   7:287553            12500    12500   100.00 2a273c50831 U-B----  119410   7:300053            12500    12500   100.00

所有的日志已经备份过了，但是由于L标示在119408，说明有事务从这里开始，现在还没有提交或是回退，而当前已经到了119507，所有的逻辑文件用了一圈，已经没有日志可以用了，但当时工作还没有做完。

查看log文件（是指那个文本文件），会看到如下的内容：

17:59:34 Aborting Long Transaction: tx: 0x1cd4d7918 username: informix uid: 300 17:59:35 Long Transaction 0x1cd4d7918 Aborted. Rollback Duration: 0 Seconds
… 这里是一大段检查点与逻辑日志用完和备份的信息，直到……18:03:22 ALERT: The oldest logical log (119408) contains records from anopen transaction (0x1cd4d7918).  Logical logging will
          remain blocked until alog file is added. Add thelog file with the onparams -a command, using the -i
          (insert) option, as in:
 
          onparams-a -d  -s  -iThen complete the transaction as soon as possible.

这里的意思是说，最老的那个逻辑日志文件包括了一个开放着的事务，逻辑日志会阻塞，直到增加一个新的逻辑日志文件。要增加逻辑日志文件，可以用onparams –a，并使用-i选项，就像下面的命令，这样就能尽快结束这个事务了。

onparams –a –d -s -i

这个命令的意思是：用dbspace的空间来增加一个逻辑日志文件，大小为size, 并插入在当前日志的后面。

3 如果正常处理的话……

用onstat –d 看一看你的数据里还没有4k块(因为逻辑日志只能用4k块的chunk)的dbspace可以用，比如我的：

$ onstat -d
 
Dbspaces
addressnumber flags      fchunk   nchunks  pgsize   flags    owner    name
2a0e750281 0x40001 1 1 4096 N  B     informix rootdbs
2a273fdc02 0x42001 2 1 8192 N TB     informix tempdbs01
2a27400283 0x42001 3 1 8192 N TB     informix tempdbs02
2a27401c04 0x42001 4 1 8192 N TB     informix tempdbs03
2a27403585 0x42001 5 1 8192 N TB     informix tempdbs04
2a27404f06 0x40001 6 1 4096 N  B     informix plogdbs
2a27406887 0x40001 7 2 4096 N  B     informix llogdbs
2a27408209 0x40001 19 70 8192 N  B     informix datadbs8 active, 2047 maximum
 
Chunks
address   chunk/dbs     offset     size       free       bpages     flags pathname
2a0e751c01 1 0 500000 479443 PO-B- /informix.links/bej/rootchk
2a27409b82 2 0 512000 511947 PO-B- /informix.links/bej/tempchk01
2a2740ba83 3 0 512000 511947 PO-B- /informix.links/bej/tempchk02
2a2740d984 4 0 512000 511947 PO-B- /informix.links/bej/tempchk03
2a274b0285 5 0 512000 511947 PO-B- /informix.links/bej/tempchk04
2a274b2186 6 0 512000 266947 PO-B- /informix.links/bej/plogchk
2a274b4087 7 0 2048000 172947 PO-B- /informix.links/bej/llogchk1
2a274b5f88 7 0 2048000 2047997 PO-B- /informix.links/bej/llogchk2
2a274b7e89 9 0 1024000 1023997 PO-B- /informix.links/bej/indxchk01
2a274b9d810 9 0 1024000 1023997 PO-B- /informix.links/bej/indxchk02

注意第一个表里，4k的有rootdbs和llogdbs, llogdbs我在安装时专用划分了用于逻辑日志的dbspace。注意第二个列表里，对应的llogdbs有两个chunck，而第一个chunk llogchk1里还有free 172947块，第二个llogchk2里则一点也没用过呢，整整8G.

如果你事先没有留一些空间，那就只好从其他4k块的dbspace里找一些空间来用，如rootdbs, 如果没有，那就只好再增加新的chunk。这不在本文范围内。

现在，要根据数据库的提示，为之增加逻辑日志文件，如下命令：

Onparams –a –d llogdbs –s 500000 –i

上面的容量单位是KB, 500000就是500M。我本来的逻辑日志是50M，但这次为了能足够空间用于回滚事务，就直接建立了500M的一个日志文件。

如果正常，数据库就会有了新的逻辑日志用于继续执行事务回滚，如果还不够，就只好再加。不过最好一次加足。

等一会儿事务回滚成功，长事务阻塞状态就解除了，原来的那个检查点被回退，所有的逻辑日志恢复到可回收利用的状态，恭喜你！

已经增加的逻辑日志太大了，如果不愿意保留，可以通过下列的命令删除之

onmode –l   #强制跳过当前日志文件，进入下一个日志文件。
onmode –l   #强制跳过当前日志文件，进入下一个日志文件。这里多跳一个，保险一点。

onmode –c   # 做一个检查点，阻塞或是解阻塞数据库服务器.
onparams-d -l <逻辑日志文件编号> –y

逻辑日志文件编号可以用onstat –l来看，找到你刚刚加上的那个，第2列就是它的编号。

这样就全完事儿了。建议立即做0级备份数据库。

4 但是有时运气不好，如果你还有备机……

但是，昨天的实际情况是笔者没有那么幸运，在执行完增加逻辑日志文件操作之后，数据库立即down了，再起就起不来了，日志里显示

19:34:32 Assert Failed: Unexpected virtual processor termination, pid = 213056, exit = 0x90009 19:34:32 IBM Informix Dynamic Server Version 11.50.FC619:34:32 Who: Session(5450877, life2@WIN-3XZYO8F2ZGA.lifebj.int, 3124, 7000002b0b548d0)
                Thread(5691992, sqlexec, 7000002a1335bb8, 1)File: mt.c Line: 14124 19:34:32 stack trace for pid 164620 written to /informix.dump/af.de4055c819:34:32 See Also: /informix.dump/af.de4055c819:34:36 mt.c, line 14124, thread 5691992, proc id 164620, Unexpected virtual processor termination, pid = 213056, exit = 0x90009 .19:34:38 The Master Daemon Died19:34:38 PANIC: Attempting to bring system down19:34:38 semctl: errno = 22 19:34:38 semctl: errno = 22 -------------------------------以上是增加逻辑日志文件后的系统报错，以下是重启的日志--------------------------- 19:58:59 Log file 1 added to DBspace 7.19:58:59 Logical Log 59579 - Backup Completed19:58:59 Assert Failed: Dynamic Server must abort19:58:59 IBM Informix Dynamic Server Version 11.50.FC619:58:59 Who: Session(23, informix@bejlif, 0, 2a133e5b8)
                Thread(60, fast_rec, 2a1308878, 5)File: rslog.c Line: 3629 19:58:59 Results: Dynamic Server must abort19:58:59 Action: Reinitialize shared memory19:58:59 stack trace for pid 176584 written to /informix.dump/af.4245b8319:58:59 See Also: /informix.dump/af.4245b8319:59:02 rslog.c, line 3629, thread 60, proc id 176584, Dynamic Server must abort.19:59:03 Fatal error in ADM VP at mt.c:13851 19:59:03 Unexpected virtual processor termination, pid = 176584, exit = 0x100 19:59:03 PANIC: Attempting to bring system down

可以看到logfile的增加没成功，在重启后数据库又在试着执行上次当机时未完成的操作，但还是出错了。我也不知道为什么，估计这是informix软件的BUG之类的。这样一来，主机基本就算完蛋了，反正我的能力是没办法了。

但技术解决不了的问题，由运维手段解决。我们的数据库是hdr主备机的。接下来我就在备机上看onstat –x，那个长事务也锁在那里，但新增的logfile没有同步过来。于是我只好把备机从”从机只读”切为独立模式。

强烈建议在做这个之前，从备机里把数据能备份的备份出来，只读的数据库是可以取出数据来的，一但进入独立主用模式，未完成的长事务也会继续执行，也会进行长事务阻塞，你就不能连接数据库了。做为一个悲催的IT人，这是你最后的生命线。

onmode –d standard

备机也立即进入了长事务阻塞模式。这是必然的，备机需要继续回滚这个事务。

然后执行相同的增加逻辑日志文件操作。

onparams –a –d llogdbs –s 500000 –i

这次成功了！备机很快回滚了事务，回到Online状态。继续执行前面说的：

onmode –l   #强制跳过当前日志文件，进入下一个日志文件。
onmode –l   #强制跳过当前日志文件，进入下一个日志文件。这里多跳一个，保险一点。
onmode –c   # 做一个检查点，阻塞或是解阻塞数据库服务器.
onparams-d -l <逻辑日志文件编号> –y

检查备机数据，确认数据是最新的，业务数据到了阻塞时间点之前，这说明你没有损失数据。

接下来要做的，是从备机上做一个0级的备份到磁带上去。

Ontape –s –L 0

把磁带放到主机上，执行恢复。

Ontape –r

完事后做onmode –m进入online模式。检查数据。

主机恢复成功后，同一盘磁带放回备机上，执行物理恢复：

Ontape –p

完成就可以做主备机hdr同步了：

主机上：

onmode -d primary <备机实例名>

备机上：

onmode -d secondary <主机实例名>

上述的备份、恢复与重建hdr过程我就不说了，请按自家手册进行。

5 最坏的坏果

上述过程失败了，而且您还没有没有备机？那你有过去的定期备份磁带吧，有的话就按您家的手册恢复。上次备份到现在更新的数据您就再想办法吧。

还没有备份磁带？您干什么吃的呀！

不过，听说IBM自己有办法，把损坏的逻辑日志删除或是修好，然后机器就又跑起来了。因为数据其实都在数据库里。

不过IBM的informix的服务好贵，而且……已经停止对这个产品的服务了。