1        問題概述

 

目前資料庫隔斷時間，都會處於 ckp req 檢查點請求狀態，日誌中看到的狀態是在短時間內連續切換邏輯日誌後丟擲： Waiting for Next Logical Log File to be Freed 報錯。

 

1.1   背景資訊：

 

主機名	sx_jsdb
作業系統版本	HP-UX
IP 地址	137.64.24.16
資料庫版本	IBM Informix Dynamic Server Version   11.50.FC5
資料庫例項名稱

 

 

1.2   概述：

   2018 年 4 月 21 日下午故障是， sx_jsdb 伺服器的 Informix 狀態變更為：

2        故障資訊採集

透過駐場工程師執行提供的資訊收集指令碼 collect.sh 收集當時資料庫伺服器的資訊，如線上日誌資訊、 session 資訊等。

 

3        故障分析過程

3.1   檢查當前活動執行緒

檢查指令碼收集的資訊 onstat.ath 檔案，發現一個處於 sleep 狀態的 sqlexec 執行緒：

 

3.2   檢查該執行緒標誌狀態

發現該執行緒狀態有以下特徵：

1. 處於關鍵區（可能會影響檢查點）

2. 主執行緒

3. 沒有處於等待狀態，即處於執行狀態

4. 有開啟事務

5. 已 sleep

綜合這幾個特徵，初步判斷該執行緒異常 sleep

 

3.3   檢查該執行緒堆疊

Session 資訊如下：

  

堆疊資訊如下：

Stack for thread: 90457 sqlexec

 base: 0xc000000048a26000

  len:   1052672

   pc: 0x0000000000000000

  tos: 0xc000000048b243d0

state: sleeping

   vp: 4

 

0x40000000024b3780 (/informix/bin/oninit)resume

0x4000000000a0c350 (/informix/bin/oninit)yield_processor_mvp

0x4000000000a1cf80 (/informix/bin/oninit)mt_yield

0x4000000000e1dfd0 (/informix/bin/oninit)logchange

0x4000000000e1c5c0 (/informix/bin/oninit)logwrite

0x4000000000cc5410 (/informix/bin/oninit)log_put

0x4000000000d14610 (/informix/bin/oninit)logm_write

0x4000000000e47960 (/informix/bin/oninit)logvimage_new

0x4000000000e42020 (/informix/bin/oninit)wrt_home

0x4000000000e40580 (/informix/bin/oninit)wrtrecord

0x4000000000e400a0 (/informix/bin/oninit)rswrite

0x4000000001013920 (/informix/bin/oninit)fmwrite

0x4000000001922f00 (/informix/bin/oninit)aud_sqiswrite

0x400000000191ee10 (/informix/bin/oninit)chkrowcons

0x4000000001b83cf0 (/informix/bin/oninit)addone

0x4000000001b8aa60 (/informix/bin/oninit)insert_next

0x4000000001a1b620 (/informix/bin/oninit)doinsert

0x4000000001a1a290 (/informix/bin/oninit)aud_doinsert

0x40000000012a9760 (/informix/bin/oninit)excommand

0x40000000017600d0 (/informix/bin/oninit)ip_evalsql

0x40000000017a2e80 (/informix/bin/oninit)ip_execimmed

0x40000000016da6c0 (/informix/bin/oninit)runproc

0x4000000002464db0 (/informix/bin/oninit)udrlm_spl_execute

0x4000000001cddee0 (/informix/bin/oninit)udrlm_exec_routine

0x4000000000dca300 (/informix/bin/oninit)udr_execute

0x4000000001831590 (/informix/bin/oninit)exroutine

0x4000000000d5cbe0 (/informix/bin/oninit)geval

0x4000000000d560e0 (/informix/bin/oninit)ev_geval

0x4000000000d558e0 (/informix/bin/oninit)new_eval

0x40000000016ef380 (/informix/bin/oninit)ip_evalexpr

0x40000000016da190 (/informix/bin/oninit)runproc

0x4000000002464db0 (/informix/bin/oninit)udrlm_spl_execute

0x4000000001cddee0 (/informix/bin/oninit)udrlm_exec_routine

0x4000000000dca300 (/informix/bin/oninit)udr_execute

0x40000000017a91e0 (/informix/bin/oninit)udr_spl_curnext

0x40000000016d9940 (/informix/bin/oninit)ip_curnext

0x40000000016bb1e0 (/informix/bin/oninit)ip_fetch

0x40000000016b9ac0 (/informix/bin/oninit)getrow

0x40000000016b7510 (/informix/bin/oninit)fetchrow

0x40000000016a8cf0 (/informix/bin/oninit)exfetch

0x40000000016a7810 (/informix/bin/oninit)sql_nfetch

0x4000000001e3af00 (/informix/bin/oninit)sq_nfetch

0x4000000001336180 (/informix/bin/oninit)sqmain

0x4000000001486240 (/informix/bin/oninit)listen_verify

0x4000000001482c60 (/informix/bin/oninit)spawn_thread

0x4000000000a22520 (/informix/bin/oninit)startup

0x40000000024b3770 (/informix/bin/oninit)coroutine_start

 

結合當前 main_loop 狀態來看 ：

Stack for thread: 37 main_loop()

 base: 0xc00000004319c000

  len:   266240

   pc: 0x0000000000000000

  tos: 0xc0000000431dc330

state: sleeping

   vp: 3

 

0x40000000024b3780 (/informix/bin/oninit)resume

0x4000000000a0c350 (/informix/bin/oninit)yield_processor_mvp

0x4000000000a1cf80 (/informix/bin/oninit)mt_yield

0x4000000001425780 (/informix/bin/oninit) wait4critex

0x40000000014ba190 (/informix/bin/oninit)checkpoint

0x400000000211d3b0 (/informix/bin/oninit)main_loop

0x4000000000a22520 (/informix/bin/oninit)startup

0x40000000024b3770 (/informix/bin/oninit)coroutine_start

結合整個活動執行緒來看，大量執行緒處於等待 log ，等待檢查點狀態。

3.4    檢查onbar_act.log

3.5   檢查日誌分析

3.6    邏輯日誌資訊

 

從邏輯日誌資訊，可以看出單個邏輯日誌檔案 2kb*50000=100 （ MB ）。

4        問題總結及建議

從以上分析過程可得初步結論 ：

Main_loop 主執行緒在等待 session 離開 critical sector ，而處於關鍵區中的 90457 執行緒處於 sleep 狀態，導致系統無法進行檢查點操作而 hang 在 ckp req 狀態。

綜合 IBM 的 BUG 庫中有存在相關的 BUG 資訊：

IT14187: CHECKPOINT HANG UNABLE TO SWITCH INTO NEXT LOGICAL LOG DUE TO PREVIOUS LONG TRANSACTION ROLLBACK 。

      本次故障問題是因觸發 IBM BUG 引起，當可以透過以下方式：

1、    升級資料庫版本

2、    調整單個邏輯日誌檔案的大小，以避免在大批次資料入庫操作時，邏輯日誌檔案切換太頻繁。