一个长事务引起的血案——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
这个命令的意思是：用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的服务好贵，而且……已经停止对这个产品的服务了。
当前标题：一个长事务引起的血案——Informix长事务回滚失败引起的阻塞故障处理
网页网址：http://hbruida.cn/article/ijcpsi.html
