Performance issue

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 sqlexecbase: 0x00000003aff07000 len: 135168 pc: 0x00000000012ce881 tos: 0x00000003aff25190 state: sleeping vp: 1 0x00000000012ce881 (/opt/informix/bin/oninit) yield_processor_mvp 0x00000000012d76df (/opt/informix/bin/oninit) mt_yield 0x0000000000e975a7 (/opt/informix/bin/oninit) logm_flush 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_idxinsert 0x000000000139bdea (/opt/informix/bin/oninit) fmwrite 0x0000000000688d82 (/opt/informix/bin/oninit) aud_sqiswrite 0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons 0x00000000007da790 (/opt/informix/bin/oninit) addone 0x00000000007de57a (/opt/informix/bin/oninit) insone_next 0x00000000008399b7 (/opt/informix/bin/oninit) doinsert 0x00000000005af784 (/opt/informix/bin/oninit) excommand 0x00000000009abfd0 (/opt/informix/bin/oninit) sq_execute 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls 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 sqlexecbase: 0x00000003a7b48000 len: 135168 pc: 0x00000000012ce881 tos: 0x00000003a7b67250 state: cond wait vp: 8 0x00000000012ce881 (/opt/informix/bin/oninit) yield_processor_mvp 0x00000000012e1216 (/opt/informix/bin/oninit) mt_fast_wait 0x0000000000d52e82 (/opt/informix/bin/oninit) logwrite 0x0000000000e99b9e (/opt/informix/bin/oninit) logm_write 0x0000000000d504bb (/opt/informix/bin/oninit) logputx 0x0000000000ccd40f (/opt/informix/bin/oninit) rscommit 0x0000000000de2a6b (/opt/informix/bin/oninit) xa_commit 0x00000000009dd04b (/opt/informix/bin/oninit) ifx_common_xcommit 0x00000000009dd39d (/opt/informix/bin/oninit) sq_xcommit 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls 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

BTree Cleaner? > On 8 Jun 2015, at 16:42, 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_processor_mvp > 0x00000000012d76df (/opt/informix/bin/oninit) mt_yield > 0x0000000000e975a7 (/opt/informix/bin/oninit) logm_flush > 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_idxinsert > 0x000000000139bdea (/opt/informix/bin/oninit) fmwrite > 0x0000000000688d82 (/opt/informix/bin/oninit) aud_sqiswrite > 0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons > 0x00000000007da790 (/opt/informix/bin/oninit) addone > 0x00000000007de57a (/opt/informix/bin/oninit) insone_next > 0x00000000008399b7 (/opt/informix/bin/oninit) doinsert > 0x00000000005af784 (/opt/informix/bin/oninit) excommand > 0x00000000009abfd0 (/opt/informix/bin/oninit) sq_execute > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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_processor_mvp > 0x00000000012e1216 (/opt/informix/bin/oninit) mt_fast_wait > 0x0000000000d52e82 (/opt/informix/bin/oninit) logwrite > 0x0000000000e99b9e (/opt/informix/bin/oninit) logm_write > 0x0000000000d504bb (/opt/informix/bin/oninit) logputx > 0x0000000000ccd40f (/opt/informix/bin/oninit) rscommit > 0x0000000000de2a6b (/opt/informix/bin/oninit) xa_commit > 0x00000000009dd04b (/opt/informix/bin/oninit) ifx_common_xcommit > 0x00000000009dd39d (/opt/informix/bin/oninit) sq_xcommit > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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. >

