Informix 11.5數據庫，雙機hdr熱備。這是背景。
這兩天出了個事情：由於一個大事務引起了邏輯日志耗盡，導致數據庫狀態進入出現了叫做“長事務阻塞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 Version 11.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 Version 9.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 2a273c3d0 28 U---C-- 119507 7:262553 12500 0 18.50 2a273c438 29 U-B---L 119408 7:275053 12500 2313 100.00 2a273c4a0 30 U-B---- 119409 7:287553 12500 12500 100.00 2a273c508 31 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 an open transaction (0x1cd4d7918). Logical logging will remain blocked until a log file is added. Add the log file with the onparams -a command, using the -i (insert) option, as in: onparams -a -d <dbspace> -s <size> -i Then complete the transaction as soon as possible.
這里的意思是說，最老的那個邏輯日志文件包括了一個開放着的事務，邏輯日志會阻塞，直到增加一個新的邏輯日志文件。要增加邏輯日志文件，可以用onparams –a，並使用-i選項，就像下面的命令，這樣就能盡快結束這個事務了。
onparams –a –d <dbspace> -s <size> -i
這個命令的意思是：用dbspace的空間來增加一個邏輯日志文件，大小為size, 並插入在當前日志的后面。
3 如果正常處理的話……
用onstat –d 看一看你的數據里還沒有4k塊(因為邏輯日志只能用4k塊的chunk)的dbspace可以用，比如我的：
$ onstat -d Dbspaces address number flags fchunk nchunks pgsize flags owner name 2a0e75028 1 0x40001 1 1 4096 N B informix rootdbs 2a273fdc0 2 0x42001 2 1 8192 N TB informix tempdbs01 2a2740028 3 0x42001 3 1 8192 N TB informix tempdbs02 2a27401c0 4 0x42001 4 1 8192 N TB informix tempdbs03 2a2740358 5 0x42001 5 1 8192 N TB informix tempdbs04 2a27404f0 6 0x40001 6 1 4096 N B informix plogdbs 2a2740688 7 0x40001 7 2 4096 N B informix llogdbs 2a2740820 9 0x40001 19 70 8192 N B informix datadbs 8 active, 2047 maximum Chunks address chunk/dbs offset size free bpages flags pathname 2a0e751c0 1 1 0 500000 479443 PO-B- /informix.links/bej/rootchk 2a27409b8 2 2 0 512000 511947 PO-B- /informix.links/bej/tempchk01 2a2740ba8 3 3 0 512000 511947 PO-B- /informix.links/bej/tempchk02 2a2740d98 4 4 0 512000 511947 PO-B- /informix.links/bej/tempchk03 2a274b028 5 5 0 512000 511947 PO-B- /informix.links/bej/tempchk04 2a274b218 6 6 0 512000 266947 PO-B- /informix.links/bej/plogchk 2a274b408 7 7 0 2048000 172947 PO-B- /informix.links/bej/llogchk1 2a274b5f8 8 7 0 2048000 2047997 PO-B- /informix.links/bej/llogchk2 2a274b7e8 9 9 0 1024000 1023997 PO-B- /informix.links/bej/indxchk01 2a274b9d8 10 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.FC6 19: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.de4055c8 19:34:32 See Also: /informix.dump/af.de4055c8 19: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 Died 19:34:38 PANIC: Attempting to bring system down 19: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 Completed 19:58:59 Assert Failed: Dynamic Server must abort 19:58:59 IBM Informix Dynamic Server Version 11.50.FC6 19: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 abort 19:58:59 Action: Reinitialize shared memory 19:58:59 stack trace for pid 176584 written to /informix.dump/af.4245b83 19:58:59 See Also: /informix.dump/af.4245b83 19: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的服務好貴，而且……已經停止對這個產品的服務了。