Waits on the physical log buffer in v12.10

Hi, Since an upgrade to 12.10.FC10X1 (from 11.70) we are seeing a lot more waits on the physical log buffer. These waits don't seem to align with any business or general server activity. These manifest themselves as a mutex wait: onstat -s: Latches with lock or userthread set name address lock wait userthread physlog 4445b258 0 3fd4dcb50 868b08028 physb1 4445b2d8 0 868b08028 abefacb60 physb2 4445b3e0 0 0 868b08028 onstat -g lmx: Locked mutexes: mid addr name holder lkcnt waiter waittime 13484 4445b258 plogpl 10250890 0 10257705 8 10218244 8 10258577 8 10155091 8 10263606 8 [snip long list of waiters] We also see a lot of buffer waits, nearly all with pgflgs "890" which indicates: 800 - Physical log 80 - B-tree leaf-node page 10 - B-tree node page This problem did not exist to anything like the same extent in 11.70 and we have logging and diagnostics that demonstrate this. When we drill into what the userthread or holder of the mutex is doing, it is invariably an insert into a reasonably busy log table. However we believe that this thread is a "victim" of a wider server issue rather than the cause. Storage performance has been suspected and we have occasionally seen slight increases in write times (maximum 12 ms) around the problem but not always. Since the 11.70 upgrade all of the pre-existing parameters were largely untouched and we have increased PHYSBUFF to 2048 (from 512) to little or no effect. I noted Art's RFE around LOGBUFF and increasing the number of buffers. Could this be related? Ben.

Can you post a thread stack from onstat -g stk? Regards, David. > On 19 February 2018 at 13:54 BENJAMIN THOMPSON <benjamin.thompson@skybettingandgaming.com> wrote: > > > Hi, > > Since an upgrade to 12.10.FC10X1 (from 11.70) we are seeing a lot more waits > on the physical log buffer. These waits don't seem to align with any business > or general server activity. These manifest themselves as a mutex wait: > > onstat -s:> > Latches with lock or userthread set > name address lock wait userthread > physlog 4445b258 0 3fd4dcb50 868b08028 > physb1 4445b2d8 0 868b08028 abefacb60 > physb2 4445b3e0 0 0 868b08028 > > onstat -g lmx:> > Locked mutexes: > mid addr name holder lkcnt waiter waittime > 13484 4445b258 plogpl 10250890 0 10257705 8 > > 10218244 8 > > 10258577 8 > > 10155091 8 > > 10263606 8 > [snip long list of waiters] > > We also see a lot of buffer waits, nearly all with pgflgs "890" which > indicates: > 800 - Physical log > 80 - B-tree leaf-node page > 10 - B-tree node page > > This problem did not exist to anything like the same extent in 11.70 and we > have logging and diagnostics that demonstrate this. > > When we drill into what the userthread or holder of the mutex is doing, it is > invariably an insert into a reasonably busy log table. However we believe that > this thread is a "victim" of a wider server issue rather than the cause. > > Storage performance has been suspected and we have occasionally seen slight > increases in write times (maximum 12 ms) around the problem but not always. > > Since the 11.70 upgrade all of the pre-existing parameters were largely > untouched and we have increased PHYSBUFF to 2048 (from 512) to little or no > effect. > > I noted Art's RFE around LOGBUFF and increasing the number of buffers. Could > this be related? > > Ben. > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. >