lets see, I have stopped the btree scanner temporarily ... Waiting for tomorrow, cause in the evening, we never had this situation. Marcus Haarmann ----- Ursprüngliche Mail ----- Von: "Spokey Wheeler" <spokey.wheeler@gmail.com> An: ids@iiug.org Gesendet: Montag, 8. Juni 2015 17:50:10 Betreff: Re: Performance issue [35234] BTree Cleaner? > On 8 Jun 2015, at 16:42, 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_processor_mvp > 0x00000000012d76df (/opt/informix/bin/oninit) mt_yield > 0x0000000000e975a7 (/opt/informix/bin/oninit) logm_flush > 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_idxinsert > 0x000000000139bdea (/opt/informix/bin/oninit) fmwrite > 0x0000000000688d82 (/opt/informix/bin/oninit) aud_sqiswrite > 0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons > 0x00000000007da790 (/opt/informix/bin/oninit) addone > 0x00000000007de57a (/opt/informix/bin/oninit) insone_next > 0x00000000008399b7 (/opt/informix/bin/oninit) doinsert > 0x00000000005af784 (/opt/informix/bin/oninit) excommand > 0x00000000009abfd0 (/opt/informix/bin/oninit) sq_execute > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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_processor_mvp > 0x00000000012e1216 (/opt/informix/bin/oninit) mt_fast_wait > 0x0000000000d52e82 (/opt/informix/bin/oninit) logwrite > 0x0000000000e99b9e (/opt/informix/bin/oninit) logm_write > 0x0000000000d504bb (/opt/informix/bin/oninit) logputx > 0x0000000000ccd40f (/opt/informix/bin/oninit) rscommit > 0x0000000000de2a6b (/opt/informix/bin/oninit) xa_commit > 0x00000000009dd04b (/opt/informix/bin/oninit) ifx_common_xcommit > 0x00000000009dd39d (/opt/informix/bin/oninit) sq_xcommit > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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. > ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

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_IO 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_processor_mvp > 0x00000000012d76df (/opt/informix/bin/oninit) mt_yield > 0x0000000000e975a7 (/opt/informix/bin/oninit) logm_flush > 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_idxinsert > 0x000000000139bdea (/opt/informix/bin/oninit) fmwrite > 0x0000000000688d82 (/opt/informix/bin/oninit) aud_sqiswrite > 0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons > 0x00000000007da790 (/opt/informix/bin/oninit) addone > 0x00000000007de57a (/opt/informix/bin/oninit) insone_next > 0x00000000008399b7 (/opt/informix/bin/oninit) doinsert > 0x00000000005af784 (/opt/informix/bin/oninit) excommand > 0x00000000009abfd0 (/opt/informix/bin/oninit) sq_execute > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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_processor_mvp > 0x00000000012e1216 (/opt/informix/bin/oninit) mt_fast_wait > 0x0000000000d52e82 (/opt/informix/bin/oninit) logwrite > 0x0000000000e99b9e (/opt/informix/bin/oninit) logm_write > 0x0000000000d504bb (/opt/informix/bin/oninit) logputx > 0x0000000000ccd40f (/opt/informix/bin/oninit) rscommit > 0x0000000000de2a6b (/opt/informix/bin/oninit) xa_commit > 0x00000000009dd04b (/opt/informix/bin/oninit) ifx_common_xcommit > 0x00000000009dd39d (/opt/informix/bin/oninit) sq_xcommit > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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. > > M

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

Marcus You don't say whether this is running on 'real' tin or as a VM. Virtual I/O adapters give yet another layer of contention that may not be immediately visible or consistent :-( Keith On 8 June 2015 at 17:24, Art Kagel <art.kagel@gmail.com> wrote: > 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_IO 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_processor_mvp > > 0x00000000012d76df (/opt/informix/bin/oninit) mt_yield > > 0x0000000000e975a7 (/opt/informix/bin/oninit) logm_flush > > 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_idxinsert > > 0x000000000139bdea (/opt/informix/bin/oninit) fmwrite > > 0x0000000000688d82 (/opt/informix/bin/oninit) aud_sqiswrite > > 0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons > > 0x00000000007da790 (/opt/informix/bin/oninit) addone > > 0x00000000007de57a (/opt/informix/bin/oninit) insone_next > > 0x00000000008399b7 (/opt/informix/bin/oninit) doinsert > > 0x00000000005af784 (/opt/informix/bin/oninit) excommand > > 0x00000000009abfd0 (/opt/informix/bin/oninit) sq_execute > > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > > 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_processor_mvp > > 0x00000000012e1216 (/opt/informix/bin/oninit) mt_fast_wait > > 0x0000000000d52e82 (/opt/informix/bin/oninit) logwrite > > 0x0000000000e99b9e (/opt/informix/bin/oninit) logm_write > > 0x0000000000d504bb (/opt/informix/bin/oninit) logputx > > 0x0000000000ccd40f (/opt/informix/bin/oninit) rscommit > > 0x0000000000de2a6b (/opt/informix/bin/oninit) xa_commit > > 0x00000000009dd04b (/opt/informix/bin/oninit) ifx_common_xcommit > > 0x00000000009dd39d (/opt/informix/bin/oninit) sq_xcommit > > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > > 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.

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üngliche 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_IO 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_processor_mvp > 0x00000000012d76df (/opt/informix/bin/oninit) mt_yield > 0x0000000000e975a7 (/opt/informix/bin/oninit) logm_flush > 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_idxinsert > 0x000000000139bdea (/opt/informix/bin/oninit) fmwrite > 0x0000000000688d82 (/opt/informix/bin/oninit) aud_sqiswrite > 0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons > 0x00000000007da790 (/opt/informix/bin/oninit) addone > 0x00000000007de57a (/opt/informix/bin/oninit) insone_next > 0x00000000008399b7 (/opt/informix/bin/oninit) doinsert > 0x00000000005af784 (/opt/informix/bin/oninit) excommand > 0x00000000009abfd0 (/opt/informix/bin/oninit) sq_execute > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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_processor_mvp > 0x00000000012e1216 (/opt/informix/bin/oninit) mt_fast_wait > 0x0000000000d52e82 (/opt/informix/bin/oninit) logwrite > 0x0000000000e99b9e (/opt/informix/bin/oninit) logm_write > 0x0000000000d504bb (/opt/informix/bin/oninit) logputx > 0x0000000000ccd40f (/opt/informix/bin/oninit) rscommit > 0x0000000000de2a6b (/opt/informix/bin/oninit) xa_commit > 0x00000000009dd04b (/opt/informix/bin/oninit) ifx_common_xcommit > 0x00000000009dd39d (/opt/informix/bin/oninit) sq_xcommit > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > 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

