求教：检查点执行时间间隔大于onconfig文件CKPTINTVL参数的值

houhuaw

onconfig文件中CKPTINTVL设定为300s，可实际检查点间隔时间大部份为10分钟，也有少部分是5分钟的，但没有超过10分钟间隔仍旧不执行的。
比如上一个检查点执行时间是00：00：00
在00：05：00执行onstat -R显示大部份都是0 dirty（这台机子业务量很大，不可能不更新数据库，confonfig LRU配置为：BUFFERPOOL      size=2K,buffers=500000,lrus=32,lru_min_dirty=0.390000,lru_max_dirty=0.780000）：

> onstat -R显示：
IBM Informix Dynamic Server Version 11.10.FC2     -- On-Line -- Up 168 days 10:22:38 -- 1375204 Kbytes
Buffer pool page size: 2048
...
0 dirty, 500000 queued, 500000 total, 524288 hash buckets, 2048 buffer size
start clean at   0.780% (of pair total) dirty, or 122 buffs dirty, stop at
   0.390%
大部份情况下过了5分钟后才会出现lru buffer中dirty不为0的情况，大部份情况为19 dirty。

>onstat -F显示：
IBM Informix Dynamic Server Version 11.10.FC2     -- On-Line -- Up 168 days 10:17:55 -- 1375204 Kbytes
Fg Writes     LRU Writes    Chunk Writes
0             1368228       1572810      

> onstat -p显示：
IBM Informix Dynamic Server Version 11.10.FC2     -- On-Line -- Up 168 days 10:20:47 -- 1375204 Kbytes
Profile
dskreads   pagreads   bufreads   %cached dskwrits   pagwrits   bufwrits   %cached
3903022    131116576  5343564559 99.95   3411397    9564319    83376312   95.93  
isamtot    open       start      read       write      rewrite    delete     commit     rollbk
6153942905 125408825  889940216  1475748619 18939770   139680     14628607   626166     2
gp_read    gp_write   gp_rewrt   gp_del     gp_alloc   gp_free    gp_curs   
0          0          0          0          0          0          0         
ovlock     ovuserthread ovbuff     usercpu  syscpu   numckpts   flushes   
0          0            0          88531.03 29910.57 27426      27929     
bufwaits   lokwaits   lockreqs   deadlks    dltouts    ckpwaits   compress   seqscans  
29885      0          2750105435 0          0          749        1811164    2038837   
ixda-RA    idx-RA     da-RA      RA-pgsused lchwaits  
338        0          134146     134484     640484682

liaosnet

回复 1# houhuaw


    onstat -g ckp  看最近20个检查点的详细情况。。

houhuaw

> onstat -g ckp                                                                                                                              
                                                                                                                                             
IBM Informix Dynamic Server Version 11.10.FC2 -- On-Line -- Up 169 days 01:59:21 -- 1375204 Kbytes                                       
                                                                                                                                          
AUTO_CKPTS=On   RTO_SERVER_RESTART=Off                                                                                                   
                                                                                                                                          
                                                                Critical Sections                          Physical Log    Logical Log   
                Clock                                                 Total Flush Block #      Ckpt  Wait  Long  # Dirty   Dskflu  Total    Avg    Total    Avg   
Interval    Time        Trigger         LSN                Time Time  Time Waits Time  Time  Time  Buffers   /Sec    Pages    /Sec   Pages    /Sec  
37955      13:00:01 *User           273:0x35f03c   0.0   0.0   0.0   1      0.0     0.0    0.0     0           0           0        0          1        0     
37956      13:05:14  CKPTINTVL  273:0x362018  0.0   0.0   0.0   0      0.0     0.0   0.0    19          19         19       0          3        0     
37957      13:15:14  CKPTINTVL  273:0x365018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0          3        0     
37958      13:25:15  CKPTINTVL  273:0x36f018   0.0   0.0   0.0   0      0.0    0.0    0.0    43          43         42       0         10       0     
37959      13:35:16  CKPTINTVL  273:0x372018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37960      13:45:16  CKPTINTVL  273:0x375018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37961      13:55:17  CKPTINTVL  273:0x378018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37962      14:05:19  CKPTINTVL  273:0x37b018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37963      14:15:20  CKPTINTVL  273:0x37e6f8   0.0   0.0   0.0   0      0.0    0.0    0.0    25          25         25       0           3        0     
37964      14:20:20  CKPTINTVL  273:0x481664  0.0   0.0   0.0   0      0.0    0.0    0.0    203        203       88       0           259    0     
37965      14:25:21  CKPTINTVL  273:0x4b4018  0.0   0.0   0.0   0      0.0    0.0    0.0    80          80         77       0           51      0     
37966      14:35:22  CKPTINTVL  273:0x5bb018  0.0   0.0   0.0   0      0.0    0.0    0.0    194        194       79       0           263    0     
37967      14:45:23  CKPTINTVL  273:0x5be018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37968      14:50:23  CKPTINTVL  273:0x5bf608   0.0   0.0   0.0   0      0.0    0.0    0.0    6            6           7         0           1        0     
37969      14:55:24  CKPTINTVL  273:0x5c25e4  0.0   0.0   0.0   0      0.0    0.0     0.0    25         25         25       0           3        0     
37970      15:00:24  CKPTINTVL  273:0x5c3240  0.0   0.0   0.0   0      0.0    0.0     0.0    2           2           0         0           1        0     
37971      15:05:25  CKPTINTVL  273:0x5c6018  0.0   0.0   0.0   0      0.0    0.0     0.0    19         19         19       0           3        0     
37972      15:15:26  CKPTINTVL  273:0x5c95e4  0.0   0.0   0.0   0      0.0    0.0     0.0    25         25         25       0           3        0     
37973      15:20:26  CKPTINTVL  273:0x5ca608  0.0   0.0   0.0   0      0.0    0.0     0.0    6           6           7         0           1        0     
37974      15:25:26  CKPTINTVL  273:0x5d2018  0.0   0.0   0.0   0      0.0    0.0     0.0    36        36         35       0           8        0     
                                                                                                                                             
Max Plog         Max Llog       Max Dskflush   Avg Dskflush   Avg Dirty      Blocked                                                            
pages/sec      pages/sec      Time               pages/sec       pages/sec      Time                                                               
8450              6008               0                    1                       0                   0

3sane

回复 1# houhuaw


    要命的CHECKPOINT，为了不影响运行，优先级还是比较低，而且有CHK_REQ这种状态，如果你想了解到底怎么做，加上TRACECKPT环境变量，不要过要重启生效，结果好像在ONLINE.LOG里，好久没有用了。

liaosnet

> onstat -g ckp                                                                                      ...
houhuaw 发表于 2011-09-13 15:34

    有的是5分钟，有的是10分钟，可能在10分钟内并没有update/insert操作（或者说明使用了buffered log的库，更新并没有刷回磁盘），故数据库认为这个ckptinteval内数据库没有改变，等到下一个ckptinteval才做检查点。。

houhuaw

有几十台这样的机子，onconfig配置都是一模一样的，数据库表结构也都是一模一样的，数据库操作也具有同质性，但却有几台出现了这样的问题，其他的都是5分钟正常执行，所用的库是with buffered log。
"3sane” 兄CHK_REQ是什么状态啊，可否指点一二。
以下是以前打开XTRACE跟踪的结果：
Component          Feature         File          Line    Pid     Time Stamp  csvr thrd      trans rstcb  session MESSAGE
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  6333  31705 00:42:31 1   0    8    8c392028 8c351028 1 need_to_ckpt() intvl 14071 phyused 17 n_dirty_buffs 17 dskflush_per_sec 1000 plogs_per_sec 8450 llogs_per_sec 6008
.......................
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  6333  31705 00:42:31 1   0    8    8c392028 8c351028 1 need_to_ckpt() intvl 14071 phyused 17 n_dirty_buffs 17 dskflush_per_sec 1000 plogs_per_sec 8450 llogs_per_sec 6008
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1421  31705 00:46:17 47  0    8    8c392028 8c351028 1 checkpoint start - intvl 14071 phyused 17 physize 500000
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1480  31705 00:46:17 48  0    8    8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1553  31705 00:46:17 49  0    8    8c392028 8c351028 1 prev intvl 14070 cur intvl 14071 phypos 85327 logpos 128:de77018 cp_dbsoffset 4  cp_chkoffset 6 cp_mchkoffset 8
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1598  31705 00:46:17 50  0    8    8c392028 8c351028 1 checkpoint normal broadcast
XTF_FLUSHER       XTF_DEBUG  rsflush.c   647   31705 00:46:17 51  0    8    8c392028 8c351028 1 dskflush(0 1 14071)
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1661  31705 00:46:17 52  0    8    8c392028 8c351028 1 dskflush over 0 phyused 17
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1700  31705 00:46:17 53  0    8    8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  2153  31705 00:46:17 54  0    8    8c392028 8c351028 1 ckptwrite() 1:2
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1824  31705 00:46:17 55  0    8    8c392028 8c351028 1 ckpt done time_between 602 run_time 0 plogs/S 0 llogs/S 0 phyused 0 blockflags 0
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1421  31705 00:51:17 56  0    8    8c392028 8c351028 1 checkpoint start - intvl 14072 phyused 0 physize 500000
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  6333  31705 00:52:32 57  0    8    8c392028 8c351028 1 need_to_ckpt() intvl 14072 phyused 17 n_dirty_buffs 17 dskflush_per_sec 1000 plogs_per_sec 8450 llogs_per_sec 6008
.....................
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1421  31705 00:56:17 103 0    8    8c392028 8c351028 1 checkpoint start - intvl 14072 phyused 17 physize 500000
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1480  31705 00:56:17 104 0    8    8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1553  31705 00:56:17 105 0    8    8c392028 8c351028 1 prev intvl 14071 cur intvl 14072 phypos 85344 logpos 128:de7a018 cp_dbsoffset 4  cp_chkoffset 7 cp_mchkoffset 8
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1598  31705 00:56:17 106 0    8    8c392028 8c351028 1 checkpoint normal broadcast
XTF_FLUSHER       XTF_DEBUG  rsflush.c   647   31705 00:56:17 107 0    8    8c392028 8c351028 1 dskflush(0 1 14072)
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1661  31705 00:56:17 108 0    8    8c392028 8c351028 1 dskflush over 0 phyused 17
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1700  31705 00:56:17 109 0    8    8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  2153  31705 00:56:17 110 0    8    8c392028 8c351028 1 ckptwrite() 1:3
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1824  31705 00:56:17 111 0    8    8c392028 8c351028 1 ckpt done time_between 600 run_time 0 plogs/S 0 llogs/S 0 phyused 0 blockflags 0
XTF_FLUSHER       XTF_DEBUG  rsflush.c   647    31705 01:00:01 112 0    50   8c3957c8 8c35ba20 13dskflush(0 1 0)
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1421  31705 01:00:01 113 0    8    8c392028 8c351028 1 checkpoint start - intvl 14073 phyused 0 physize 500000
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1480  31705 01:00:01 114 0    8    8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1553  31705 01:00:01 115 0    8    8c392028 8c351028 1 prev intvl 14072 cur intvl 14073 phypos 85344 logpos 128:de7b03c cp_dbsoffset 4  cp_chkoffset 7 cp_mchkoffset 8
XTF_FLUSHER        XTF_DEBUG  rsflush.c  647    31705 01:00:01 116 0    8    8c392028 8c351028 1 dskflush(0 1 14073)
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1661  31705 01:00:01 117 0    8    8c392028 8c351028 1 dskflush over 0 phyused 0
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1700  31705 01:00:01 118 0    8    8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  2153  31705 01:00:01 119 0    8    8c392028 8c351028 1 ckptwrite() 1:2
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1824  31705 01:00:01 120 0    8    8c392028 8c351028 1 ckpt done time_between 224 run_time 0 plogs/S 0 llogs/S 0 phyused 0 blockflags 0
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  6333  31705 01:02:32 121 0    8    8c392028 8c351028 1 need_to_ckpt() intvl 14074 phyused 17 n_dirty_buffs 17 dskflush_per_sec 1000 plogs_per_sec 8450 llogs_per_sec 6008
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  6333  31705 01:02:37 122 0    8    8c392028 8c351028 1 need_to_ckpt() intvl 14074 phyused 17 n_dirty_buffs 17 dskflush_per_sec 1000 plogs_per_sec 8450 llogs_per_sec 6008
..............................
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  6333  31705 01:05:17 154 0    8    8c392028 8c351028 1 need_to_ckpt() intvl 14074 phyused 17 n_dirty_buffs 17 dskflush_per_sec 1000 plogs_per_sec 8450 llogs_per_sec 6008
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1421  31705 01:05:17 155 0    8    8c392028 8c351028 1 checkpoint start - intvl 14074 phyused 17 physize 500000
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1480  31705 01:05:17 156 0    8    8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1553  31705 01:05:17 157 0    8    8c392028 8c351028 1 prev intvl 14073 cur intvl 14074 phypos 85361 logpos 128:de7e018 cp_dbsoffset 4  cp_chkoffset 6 cp_mchkoffset 8
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1598  31705 01:05:17 158 0    8    8c392028 8c351028 1 checkpoint normal broadcast
XTF_FLUSHER       XTF_DEBUG  rsflush.c   647    31705 01:05:17 159 0    8    8c392028 8c351028 1 dskflush(0 1 14074)
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1661  31705 01:05:17 160 0    8    8c392028 8c351028 1 dskflush over 0 phyused 17
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1700  31705 01:05:17 161 0    8    8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  2153  31705 01:05:17 162 0    8    8c392028 8c351028 1 ckptwrite() 1:3
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1824  31705 01:05:17 163 0    8    8c392028 8c351028 1 ckpt done time_between 316 run_time 0 plogs/S 0 llogs/S 0 phyused 0 blockflags 0
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  1421  31705 01:10:17 164 0    8    8c392028 8c351028 1 checkpoint start - intvl 14075 phyused 0 physize 500000
XTF_CHECKPOINT XTF_DEBUG  rsrecvr.c  6333  31705 01:12:32 165 0    8    8c392028 8c351028 1 need_to_ckpt() intvl 14075 phyused 17 n_dirty_buffs 17 dskflush_per_sec 1000 plogs_per_sec 8450 llogs_per_sec 6008