Hi David, Presumably you are following http://www-01.ibm.com/support/docview.wss?uid=swg21653615 I think the stack you want is below. Ben. Stack for thread: 10250890 sqlexecbase: 0x0000000a8345f000 len: 151552 pc: 0x000000000140e8d6 tos: 0x0000000a8347ffd0 state: mutex wait vp: 10 0x000000000140e8d6 (/opt/informix/bin/oninit) yield_processor_mvp 0x000000000141ac0e (/opt/informix/bin/oninit) mt_lock_wait 0x000000000141c240 (/opt/informix/bin/oninit) mt_lock_helper 0x0000000000d9579a (/opt/informix/bin/oninit) bfphysflush 0x0000000000d9648e (/opt/informix/bin/oninit) bfphyslogx 0x0000000000d6e470 (/opt/informix/bin/oninit) btadditem 0x0000000000d7003f (/opt/informix/bin/oninit) rsbtadditem 0x00000000014f4d1b (/opt/informix/bin/oninit) fm_idxinsert 0x00000000014cd8a2 (/opt/informix/bin/oninit) fmwrite 0x00000000006c5332 (/opt/informix/bin/oninit) aud_sqiswrite 0x000000000088890f (/opt/informix/bin/oninit) chkrowcons 0x0000000000827d60 (/opt/informix/bin/oninit) addone 0x000000000082c7b9 (/opt/informix/bin/oninit) insone_next 0x0000000000894907 (/opt/informix/bin/oninit) doinsert 0x00000000005d2dd8 (/opt/informix/bin/oninit) excommand 0x000000000068beea (/opt/informix/bin/oninit) ip_evalsql 0x000000000069862d (/opt/informix/bin/oninit) runproc 0x00000000006995b0 (/opt/informix/bin/oninit) udrlm_spl_execute 0x0000000000a562fe (/opt/informix/bin/oninit) udrlm_exec_routine 0x00000000006d429c (/opt/informix/bin/oninit) udr_execute 0x000000000069a2bf (/opt/informix/bin/oninit) ip_curnext 0x000000000069b361 (/opt/informix/bin/oninit) ip_fetch 0x00000000007fb958 (/opt/informix/bin/oninit) getrow 0x00000000007fc1e8 (/opt/informix/bin/oninit) fetchrow 0x00000000005cf628 (/opt/informix/bin/oninit) exfetch 0x0000000000a17450 (/opt/informix/bin/oninit) sql_nfetch 0x0000000000a17a3b (/opt/informix/bin/oninit) sq_nfetch 0x0000000000adfb43 (/opt/informix/bin/oninit) sqmain 0x000000000151c32b (/opt/informix/bin/oninit) spawn_thread 0x00000000013e1d30 (/opt/informix/bin/oninit) th_init_initgls 0x000000000144aac8 (/opt/informix/bin/oninit) startup

I haven't seen this yet, but most customers didn't move yet. The one thing that comes to mind is the new index usage tracking feature... But that doesn't map perfectly with "INSERT" operations. However, the new data is stored in the partition header which needs to be changed on every INSERT/DELETE.... I expressed some concerns about these new feature. Acknowledging of course that it's very useful... I would suggest a ticket... Regards. On Mon, Feb 19, 2018 at 1:54 PM, BENJAMIN THOMPSON < benjamin.thompson@skybettingandgaming.com> wrote: > Hi, > > Since an upgrade to 12.10.FC10X1 (from 11.70) we are seeing a lot more > waits > on the physical log buffer. These waits don't seem to align with any > business > or general server activity. These manifest themselves as a mutex wait: > > onstat -s:> > Latches with lock or userthread set > name address lock wait userthread > physlog 4445b258 0 3fd4dcb50 868b08028 > physb1 4445b2d8 0 868b08028 abefacb60 > physb2 4445b3e0 0 0 868b08028 > > onstat -g lmx:> > Locked mutexes: > mid addr name holder lkcnt waiter waittime > 13484 4445b258 plogpl 10250890 0 10257705 8 > > 10218244 8 > > 10258577 8 > > 10155091 8 > > 10263606 8 > [snip long list of waiters] > > We also see a lot of buffer waits, nearly all with pgflgs "890" which > indicates: > 800 - Physical log > 80 - B-tree leaf-node page > 10 - B-tree node page > > This problem did not exist to anything like the same extent in 11.70 and we > have logging and diagnostics that demonstrate this. > > When we drill into what the userthread or holder of the mutex is doing, it > is > invariably an insert into a reasonably busy log table. However we believe > that > this thread is a "victim" of a wider server issue rather than the cause. > > Storage performance has been suspected and we have occasionally seen slight > increases in write times (maximum 12 ms) around the problem but not always. > > Since the 11.70 upgrade all of the pre-existing parameters were largely > untouched and we have increased PHYSBUFF to 2048 (from 512) to little or no > effect. > > I noted Art's RFE around LOGBUFF and increasing the number of buffers. > Could > this be related? > > Ben. > > > ************************************************************ > ******************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > -- Fernando Nunes Portugal http://informix-technology.blogspot.com My email works... but I don't check it frequently...

