CPU usage problems when using KAIO in V7.3? on SINIX.
Description of problem with Informix 7.3* and SINIX.
This problem seems common to a number of Informix 7.30 and 7.31
for Sinix.
I do not know if there are specific releases of Informix for each
major subversion of SINIX or not.
The versions for which I have a detailed description are
ReliantUNIX-N 5.44 C0033 and Informix Dynamic Server Version 7.31.UC2.
The database is located on raw devices in which case Informix
uses kernel asynchronous I/O by default.
The problem I try to describe only occurs when I have an SQL-statement
that needs to read a large number of rows and only find a few matches.
In this case when I look into what happens with sar we see the %sys
is abnormally high
rmsanoisa.conf#rootm#/home/informix/informix/gestion>sar -ud 5 12
ReliantUNIX-N rmsano 5.44 C0033 RM400 10/13/99
00:39:30 %usr %sys %wio %idle int/s intdef/ device %busy avque r+w/s blks/s avwait avserv
00:39:35 28 72 0 0 1105 0
ios0/sdisk011 54.61 1.00 992 3969 0.50 0.55
00:39:40 27 73 0 0 1191 0
ios0/sdisk011 54.54 1.00 1078 4312 0.50 0.51
00:39:45 29 71 0 0 1158 0
ios0/sdisk011 54.90 1.00 1045 4182 0.50 0.53
00:39:50 25 75 0 0 1180 0
ios0/sdisk011 54.84 1.00 1070 4281 0.50 0.51
00:39:55 28 72 0 0 1183 0
ios0/sdisk010 0.62 2.94 1 16 11.80 6.20
ios0/sdisk011 53.84 1.00 1070 4279 0.50 0.50
When we examine with scstat what are the most called system calls
we see that the most called is
kaiopoll which ranges between 32.000 and 34.000 calls per second followed by
ioctl that is called around 1.070 times per second.
The number for the other system calls is insignificant (less than 10/sec).
I verified via ps -fe which were the active processes and found that only
the main oninit process is active.
As you can see on the 'grep oninit' both ps commands were executed
with an interval of 11 seconds and the CPU time used by process 1618
has increased with 11 seconds.
From this we can deduce that all CPU power is mobilized by the
oninit process.
rmsanoisa.conf#rootm#/home/informix/informix/gestion>ps -fe | grep oninit
root 1619 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1622 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1620 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1618 1 80 Oct 11 ? 63:10 /opt/lib/informix/bin/oninit
root 1621 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1624 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1623 1618 0 Oct 11 ? 0:01 /opt/lib/informix/bin/oninit
root 1727 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1625 1618 0 Oct 11 ? 17:23 /opt/lib/informix/bin/oninit
root 1726 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 8548 8524 2 00:40:27 pts/6 0:00 grep oninit
rmsanoisa.conf#rootm#/home/informix/informix/gestion>ps -fe | grep oninit
root 1619 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1622 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1620 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1618 1 79 Oct 11 ? 63:21 /opt/lib/informix/bin/oninit
root 1621 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1624 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1623 1618 0 Oct 11 ? 0:01 /opt/lib/informix/bin/oninit
root 1727 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 1625 1618 0 Oct 11 ? 17:23 /opt/lib/informix/bin/oninit
root 1726 1618 0 Oct 11 ? 0:00 /opt/lib/informix/bin/oninit
root 8550 8524 2 00:40:38 pts/6 0:00 grep oninit
As truss slows down too much the process I do not attach to much
value to the output of this command. I'm sure, and have seen it
on another system where I'm looking into the same problem a
large number a kaiopoll have a return value of 0. (See difference
in number of kaiopoll and ioctl in scstat).
This truss spans what happened in a timespan of 3 seconds,
but truss largely reduced
rmsanoisa.conf#rootm#/home/informix/informix/gestion>truss -fap 1618
1618: *** SGID: rgid/egid/sgid = 0 / 103 / 103 ***
1618: psargs: /opt/lib/informix/bin/oninit
1618: Received signal #14, SIGALRM [caught]
1618: kill(1618, SIG#0) = 0
1618: times(0x00000000245CB6E0) = 12711334
1618: alarm(3) = 01618: setcontext(0x00000000245CB720)
1618: kaiopoll(0x000000000000008F, 0x00000000244A97B0) = 1
1618: ioctl(11, 0xFFFFFFFF803C5305, 0x0000000024369308) = 0
DELETED 168 similar occurrences of kaiopoll and ioctl
1618: kaiopoll(0x000000000000008F, 0x00000000244A97B0) = 1
1618: ioctl(11, 0xFFFFFFFF803C5305, 0x0000000024369308) = 0
1618: kaiopoll(0x000000000000008F, 0x00000000244A97B0) = 1
1618: ioctl(11, 0xFFFFFFFF803C5305, 0x0000000024369308) = 0
1618: Received signal #14, SIGALRM [caught]
1618: kill(1618, SIG#0) = 0
1618: times(0x00000000245CB6E0) = 12711636
1618: alarm(3) = 0
Once I inhibit KAIO with KAIOOFF=1 then the CPU usage by Informix
becomes normal again but now my I/O is three times slower..
ReliantUNIX-N rmsano 5.44 C0033 RM400 10/13/99
00:46:20 %usr %sys %wio %idle int/s intdef/s device %busy avque r+w/s blks/s avwait avserv
00:46:25 0 2 0 98 1779 0
ios0/sdisk010 0.20 1.00 0 6 0.00 10.00
ios0/sdisk011 19.98 1.00 393 1573 0.50 0.51
00:46:30 0 1 1 98 1787 0
ios0/sdisk010 1.30 5.25 2 58 31.00 7.22
ios0/sdisk011 20.84 1.00 395 1580 0.50 0.53
00:46:35 0 3 10 86 1797 0
ios0/sdisk010 10.26 1.50 16 101 3.55 6.58
ios0/sdisk011 20.30 1.00 393 1574 0.50 0.52
00:46:40 0 1 2 96 1777 0
ios0/sdisk011 21.64 1.00 392 1568 0.50 0.55
This test was done with the following script :
isql sysmaster <<EOF >/tmp/mike 2>&1
SELECT trim(dbsname)||":"||trim(tabname)
FROM syspaghdr P, systabnames T
WHERE P.pg_flags = 208
AND P.pg_partnum > 1048570
AND P.pg_partnum = T.partnum
EOF
I'm open to all suggestions and requests for further information and tests.
Mike.