IDS Forum

Re: Performance issue

Posted By: Madison Pruet
Date: Monday, 8 June 2015, at 12:35 p.m.

In Response To: Performance issue (Marcus Haarmann)

While your IO complex may be fast, you still need to be careful not to
overload it. Also you might want to check to make sure that your log
chunks are not on units that are having to do a lot of read activity.

From: "Marcus Haarmann" <marcus.haarmann@midoco.de>
To: ids@iiug.org
Date: 06/08/2015 10:43 AM
Subject: Performance issue [35233]
Sent by: ids-bounces@iiug.org

Hi experts,

we are encountering a performance problem on one of our database systems,
which happens periodically,
not limited to a specific high load.
The effect is that all our application servers are blocked with some
transactions (which are committing
at this time), until 20-30 seconds later all the threads are unblocked all
of
a sudden.
(in the same millisecond, spread over all client machines).
The common thing is that all these threads have a connection to a specific
database instance and
have all done mostly read-only work (within a XA transaction, which is
necessary to support multiple
datasources).
Since this effect is not really happening really regularly, but between 4-8

times spread over the day,
it is not easy to find out what is the main blocker here.

We have now done some measurements in the application to get the correct
time
when the situation occurs
and executed a script each 10 seconds to get some status information from
the
common DB instance.
The script put a timestamp in a log and executed onstat -g sql, followed by

onstat -g stk

What seems to be interesting:
1) online.log does not show anything when the effect occurs (no checkpoint,
no
full log, no entry at all)
2) What we found as common output ist the following thread during the
blocking
period:

Stack for thread: 1101943 sqlexec
base: 0x00000003aff07000
len: 135168
pc: 0x00000000012ce881
tos: 0x00000003aff25190
state: sleeping
vp: 1

0x00000000012ce881 (/opt/informix/bin/oninit) yield=5Fprocessor=5Fmvp
0x00000000012d76df (/opt/informix/bin/oninit) mt=5Fyield
0x0000000000e975a7 (/opt/informix/bin/oninit) logm=5Fflush
0x0000000000d526ef (/opt/informix/bin/oninit) logflush
0x0000000000d21e55 (/opt/informix/bin/oninit) bfphysflush
0x0000000000d22a37 (/opt/informix/bin/oninit) bfphyslogx
0x0000000000cfe082 (/opt/informix/bin/oninit) btadditem
0x0000000000d00382 (/opt/informix/bin/oninit) rsbtadditem
0x00000000013be6b0 (/opt/informix/bin/oninit) fm=5Fidxinsert
0x000000000139bdea (/opt/informix/bin/oninit) fmwrite
0x0000000000688d82 (/opt/informix/bin/oninit) aud=5Fsqiswrite
0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons
0x00000000007da790 (/opt/informix/bin/oninit) addone
0x00000000007de57a (/opt/informix/bin/oninit) insone=5Fnext
0x00000000008399b7 (/opt/informix/bin/oninit) doinsert
0x00000000005af784 (/opt/informix/bin/oninit) excommand
0x00000000009abfd0 (/opt/informix/bin/oninit) sq=5Fexecute
0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain
0x00000000013dbe3b (/opt/informix/bin/oninit) spawn=5Fthread
0x00000000013151c0 (/opt/informix/bin/oninit) th=5Finit=5Finitgls
0x00000000012e1a38 (/opt/informix/bin/oninit) startup

This seems to be an insert, which triggers an index (btree) write, which
triggers a physical log flush.
(there have been many inserts between the blocking times, which did not
trigger such a flush.
This only occurs sometimes.)

3) also a very high number of threads does the following:

Stack for thread: 905431 sqlexec
base: 0x00000003a7b48000
len: 135168
pc: 0x00000000012ce881
tos: 0x00000003a7b67250
state: cond wait
vp: 8