http://members.iiug.org/forums/ids/index.cgi/read/35233 has a similar stack and mentions checking - BT Scanner - HDR back pressure (some form of secondary in use?) Regards, David. > On 19 February 2018 at 14:48 BENJAMIN THOMPSON <benjamin.thompson@skybettingandgaming.com> wrote: > > > Hi David, > > Presumably you are following > http://www-01.ibm.com/support/docview.wss?uid=swg21653615 > > I think the stack you want is below. > > Ben. > > Stack for thread: 10250890 sqlexec> base: 0x0000000a8345f000 > len: 151552 > > pc: 0x000000000140e8d6 > tos: 0x0000000a8347ffd0 > state: mutex wait > > vp: 10 > > 0x000000000140e8d6 (/opt/informix/bin/oninit) yield_processor_mvp > 0x000000000141ac0e (/opt/informix/bin/oninit) mt_lock_wait > 0x000000000141c240 (/opt/informix/bin/oninit) mt_lock_helper > 0x0000000000d9579a (/opt/informix/bin/oninit) bfphysflush > 0x0000000000d9648e (/opt/informix/bin/oninit) bfphyslogx > 0x0000000000d6e470 (/opt/informix/bin/oninit) btadditem > 0x0000000000d7003f (/opt/informix/bin/oninit) rsbtadditem > 0x00000000014f4d1b (/opt/informix/bin/oninit) fm_idxinsert > 0x00000000014cd8a2 (/opt/informix/bin/oninit) fmwrite > 0x00000000006c5332 (/opt/informix/bin/oninit) aud_sqiswrite > 0x000000000088890f (/opt/informix/bin/oninit) chkrowcons > 0x0000000000827d60 (/opt/informix/bin/oninit) addone > 0x000000000082c7b9 (/opt/informix/bin/oninit) insone_next > 0x0000000000894907 (/opt/informix/bin/oninit) doinsert > 0x00000000005d2dd8 (/opt/informix/bin/oninit) excommand > 0x000000000068beea (/opt/informix/bin/oninit) ip_evalsql > 0x000000000069862d (/opt/informix/bin/oninit) runproc > 0x00000000006995b0 (/opt/informix/bin/oninit) udrlm_spl_execute > 0x0000000000a562fe (/opt/informix/bin/oninit) udrlm_exec_routine > 0x00000000006d429c (/opt/informix/bin/oninit) udr_execute > 0x000000000069a2bf (/opt/informix/bin/oninit) ip_curnext > 0x000000000069b361 (/opt/informix/bin/oninit) ip_fetch > 0x00000000007fb958 (/opt/informix/bin/oninit) getrow > 0x00000000007fc1e8 (/opt/informix/bin/oninit) fetchrow > 0x00000000005cf628 (/opt/informix/bin/oninit) exfetch > 0x0000000000a17450 (/opt/informix/bin/oninit) sql_nfetch > 0x0000000000a17a3b (/opt/informix/bin/oninit) sq_nfetch > 0x0000000000adfb43 (/opt/informix/bin/oninit) sqmain > 0x000000000151c32b (/opt/informix/bin/oninit) spawn_thread > 0x00000000013e1d30 (/opt/informix/bin/oninit) th_init_initgls > 0x000000000144aac8 (/opt/informix/bin/oninit) startup > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. >

BTree scanner is a good candidate and would explain the seemingly random nature of the problem since we haven't been looking at that explicitly. The difference between 12.10.FC10X1 and 12.10.FC10 is a patch that means the scanner is cleaning non-default page sizes properly, which apparently previous versions including all 11.70 did not do. This might be making it more aggressive. Ben.

Sounds possible. You don't happen to have any FC10? On Mon, Feb 19, 2018 at 4:17 PM, BENJAMIN THOMPSON < benjamin.thompson@skybettingandgaming.com> wrote: > BTree scanner is a good candidate and would explain the seemingly random > nature of the problem since we haven't been looking at that explicitly. The > difference between 12.10.FC10X1 and 12.10.FC10 is a patch that means the > scanner is cleaning non-default page sizes properly, which apparently > previous > versions including all 11.70 did not do. This might be making it more > aggressive. > > Ben. > > > ************************************************************ > ******************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > -- Fernando Nunes Portugal http://informix-technology.blogspot.com My email works... but I don't check it frequently...