3sane

回复 6# houhuaw


    CHK_REQ也许我拼错了，就是等待做CHECKPOINT，这会延迟CHECKPOINT的执行时间，看起来间隔就长了。从LOG里看还真有PHYLOG为0 used的情况，回头看，你设的LRU_MIN很小，所以都被LRU清理掉了。而且修改量不是太大，留给CHECKPOINT做的事情就不多了。
   另外建议你尽快升级数据库版本，不要用11.10或11.20的版本。

houhuaw

回复 7# 3sane


    "就是等待做CHECKPOINT，这会延迟CHECKPOINT的执行时间"，CHECKPOINT不是到了CKPTINTVL间隔的时间或者其他事件触发的吗，这个是否等待做CHECKPOINT在什么地方可以设置？请指教

   "PHYLOG为0 used“，phyused 0指的是LRU的buffer 0个为dirty的吧。为啥5分钟之内不往LRU里面写东西呢？不可能没有修改数据库记录的操作吧，其他业务量小得多的或者没有承载业务在那里空转的机子都 按时执行了检查点，这台机子没有承载业务之前就出现了这个情况。其他机子没有承载业务之前也是按时执行检查点。

   "你设的LRU_MIN很小，所以都被LRU清理掉了"，有几十台这样的机子，配置都一样，就这几台出现了这个问题。所以我很迷惑。

houhuaw

回复 5# liaosnet


    "可能在10分钟内并没有update/insert操作（或者说明使用了buffered log的库，更新并没有刷回磁盘），故数据库认为这个ckptinteval内数据库没有改变，等到下一个ckptinteval才做检查点"
     有几十台从数据库本身配置看来一样的机子，在没有承载业务之前都是按时执行检查点的，这台机子没有承载业务之前就出现了这个问题，承载业务后问题依旧。没有承载业务就是说：主机和磁阵启动状态，数据库Online状态，但没有什么东东来更改数据库记录。

liaosnet

回复 9# houhuaw


    从你的onstat -g ckp的输出上看
37960      13:45:16  CKPTINTVL  273:0x375018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37961      13:55:17  CKPTINTVL  273:0x378018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37962      14:05:19  CKPTINTVL  273:0x37b018  0.0   0.0   0.0   0      0.0    0.0    0.0    19          19         19       0           3        0     
37963      14:15:20  CKPTINTVL  273:0x37e6f8   0.0   0.0   0.0   0      0.0    0.0    0.0    25          25         25       0           3        0     
37964      14:20:20  CKPTINTVL  273:0x481664  0.0   0.0   0.0   0      0.0    0.0    0.0    203        203       88       0           259    0     
37965      14:25:21  CKPTINTVL  273:0x4b4018  0.0   0.0   0.0   0      0.0    0.0    0.0    80          80         77       0           51      0     

每次检查点间的逻辑日志量都非常少的。。就可能出现一段时间没有更新（或者更新在仍在缓存里），导致数据库认为没有变动的。。故不需要做检查点的。。
如37960 到 37961 之间的逻辑日志差为 0x378018   -  0x375018 = 0x3000(1228 字节，这其中还包括上次检查点的记录的量。。这个是非常小的。。
而37964 到 37965 之间的逻辑日志差为 0x4b4018   -  0x481664 = 0x329B4(207284)字节，这个应该已经超过逻辑日志缓冲区的大小了，因此有提交，有改变，做了检查点。。


BTW：检查点是为了保证数据库一致的机制。。只要它做就好了。。。5分钟一次，10分钟一次并没有什么问题。。。