Check the RAID10 block/stripe size. If it is very large, then many IOs may be hitting only a single pair of drives rather than being spread across the array. 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 3:48 PM, Marcus Haarmann <marcus.haarmann@midoco.de> wrote: > 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üngliche 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_IO 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_processor_mvp > > 0x00000000012d76df (/opt/informix/bin/oninit) mt_yield > > 0x0000000000e975a7 (/opt/informix/bin/oninit) logm_flush > > 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_idxinsert > > 0x000000000139bdea (/opt/informix/bin/oninit) fmwrite > > 0x0000000000688d82 (/opt/informix/bin/oninit) aud_sqiswrite > > 0x000000000082a233 (/opt/informix/bin/oninit) chkrowcons > > 0x00000000007da790 (/opt/informix/bin/oninit) addone > > 0x00000000007de57a (/opt/informix/bin/oninit) insone_next > > 0x00000000008399b7 (/opt/informix/bin/oninit) doinsert > > 0x00000000005af784 (/opt/informix/bin/oninit) excommand > > 0x00000000009abfd0 (/opt/informix/bin/oninit) sq_execute > > 0x0000000000a6a3fb (/opt/informix/bin/oninit) sqmain > > 0x00000000013dbe3b (/opt/informix/bin/oninit) spawn_thread > > 0x00000000013151c0 (/opt/informix/bin/oninit) th_init_initgls > > 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 > > > > 0x00000000012ce

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

Another thing to think about. Since you have HDR, you might have had a short back flow from the secondary to the primary. Normally when that occurs we would see a different function at the top of the stack, but you might be capturing the diagnostics after the backflow has been resolved. So it might be worth it to ... 1) know the value of OFFLINE recovery threads on the secondary 2) know if it is possible that the primary and secondary are sharing the same physical resources. 3) get the output of onstat -g laq on the secondary server. And of course - the size of the physical and logical log buffer... M.Pruet 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 sqlexecbase: 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 sqlexecbase: 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.

>> What are the underlying disk structures (RAID level, etc.)? Can RAID level affect database performance then, Art ...?

Troll. > On 9 Jun 2015, at 12:09, NEIL TRUBY <neil.truby@ardenta.com> wrote: > >>> What are the underlying disk structures (RAID level, etc.)? > > Can RAID level affect database performance then, Art ...? > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. >

Troll ;-) 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 Tue, Jun 9, 2015 at 7:09 AM, NEIL TRUBY <neil.truby@ardenta.com> wrote: > >> What are the underlying disk structures (RAID level, etc.)? > > Can RAID level affect database performance then, Art ...? > > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > --001a113f934ef497eb0518141340

Harsh but fair Paul Watson Oninit www.oninit.com +1 913 387 7529 Oninit® is a Registered Trademark of Oninit LLC > On Jun 9, 2015, at 06:10, Spokey Wheeler <spokey.wheeler@gmail.com> wrote: > > Troll. > >> On 9 Jun 2015, at 12:09, NEIL TRUBY <neil.truby@ardenta.com> wrote: >> >>>> What are the underlying disk structures (RAID level, etc.)? >> >> Can RAID level affect database performance then, Art ...? >> >> >> > ******************************************************************************* >> Forum Note: Use "Reply" to post a response in the discussion forum. >> > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum.