求教：检查点执行时间间隔大于onconfig文件CKPTINTVL参数的值
本帖最后由 houhuaw 于 2011-09-12 23:58 编辑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 1311165765343564559 99.95 3411397 9564319 83376312 95.93
isamtot open start read write rewrite delete commit rollbk
6153942905 1254088258899402161475748619 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 usercpusyscpu 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 回复 1# houhuaw
onstat -g ckp看最近20个检查点的详细情况。。 本帖最后由 houhuaw 于 2011-09-13 15:56 编辑
> 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 # CkptWaitLong# Dirty DskfluTotal Avg Total Avg
Interval Time Trigger LSN Time TimeTime Waits TimeTimeTimeBuffers /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:14CKPTINTVL273:0x3620180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37957 13:15:14CKPTINTVL273:0x3650180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37958 13:25:15CKPTINTVL273:0x36f018 0.0 0.0 0.0 0 0.0 0.0 0.0 43 43 42 0 10 0
37959 13:35:16CKPTINTVL273:0x3720180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37960 13:45:16CKPTINTVL273:0x3750180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37961 13:55:17CKPTINTVL273:0x3780180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37962 14:05:19CKPTINTVL273:0x37b0180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37963 14:15:20CKPTINTVL273:0x37e6f8 0.0 0.0 0.0 0 0.0 0.0 0.0 25 25 25 0 3 0
37964 14:20:20CKPTINTVL273:0x4816640.0 0.0 0.0 0 0.0 0.0 0.0 203 203 88 0 259 0
37965 14:25:21CKPTINTVL273:0x4b40180.0 0.0 0.0 0 0.0 0.0 0.0 80 80 77 0 51 0
37966 14:35:22CKPTINTVL273:0x5bb0180.0 0.0 0.0 0 0.0 0.0 0.0 194 194 79 0 263 0
37967 14:45:23CKPTINTVL273:0x5be0180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37968 14:50:23CKPTINTVL273:0x5bf608 0.0 0.0 0.0 0 0.0 0.0 0.0 6 6 7 0 1 0
37969 14:55:24CKPTINTVL273:0x5c25e40.0 0.0 0.0 0 0.0 0.0 0.0 25 25 25 0 3 0
37970 15:00:24CKPTINTVL273:0x5c32400.0 0.0 0.0 0 0.0 0.0 0.0 2 2 0 0 1 0
37971 15:05:25CKPTINTVL273:0x5c60180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37972 15:15:26CKPTINTVL273:0x5c95e40.0 0.0 0.0 0 0.0 0.0 0.0 25 25 25 0 3 0
37973 15:20:26CKPTINTVL273:0x5ca6080.0 0.0 0.0 0 0.0 0.0 0.0 6 6 7 0 1 0
37974 15:25:26CKPTINTVL273:0x5d20180.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 回复 1# houhuaw
要命的CHECKPOINT，为了不影响运行，优先级还是比较低，而且有CHK_REQ这种状态，如果你想了解到底怎么做，加上TRACECKPT环境变量，不要过要重启生效，结果好像在ONLINE.LOG里，好久没有用了。 > onstat -g ckp ...
houhuaw 发表于 2011-09-13 15:34 http://bbs.chinaunix.net/images/common/back.gif
有的是5分钟，有的是10分钟，可能在10分钟内并没有update/insert操作（或者说明使用了buffered log的库，更新并没有刷回磁盘），故数据库认为这个ckptinteval内数据库没有改变，等到下一个ckptinteval才做检查点。。 有几十台这样的机子，onconfig配置都是一模一样的，数据库表结构也都是一模一样的，数据库操作也具有同质性，但却有几台出现了这样的问题，其他的都是5分钟正常执行，所用的库是with buffered log。
"3sane” 兄CHK_REQ是什么状态啊，可否指点一二。
以下是以前打开XTRACE跟踪的结果：
Component Feature File Line Pid Time Stampcsvr thrd trans rstcbsession MESSAGE
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c633331705 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_DEBUGrsrecvr.c633331705 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_DEBUGrsrecvr.c142131705 00:46:17 470 8 8c392028 8c351028 1 checkpoint start - intvl 14071 phyused 17 physize 500000
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c148031705 00:46:17 480 8 8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c155331705 00:46:17 490 8 8c392028 8c351028 1 prev intvl 14070 cur intvl 14071 phypos 85327 logpos 128:de77018 cp_dbsoffset 4cp_chkoffset 6 cp_mchkoffset 8
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c159831705 00:46:17 500 8 8c392028 8c351028 1 checkpoint normal broadcast
XTF_FLUSHER XTF_DEBUGrsflush.c 647 31705 00:46:17 510 8 8c392028 8c351028 1 dskflush(0 1 14071)
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c166131705 00:46:17 520 8 8c392028 8c351028 1 dskflush over 0 phyused 17
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c170031705 00:46:17 530 8 8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c215331705 00:46:17 540 8 8c392028 8c351028 1 ckptwrite() 1:2
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c182431705 00:46:17 550 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_DEBUGrsrecvr.c142131705 00:51:17 560 8 8c392028 8c351028 1 checkpoint start - intvl 14072 phyused 0 physize 500000
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c633331705 00:52:32 570 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_DEBUGrsrecvr.c142131705 00:56:17 103 0 8 8c392028 8c351028 1 checkpoint start - intvl 14072 phyused 17 physize 500000
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c148031705 00:56:17 104 0 8 8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c155331705 00:56:17 105 0 8 8c392028 8c351028 1 prev intvl 14071 cur intvl 14072 phypos 85344 logpos 128:de7a018 cp_dbsoffset 4cp_chkoffset 7 cp_mchkoffset 8
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c159831705 00:56:17 106 0 8 8c392028 8c351028 1 checkpoint normal broadcast
XTF_FLUSHER XTF_DEBUGrsflush.c 647 31705 00:56:17 107 0 8 8c392028 8c351028 1 dskflush(0 1 14072)
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c166131705 00:56:17 108 0 8 8c392028 8c351028 1 dskflush over 0 phyused 17
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c170031705 00:56:17 109 0 8 8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c215331705 00:56:17 110 0 8 8c392028 8c351028 1 ckptwrite() 1:3
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c182431705 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_DEBUGrsflush.c 647 31705 01:00:01 112 0 50 8c3957c8 8c35ba20 13dskflush(0 1 0)
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c142131705 01:00:01 113 0 8 8c392028 8c351028 1 checkpoint start - intvl 14073 phyused 0 physize 500000
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c148031705 01:00:01 114 0 8 8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c155331705 01:00:01 115 0 8 8c392028 8c351028 1 prev intvl 14072 cur intvl 14073 phypos 85344 logpos 128:de7b03c cp_dbsoffset 4cp_chkoffset 7 cp_mchkoffset 8
XTF_FLUSHER XTF_DEBUGrsflush.c647 31705 01:00:01 116 0 8 8c392028 8c351028 1 dskflush(0 1 14073)
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c166131705 01:00:01 117 0 8 8c392028 8c351028 1 dskflush over 0 phyused 0
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c170031705 01:00:01 118 0 8 8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c215331705 01:00:01 119 0 8 8c392028 8c351028 1 ckptwrite() 1:2
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c182431705 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_DEBUGrsrecvr.c633331705 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_DEBUGrsrecvr.c633331705 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_DEBUGrsrecvr.c633331705 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_DEBUGrsrecvr.c142131705 01:05:17 155 0 8 8c392028 8c351028 1 checkpoint start - intvl 14074 phyused 17 physize 500000
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c148031705 01:05:17 156 0 8 8c392028 8c351028 1 checkpoint active
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c155331705 01:05:17 157 0 8 8c392028 8c351028 1 prev intvl 14073 cur intvl 14074 phypos 85361 logpos 128:de7e018 cp_dbsoffset 4cp_chkoffset 6 cp_mchkoffset 8
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c159831705 01:05:17 158 0 8 8c392028 8c351028 1 checkpoint normal broadcast
XTF_FLUSHER XTF_DEBUGrsflush.c 647 31705 01:05:17 159 0 8 8c392028 8c351028 1 dskflush(0 1 14074)
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c166131705 01:05:17 160 0 8 8c392028 8c351028 1 dskflush over 0 phyused 17
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c170031705 01:05:17 161 0 8 8c392028 8c351028 1 write reserved pages
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c215331705 01:05:17 162 0 8 8c392028 8c351028 1 ckptwrite() 1:3
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c182431705 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_DEBUGrsrecvr.c142131705 01:10:17 164 0 8 8c392028 8c351028 1 checkpoint start - intvl 14075 phyused 0 physize 500000
XTF_CHECKPOINT XTF_DEBUGrsrecvr.c633331705 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 回复 6# houhuaw
CHK_REQ也许我拼错了，就是等待做CHECKPOINT，这会延迟CHECKPOINT的执行时间，看起来间隔就长了。从LOG里看还真有PHYLOG为0 used的情况，回头看，你设的LRU_MIN很小，所以都被LRU清理掉了。而且修改量不是太大，留给CHECKPOINT做的事情就不多了。
另外建议你尽快升级数据库版本，不要用11.10或11.20的版本。 回复 7# 3sane
"就是等待做CHECKPOINT，这会延迟CHECKPOINT的执行时间"，CHECKPOINT不是到了CKPTINTVL间隔的时间或者其他事件触发的吗，这个是否等待做CHECKPOINT在什么地方可以设置？请指教
"PHYLOG为0 used“，phyused 0指的是LRU的buffer 0个为dirty的吧。为啥5分钟之内不往LRU里面写东西呢？不可能没有修改数据库记录的操作吧，其他业务量小得多的或者没有承载业务在那里空转的机子都 按时执行了检查点，这台机子没有承载业务之前就出现了这个情况。其他机子没有承载业务之前也是按时执行检查点。
"你设的LRU_MIN很小，所以都被LRU清理掉了"，有几十台这样的机子，配置都一样，就这几台出现了这个问题。所以我很迷惑。 回复 5# liaosnet
"可能在10分钟内并没有update/insert操作（或者说明使用了buffered log的库，更新并没有刷回磁盘），故数据库认为这个ckptinteval内数据库没有改变，等到下一个ckptinteval才做检查点"
有几十台从数据库本身配置看来一样的机子，在没有承载业务之前都是按时执行检查点的，这台机子没有承载业务之前就出现了这个问题，承载业务后问题依旧。没有承载业务就是说：主机和磁阵启动状态，数据库Online状态，但没有什么东东来更改数据库记录。 回复 9# houhuaw
从你的onstat -g ckp的输出上看
37960 13:45:16CKPTINTVL273:0x3750180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37961 13:55:17CKPTINTVL273:0x3780180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37962 14:05:19CKPTINTVL273:0x37b0180.0 0.0 0.0 0 0.0 0.0 0.0 19 19 19 0 3 0
37963 14:15:20CKPTINTVL273:0x37e6f8 0.0 0.0 0.0 0 0.0 0.0 0.0 25 25 25 0 3 0
37964 14:20:20CKPTINTVL273:0x4816640.0 0.0 0.0 0 0.0 0.0 0.0 203 203 88 0 259 0
37965 14:25:21CKPTINTVL273:0x4b40180.0 0.0 0.0 0 0.0 0.0 0.0 80 80 77 0 51 0
每次检查点间的逻辑日志量都非常少的。。就可能出现一段时间没有更新（或者更新在仍在缓存里），导致数据库认为没有变动的。。故不需要做检查点的。。
如37960 到 37961 之间的逻辑日志差为 0x378018 -0x375018 = 0x3000(12288) 字节，这其中还包括上次检查点的记录的量。。这个是非常小的。。
而37964 到 37965 之间的逻辑日志差为 0x4b4018 -0x481664 = 0x329B4(207284)字节，这个应该已经超过逻辑日志缓冲区的大小了，因此有提交，有改变，做了检查点。。
BTW：检查点是为了保证数据库一致的机制。。只要它做就好了。。。5分钟一次，10分钟一次并没有什么问题。。。
页:
[1]
2