IDS Forum

Re: Performance issue

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

In Response To: Re: Performance issue (Marcus Haarmann)

The stacks that you printed are from writes to the physical log and the
logical log. If you are seeing them a lot, then I would suspect the
following...

1) your logs are on the same physical device as chunks that you are doing a
lot of reads from.
2) Your logical/physical log buffer is possibly a bit too small

I would suspect that onstat -l would be useful to see. Also I would
suggest that the physical/logic log space/chunks be isolated from other
chunks. Given the nature of the log files, there would be an advantage to
completely isolate them because the vast majority of their activity is
going to be writes and sequential writes at that. Since the writes tend to
be sequential and serial, there is no real advantage to striping the log
file chunks.

I doubt that it has anything to do with the BTCleaner, unless the indexes
and log chunks are on the same physical device.

M.Pruet

From: "Marcus Haarmann" <marcus.haarmann@midoco.de>
To: ids@iiug.org
Date: 06/08/2015 02:49 PM
Subject: Re: Performance issue [35239]
Sent by: ids-bounces@iiug.org

Hi Art,

we have SAS harddisks with Raid10, connected with Fibre channel 8GBit.
The array is directly attached, no switches.
All partitions are raw with an lvm2 layer as partitioning help.
KAIO is worth a review, but first we will run without btree cleaner to
check
for influences
one at a time.
Logs are on a separate partition, but I think the admin did not put it on
separate disks.
We have to check the SAN layout, which I did not set up.
I will check if the indexes are fully separated, I doubt it, because the
primary/foreign keys
are most probably in the data dbs.
And yes, we are running without any virtualization, directly on the
machine,
no virtual drivers etc.
This hardware is dedicated to that Informix instance, also the disk array
is
only serving this instance,
so any external influence should be reduced to a minimum.
As always, there could be more buffering, but growth edition has some
limits
here ...

Marcus Haarmann

----- Urspr=FCngliche Mail -----

Von: "Art Kagel" <art.kagel@gmail.com>
An: ids@iiug.org
Gesendet: Montag, 8. Juni 2015 18:24:20
Betreff: Re: Performance issue [35236]

Marcus:

Spokey may have nailed it, the BT Scanner activity is certainly a
possibility, I also see that the first stack trace includes adding a new
key to an index which may have triggered that index to go over the hill and

be placed on the Btree hot list. It's worth looking into what the BT
Scanner is doing at the time of the next block incident.

Personally, I want to blame IO. You say: "the disk array is very fast, I/O
should not be the problem" but that doesn't mean much. Is it possible that
the chunks are on a SAN/NAS that is being shared with other applications
that may be interfering/contending for head placement or bandwidth? What
are the underlying disk structures (RAID level, etc.)? How is your read
ahead configured? Are the chunks for the logical and physical logs on the
same disk structures as each other? As the data? As the index? Are you
simply contending with yourself? Are the chunks RAW or COOKED? Is
DIRECT=5FIO enabled? Is KAIO configured with enough OS resources to cope?

Art

Art S. Kagel, President and Principal Consultant
ASK Database Management
www.askdbmgt.com

Blog: http://informix-myview.blogspot.com/

Disclaimer: Please keep in mind that my own opinions are my own opinions
and do not reflect on the IIUG, nor any other organization with which I am
associated either explicitly, implicitly, or by inference. Neither do
those opinions reflect those of other individuals affiliated with any
entity with which I am affiliated nor those of the entities themselves.

On Mon, Jun 8, 2015 at 11:42 AM, Marcus Haarmann
<marcus.haarmann@midoco.de>
wrote:

> 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.
>
>

--001a1140289caf92940518041266

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

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

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

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.