1        问题概述

目前数据库隔断时间，都会处于 ckp req 检查点请求状态，日志中看到的状态是在短时间内连续切换逻辑日志后抛出： Waiting for Next Logical Log File to be Freed 报错。

1.1   背景信息：

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 信息：

http://www-01.ibm.com/support/docview.wss?uid=swg1IT14187

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

      本次故障问题是因触发 IBM BUG 引起，当可以通过以下方式：

1、    升级数据库版本

2、    调整单个逻辑日志文件的大小，以避免在大批量数据入库操作时，逻辑日志文件切换太频繁。