0x00000000012ce881 (/opt/informix/bin/oninit) yield=5Fprocessor=5Fmvp
0x00000000012e1216 (/opt/informix/bin/oninit) mt=5Ffast=5Fwait
0x0000000000d52e82 (/opt/informix/bin/oninit) logwrite
0x0000000000e99b9e (/opt/informix/bin/oninit) logm=5Fwrite
0x0000000000d504bb (/opt/informix/bin/oninit) logputx
0x0000000000ccd40f (/opt/informix/bin/oninit) rscommit
0x0000000000de2a6b (/opt/informix/bin/oninit) xa=5Fcommit
0x00000000009dd04b (/opt/informix/bin/oninit) ifx=5Fcommon=5Fxcommit
0x00000000009dd39d (/opt/informix/bin/oninit) sq=5Fxcommit
0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain
0x00000000013dbe3b (/opt/informix/bin/oninit) spawn=5Fthread
0x00000000013151c0 (/opt/informix/bin/oninit) th=5Finit=5Finitgls
0x00000000012e1a38 (/opt/informix/bin/oninit) startup

This seems to be one of the threads blocking in commit. The reason is
obviously a logwrite call,
which it is waiting for. We have 95 threads a this time which have a
logwrite
stack member !

Now my question: How can we prevent this flushing ? Or make it happen
faster ?
Or are we on the wrong way when looking at the source of the problem ?
What is really happening during logwrite ? Since the hardware is relatively

new,
and the disk array is very fast, I/O should not be the problem.

We have here: IDS 11.70FC8XB8GE running on Linux x64, using huge memory
pages.

Machine has 24GB Ram, Database uses ~15GB.
Checkpoints are done on 3-4 seconds, flush time 1.5-2.4 seconds (this
cannot
trigger 20 seconds of
blocking from my point of view).
onstat -F shows only chunk writes. onstat -p shows 99,8% read cached and
86,47% write cached.
Physical log is 5GB, rarely used > 5%
Checkpoints occur each 300sec, no other triggers than interval.

The machine is paired with a secondary instance via HDR. HDR pair was up
and
running without any trace of
"real" activity (checkpoints 1 second).

Any idea will be appreciated, we cannot file a bug, since we are not able
to
reproduce the behaviour
or even present an onstat -a output.
Yes, the instance is loaded very high, but we have other instances with
equal
or higher load, which
are not behaving like this.

Marcus Haarmann

***************************************************************************=
****

Forum Note: Use "Reply" to post a response in the discussion forum.

Messages In This Thread

• Performance issue
  Marcus Haarmann -- Monday, 8 June 2015, at 11:42 a.m.
  • Re: Performance issue
    Spokey Wheeler -- Monday, 8 June 2015, at 11:50 a.m.
    • Re: Performance issue
      Marcus Haarmann -- Monday, 8 June 2015, at 12:17 p.m.
  • Re: Performance issue
    Art Kagel -- Monday, 8 June 2015, at 12:24 p.m.
    • Re: Performance issue
      Keith Simmons -- Monday, 8 June 2015, at 3:18 p.m.
    • Re: Performance issue
      Marcus Haarmann -- Monday, 8 June 2015, at 3:48 p.m.
      • Re: Performance issue
        Art Kagel -- Monday, 8 June 2015, at 3:57 p.m.
      • Re: Performance issue
        Madison Pruet -- Monday, 8 June 2015, at 4:35 p.m.
    • Re: Performance issue
      NEIL TRUBY -- Tuesday, 9 June 2015, at 7:09 a.m.
      • Re: Performance issue
        Spokey Wheeler -- Tuesday, 9 June 2015, at 7:10 a.m.
        • Re: Performance issue
          Paul Watson -- Tuesday, 9 June 2015, at 8:48 a.m.
      • Re: Performance issue
        Art Kagel -- Tuesday, 9 June 2015, at 7:30 a.m.
  • Re: Performance issue
    Madison Pruet -- Monday, 8 June 2015, at 12:35 p.m.
  • Re: Performance issue
    Madison Pruet -- Monday, 8 June 2015, at 4:39 p.m.

IDS Forum is maintained by Administrator with WebBBS 5.12.