When building an index, the code currently looks to see if there
is a pending checkpoint, and if so, it exits critical section
and releases the buffers it holds to allow the checkpoint to
continue. However, as soon as the it can, it re-enters it's
critical section and then grabs all it's buffers again with X
locks. If it's able to get it's buffers back before the
checkpoint process was able to flush them, it can then hold the
buffers for a long time causing the checkpoint to not be able to
finish flushing the required buffers to close out the
checkpoint. This shows up as long duration checkpoints where
all the time is in the flush portion of the checkpoint, and then
would artificially decrease the disk flushes per second in the
onstat -g ckp output (which might cause people to think there
was some IO issue).
You would likely see the following if encountering the problem.
First, the main_loop thread will be running very frequently, but
if you can get a stack trace from it when it is yielding, it
would look like this:
yield_processor
ckpt_dskflush
checkpoint
main_loop
th_init_initgls
startup
Also, you would see some amount of buffers in onstat -b output
that had there xflags set to "80" (to be xlocked) and if you
were to trace the owner of those buffers, they would track back
to xchg threads of part of an index build.
onstat -b output:
IBM Informix Dynamic Server Version 12.10.FC12 -- On-Line (CKPT
INP) -- Up 7 days 23:13:04 -- 251036672 Kbytes
Buffers
address userthread flgs pagenum
memaddr nslots pgflgs xflgs owner waitlist
Buffer pool page size: 2048
6b19fe858 0 10807 23:1596663
cb17be000 14 10 80 240147388 0
6b1a08ad8 0 10807 23:1607198
cb1840000 12 10 80 16e73c638 0
6b1c65cb8 0 10807 23:1645611
cb3681800 11 10 80 126ec8518 0
6b1fa5b58 0 10807 23:1601752
cb601a000 14 10 80 254441718 0
...
Now we look up owner value in onstat -g ath output:
grep 240147388 onstat.g.ath*
3319075 2304ff2b0 240147388 1 cond wait
sortproc:0 17cpu xchg_2.1
Can also look for that owner value in onstat -g ses 0 output,
and we have the following:
session
#RSAM total used dynamic
id user tty pid hostname
threads memory memory explain
64299 informix - 6008 host1
23 4788224 2794520 off
tid name rstcb flags curstk status
...
3319075 xchg_2.1 240147388 Y-B-X-- 6815 cond wait
sortproc:0-
...
sqscb info
scb sqscb optofc pdqpriority
optcompind directives
15e798230 231cd3028 0 10 2
1
Sess SQL Current Iso Lock SQL
ISAM F.E.
Id Stmt type Database Lvl Mode ERR
ERR Vers Explain
64299 CREATE INDEX db1 CR Not Wait 0
0 9.24 Off
Current SQL statement (13) :
create index "informix".t1_idx1 on "informix".t1 (c1,
c2, c3) using btree in s07 online |
