onstat -l
Tristan asked what the undocumented "Buffer Waiting / Buffer ioproc flags" block (lines L-1..L-3) in onstat -l output on IDS 11.50 means, suspecting it signalled a problem behind occasional slow application response. Art Kagel explained these are the three rotating logical-log buffers and the lines indicate non-current buffers waiting to be flushed, which only matters if log-chunk I/O times (onstat -g iof) are high or the buffer is nearly full; Tristan's times were low (~0.006s) and bufused tiny. Fernando noted the output has existed since v4.x, is typically seen with unbuffered logging plus heavy commit rates (and with HDR/SDS, shown by 'G' flags in onstat -u), and suggested opening a PMR for documentation. No definitive resolution is recorded; Tristan planned to raise a PMR and consider buffered logging on the busiest database.
Auto-generated by DrWatson from the posts below — may be imperfect; read the full thread.
I'm seeing a couple of extra lines in the output of 'onstat -l', which I can't
find documented in the 11.50 administrators guide and references.
The lines in question look like this:
Buffer Waiting
Buffer ioproc flags
L-1 0 0x1 0
L-2 0 0x1 0
The exact lines varies (L-1 through to L-4 I think), and sometimes the entire
block simply isn't there.
My naive assumption is that this probably represents a problem, and if
something is waiting on buffers long enough for it to show in onstat -l for
several seconds at a time?
Is anyone familiar with what this actually means?
Thanks,
Tristan
There are three logical log buffers: L-1, L-2, & L-3. The current buffer
rotates among these three. While one is being written to disk the next one
is used, etc. I don't remember seeing this output, but it may indicate that
one or both of the buffers which is not current are waiting to be written
out. This can become a problem if the IO subsystem is so slow that all
three buffers are full and logical log records must wait to be written to a
buffer until one can be flushed and released for reuse. What are the IO
service times reported for the logical log chunk(s) in onstat -g iof? If
these are high, say over 0.025secs, you may have an IO bottleneck on those
chunks.
Art
Art S. Kagel
Advanced DataTools (www.advancedatatools.com)
IIUG Board of Directors (art@iiug.org)
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions and
do not reflect on my employer, Advanced DataTools, 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, Dec 7, 2010 at 6:58 PM, Tristan Ball <tristanb@pronto.com.au> wrote:
> I'm seeing a couple of extra lines in the output of 'onstat -l', which I
> can't
> find documented in the 11.50 administrators guide and references.
>
> The lines in question look like this:
>
> Buffer Waiting
> Buffer ioproc flags
> L-1 0 0x1 0
> L-2 0 0x1 0
>
> The exact lines varies (L-1 through to L-4 I think), and sometimes the
> entire
> block simply isn't there.
>
> My naive assumption is that this probably represents a problem, and if
> something is waiting on buffers long enough for it to show in onstat -l for
> several seconds at a time?
>
> Is anyone familiar with what this actually means?
>
> Thanks,
>
> Tristan
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--485b393ab8495e10a10496dc775c
Thanks Art.
The service times in iostat -g iof are low, 0.0059, or 0.0060 for the logical
log chunks.
However we do rotate through the log buffers very quickly, although I never
see the bufused for the logical log buffers go higher than 2, however given
the statement/transaction rate on this database is fairly high (10k to
100k/sec), and my understanding that the log buffers will flush (& rotate?) on
commit/prepare's amoung other things, that seems normal.
Given the high rate of rotation on those buffers, I suspect it's possible that
we're waiting on buffer flushes even with low service times from disk.
The root of why I ask is that I'm chasing occasional slow response in the
application in front of this database, which appears to be database related.
I'm seeing some very high individual statement runtimes in sqltrace output,
for very simple requests - however apparently our release of IDS has bugs with
regards to reporting sql trace timings, so I can't really trust them.
Thanks again for your time, I think I might log this with IBM and see what
they say.
Regards,
Tristan
-----Original Message-----
From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of Art Kagel
Sent: Wednesday, 8 December 2010 12:59 PM
To: ids@iiug.org
Subject: Re: onstat -l [22149]
There are three logical log buffers: L-1, L-2, & L-3. The current buffer
rotates among these three. While one is being written to disk the next one is
used, etc. I don't remember seeing this output, but it may indicate that one
or both of the buffers which is not current are waiting to be written out.
This can become a problem if the IO subsystem is so slow that all three
buffers are full and logical log records must wait to be written to a buffer
until one can be flushed and released for reuse. What are the IO service times
reported for the logical log chunk(s) in onstat -g iof? If these are high, say
over 0.025secs, you may have an IO bottleneck on those chunks.
Art
Art S. Kagel
Advanced DataTools (www.advancedatatools.com) IIUG Board of Directors
(art@iiug.org)
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions and
do not reflect on my employer, Advanced DataTools, 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, Dec 7, 2010 at 6:58 PM, Tristan Ball <tristanb@pronto.com.au> wrote:
> I'm seeing a couple of extra lines in the output of 'onstat -l', which
> I can't find documented in the 11.50 administrators guide and
> references.
>
> The lines in question look like this:
>
> Buffer Waiting
> Buffer ioproc flags
> L-1 0 0x1 0
> L-2 0 0x1 0
>
> The exact lines varies (L-1 through to L-4 I think), and sometimes the
> entire block simply isn't there.
>
> My naive assumption is that this probably represents a problem, and if
> something is waiting on buffers long enough for it to show in onstat
> -l for several seconds at a time?
>
> Is anyone familiar with what this actually means?
>
> Thanks,
>
> Tristan
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--485b393ab8495e10a10496dc775c
*******************************************************************************
Forum Note: Use "Reply" to post a response in the discussion forum.
Logical log bufers are flushed when they fill if the database containing all
of the transactions in the buffer uses buffered logging and either when they
fill or when a commit or rollback is written to the log if the database to
which the commit/rollback belongs uses unbuffered logging. Onstat -l will
show you the percent full of the log buffer and the number of pages flushed
to the buffer on average. If the full percentage is close to 100% or the
number of pages flushed to the logical logs per io is close to the size of
the log buffers, you may need to increase the logical log buffer size. It
should be a bit larger than say two average sized transactions as a rule of
thumb.
Art S. Kagel
Advanced DataTools (www.advancedatatools.com)
IIUG Board of Directors (art@iiug.org)
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions and
do not reflect on my employer, Advanced DataTools, 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 Wed, Dec 8, 2010 at 4:41 PM, Tristan Ball <tristanb@pronto.com.au> wrote:
> Thanks Art.
>
> The service times in iostat -g iof are low, 0.0059, or 0.0060 for the
> logical
> log chunks.
>
> However we do rotate through the log buffers very quickly, although I never
> see the bufused for the logical log buffers go higher than 2, however given
> the statement/transaction rate on this database is fairly high (10k to
> 100k/sec), and my understanding that the log buffers will flush (& rotate?)
> on
> commit/prepare's amoung other things, that seems normal.
>
> Given the high rate of rotation on those buffers, I suspect it's possible
> that
> we're waiting on buffer flushes even with low service times from disk.
>
> The root of why I ask is that I'm chasing occasional slow response in the
> application in front of this database, which appears to be database
> related.
> I'm seeing some very high individual statement runtimes in sqltrace output,
> for very simple requests - however apparently our release of IDS has bugs
> with
> regards to reporting sql trace timings, so I can't really trust them.
>
> Thanks again for your time, I think I might log this with IBM and see what
> they say.
>
> Regards,
>
> Tristan
>
> -----Original Message-----
> From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of Art
> Kagel
> Sent: Wednesday, 8 December 2010 12:59 PM
> To: ids@iiug.org
> Subject: Re: onstat -l [22149]
>
> There are three logical log buffers: L-1, L-2, & L-3. The current buffer
> rotates among these three. While one is being written to disk the next one
> is
> used, etc. I don't remember seeing this output, but it may indicate that
> one
> or both of the buffers which is not current are waiting to be written out.
> This can become a problem if the IO subsystem is so slow that all three
> buffers are full and logical log records must wait to be written to a
> buffer
> until one can be flushed and released for reuse. What are the IO service
> times
> reported for the logical log chunk(s) in onstat -g iof? If these are high,
> say
> over 0.025secs, you may have an IO bottleneck on those chunks.
>
> Art
>
> Art S. Kagel
> Advanced DataTools (www.advancedatatools.com) IIUG Board of Directors
> (art@iiug.org)
> Blog: http://informix-myview.blogspot.com/
>
> Disclaimer: Please keep in mind that my own opinions are my own opinions
> and
> do not reflect on my employer, Advanced DataTools, 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, Dec 7, 2010 at 6:58 PM, Tristan Ball <tristanb@pronto.com.au>
> wrote:
>
> > I'm seeing a couple of extra lines in the output of 'onstat -l', which
> > I can't find documented in the 11.50 administrators guide and
> > references.
> >
> > The lines in question look like this:
> >
> > Buffer Waiting
> > Buffer ioproc flags
> > L-1 0 0x1 0
> > L-2 0 0x1 0
> >
> > The exact lines varies (L-1 through to L-4 I think), and sometimes the
> > entire block simply isn't there.
> >
> > My naive assumption is that this probably represents a problem, and if
> > something is waiting on buffers long enough for it to show in onstat
> > -l for several seconds at a time?
> >
> > Is anyone familiar with what this actually means?
> >
> > Thanks,
> >
> > Tristan
> >
> >
> >
> >
>
>
>
*******************************************************************************
> > Forum Note: Use "Reply" to post a response in the discussion forum.
> >
> >
>
> --485b393ab8495e10a10496dc775c
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
--20cf30433efe3a60b40496ee2680
Nice... I started this reply by saying I haven't seen this output either...
But then I went into the knowledge base...
You may not believe it, but it's there since version 4.x at least. (tbstat
-l) :)
It was about time that someone documents it (assuming it isn't - I didn't
look - )
L-x means the logical buffer... Please confirm if you ever seen L-4, since
Art is right, it should be at most L-3
ioproc should be the thread identifier... No idea what "0" means. No idea
what the flags mean...
Do you have HDR or SDS setup? When you see this output you should also have
"G" flags on the onstat -u output.
This can be a serious problem if you have it frequently.
I believe there is material around this issues (when they are issues, not
saying that's your case) to write a small book :)
In HDR environments this is one of the reasons why the primary can be
impacted by secondary. We've seen several customer having problems, but too
many times the cause is related to poor configuration or too much load on
the secondary (there was a chat with the labs session that dig into this).
So, I think there hasn't been enough "pressure" to solve this, and I suppose
there is no decision about the solution. Typically this is seen in
unbuffered logging databases together with high usage systems.
In unbuffered logging, each commit forces a logical log buffer flush, and
with many sessions this sometimes makes the 3 logical log buffers not enough
for the rotation needed. A simple solution would be to get more logical log
buffers, but I believe R&D would prefer a better solution.
Not much help, but if you require documentation on this, please open a PMR
and ask about it (I know customers have other/better things to do, but
that's the quickest way to get it done).
Regards.
On Wed, Dec 8, 2010 at 1:59 AM, Art Kagel <art.kagel@gmail.com> wrote:
> There are three logical log buffers: L-1, L-2, & L-3. The current buffer
> rotates among these three. While one is being written to disk the next one
> is used, etc. I don't remember seeing this output, but it may indicate that
> one or both of the buffers which is not current are waiting to be written
> out. This can become a problem if the IO subsystem is so slow that all
> three buffers are full and logical log records must wait to be written to a
> buffer until one can be flushed and released for reuse. What are the IO
> service times reported for the logical log chunk(s) in onstat -g iof? If
> these are high, say over 0.025secs, you may have an IO bottleneck on those
> chunks.
>
> Art
>
> Art S. Kagel
> Advanced DataTools (www.advancedatatools.com)
> IIUG Board of Directors (art@iiug.org)
> Blog: http://informix-myview.blogspot.com/
>
> Disclaimer: Please keep in mind that my own opinions are my own opinions
> and
> do not reflect on my employer, Advanced DataTools, 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, Dec 7, 2010 at 6:58 PM, Tristan Ball <tristanb@pronto.com.au>
> wrote:
>
> > I'm seeing a couple of extra lines in the output of 'onstat -l', which I
> > can't
> > find documented in the 11.50 administrators guide and references.
> >
> > The lines in question look like this:
> >
> > Buffer Waiting
> > Buffer ioproc flags
> > L-1 0 0x1 0
> > L-2 0 0x1 0
> >
> > The exact lines varies (L-1 through to L-4 I think), and sometimes the
> > entire
> > block simply isn't there.
> >
> > My naive assumption is that this probably represents a problem, and if
> > something is waiting on buffers long enough for it to show in onstat -l
> for
> > several seconds at a time?
> >
> > Is anyone familiar with what this actually means?
> >
> > Thanks,
> >
> > Tristan
> >
> >
> >
> >
>
>
*******************************************************************************
> > Forum Note: Use "Reply" to post a response in the discussion forum.
> >
> >
>
> --485b393ab8495e10a10496dc775c
>
>
>
>
*******************************************************************************
> 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...
--0015174c1102864fb90496ee5968
I think we're flushing on commits etc, rather than the buffer filling, unless
it fills between subsequent calls to onstat - and given the rate of rotation,
that's actually possible, but the pages/io implies not?
If we do an insert or update that isn't explicitly wrapped in a transaction,
would that also cause a log flush? From the looks of things, we only flush a
page or two for each rotation, but we're basically always rotating.
# while /bin/true; do echo ---------------;date; onstat -l |head -20|egrep
"(Waiting|ioproc|L-|Logical|recs)"; sleep 0.2;done
---------------
Thu Dec 9 12:17:53 EETDT 2010
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-1 0 16 287931350 16240274 9138448 17.7 1.8
Subsystem numrecs Log Space used
Buffer Waiting
Buffer ioproc flags
L-3 0 0x1 0
---------------
Thu Dec 9 12:17:54 EETDT 2010
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-3 0 16 287931350 16240274 9138448 17.7 1.8
Subsystem numrecs Log Space used
---------------
Thu Dec 9 12:17:54 EETDT 2010
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-1 0 16 287931350 16240274 9138448 17.7 1.8
Subsystem numrecs Log Space used
Buffer Waiting
Buffer ioproc flags
L-3 0 0x1 0
---------------
Thu Dec 9 12:17:54 EETDT 2010
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-1 0 16 287931350 16240274 9138448 17.7 1.8
Subsystem numrecs Log Space used
Buffer Waiting
Buffer ioproc flags
L-3 0 0x1 0
---------------
Thu Dec 9 12:17:54 EETDT 2010
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-1 0 16 287935315 16240912 9139083 17.7 1.8
Subsystem numrecs Log Space used
Buffer Waiting
Buffer ioproc flags
L-3 0 0x1 0
---------------
Thu Dec 9 12:17:54 EETDT 2010
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-2 0 16 287935315 16240912 9139083 17.7 1.8
Subsystem numrecs Log Space used
Buffer Waiting
Buffer ioproc flags
L-1 0 0x1 0
---------------
Thu Dec 9 12:17:55 EETDT 2010
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
L-1 1 16 287935315 16240912 9139083 17.7 1.8
Subsystem numrecs Log Space used
Buffer Waiting
Buffer ioproc flags
L-3 0 0x1 0
-----Original Message-----
From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of Art Kagel
Sent: Thursday, 9 December 2010 10:05 AM
To: ids@iiug.org
Subject: Re: onstat -l [22171]
Logical log bufers are flushed when they fill if the database containing all
of the transactions in the buffer uses buffered logging and either when they
fill or when a commit or rollback is written to the log if the database to
which the commit/rollback belongs uses unbuffered logging. Onstat -l will show
you the percent full of the log buffer and the number of pages flushed to the
buffer on average. If the full percentage is close to 100% or the number of
pages flushed to the logical logs per io is close to the size of the log
buffers, you may need to increase the logical log buffer size. It should be a
bit larger than say two average sized transactions as a rule of thumb.
Art S. Kagel
Advanced DataTools (www.advancedatatools.com<http://www.advancedatatools.com>)
IIUG Board of Directors (art@iiug.org<mailto:art@iiug.org>)
Blog: http://informix-myview.blogspot.com/
Disclaimer: Please keep in mind that my own opinions are my own opinions and
do not reflect on my employer, Advanced DataTools, 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 Wed, Dec 8, 2010 at 4:41 PM, Tristan Ball
<tristanb@pronto.com.au<mailto:tristanb@pronto.com.au>> wrote:
> Thanks Art.
>
> The service times in iostat -g iof are low, 0.0059, or 0.0060 for the
> logical log chunks.
>
> However we do rotate through the log buffers very quickly, although I
> never see the bufused for the logical log buffers go higher than 2,
> however given the statement/transaction rate on this database is
> fairly high (10k to 100k/sec), and my understanding that the log
> buffers will flush (& rotate?) on commit/prepare's amoung other
> things, that seems normal.
>
> Given the high rate of rotation on those buffers, I suspect it's
> possible that we're waiting on buffer flushes even with low service
> times from disk.
>
> The root of why I ask is that I'm chasing occasional slow response in
> the application in front of this database, which appears to be
> database related.
> I'm seeing some very high individual statement runtimes in sqltrace
> output, for very simple requests - however apparently our release of
> IDS has bugs with regards to reporting sql trace timings, so I can't
> really trust them.
>
> Thanks again for your time, I think I might log this with IBM and see
> what they say.
>
> Regards,
>
> Tristan
>
> -----Original Message-----
> From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of
> Art Kagel
> Sent: Wednesday, 8 December 2010 12:59 PM
> To: ids@iiug.org
> Subject: Re: onstat -l [22149]
>
> There are three logical log buffers: L-1, L-2, & L-3. The current
> buffer rotates among these three. While one is being written to disk
> the next one is used, etc. I don't remember seeing this output, but it
> may indicate that one or both of the buffers which is not current are
> waiting to be written out.
> This can become a problem if the IO subsystem is so slow that all
> three buffers are full and logical log records must wait to be written
> to a buffer until one can be flushed and released for reuse. What are
> the IO service times reported for the logical log chunk(s) in onstat
> -g iof? If these are high, say over 0.025secs, you may have an IO
> bottleneck on those chunks.
>
> Art
>
> Art S. Kagel
> Advanced DataTools
(www.advancedatatools.com<http://www.advancedatatools.com>) IIUG Board of
Directors
> (art@iiug.org<mailto:art@iiug.org>)
> Blog: http://informix-myview.blogspot.com/
>
> Disclaimer: Please keep in mind that my own opinions are my own
> opinions and do not reflect on my employer, Advanced DataTools, the
> IIUG, nor any other organization with which I am a
You're flushing about 4k at a time with a 16k buffer size so....
Yes. If not in a transaction each statement behaves like it is wrapped in
one and will flush.
Art
On Dec 8, 2010 8:25 PM, "Tristan Ball" <tristanb@pronto.com.au> wrote:
> I think we're flushing on commits etc, rather than the buffer filling,
unless
> it fills between subsequent calls to onstat - and given the rate of
rotation,
> that's actually possible, but the pages/io implies not?
>
> If we do an insert or update that isn't explicitly wrapped in a
transaction,
> would that also cause a log flush? From the looks of things, we only flush
a
> page or two for each rotation, but we're basically always rotating.
>
> # while /bin/true; do echo ---------------;date; onstat -l |head -20|egrep
> "(Waiting|ioproc|L-|Logical|recs)"; sleep 0.2;done
>
> ---------------
>
> Thu Dec 9 12:17:53 EETDT 2010
>
> Logical Logging
>
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
>
> L-1 0 16 287931350 16240274 9138448 17.7 1.8
>
> Subsystem numrecs Log Space used
>
> Buffer Waiting
>
> Buffer ioproc flags
>
> L-3 0 0x1 0
>
> ---------------
>
> Thu Dec 9 12:17:54 EETDT 2010
>
> Logical Logging
>
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
>
> L-3 0 16 287931350 16240274 9138448 17.7 1.8
>
> Subsystem numrecs Log Space used
>
> ---------------
>
> Thu Dec 9 12:17:54 EETDT 2010
>
> Logical Logging
>
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
>
> L-1 0 16 287931350 16240274 9138448 17.7 1.8
>
> Subsystem numrecs Log Space used
>
> Buffer Waiting
>
> Buffer ioproc flags
>
> L-3 0 0x1 0
>
> ---------------
>
> Thu Dec 9 12:17:54 EETDT 2010
>
> Logical Logging
>
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
>
> L-1 0 16 287931350 16240274 9138448 17.7 1.8
>
> Subsystem numrecs Log Space used
>
> Buffer Waiting
>
> Buffer ioproc flags
>
> L-3 0 0x1 0
>
> ---------------
>
> Thu Dec 9 12:17:54 EETDT 2010
>
> Logical Logging
>
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
>
> L-1 0 16 287935315 16240912 9139083 17.7 1.8
>
> Subsystem numrecs Log Space used
>
> Buffer Waiting
>
> Buffer ioproc flags
>
> L-3 0 0x1 0
>
> ---------------
>
> Thu Dec 9 12:17:54 EETDT 2010
>
> Logical Logging
>
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
>
> L-2 0 16 287935315 16240912 9139083 17.7 1.8
>
> Subsystem numrecs Log Space used
>
> Buffer Waiting
>
> Buffer ioproc flags
>
> L-1 0 0x1 0
>
> ---------------
>
> Thu Dec 9 12:17:55 EETDT 2010
>
> Logical Logging
>
> Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io
>
> L-1 1 16 287935315 16240912 9139083 17.7 1.8
>
> Subsystem numrecs Log Space used
>
> Buffer Waiting
>
> Buffer ioproc flags
>
> L-3 0 0x1 0
>
> -----Original Message-----
> From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of Art
> Kagel
> Sent: Thursday, 9 December 2010 10:05 AM
> To: ids@iiug.org
> Subject: Re: onstat -l [22171]
>
> Logical log bufers are flushed when they fill if the database containing
all
> of the transactions in the buffer uses buffered logging and either when
they
> fill or when a commit or rollback is written to the log if the database to
> which the commit/rollback belongs uses unbuffered logging. Onstat -l will
show
> you the percent full of the log buffer and the number of pages flushed to
the
> buffer on average. If the full percentage is close to 100% or the number
of
> pages flushed to the logical logs per io is close to the size of the log
> buffers, you may need to increase the logical log buffer size. It should
be a
> bit larger than say two average sized transactions as a rule of thumb.
>
> Art S. Kagel
>
> Advanced DataTools (www.advancedatatools.com<
http://www.advancedatatools.com>)
> IIUG Board of Directors (art@iiug.org<mailto:art@iiug.org>)
>
> Blog: http://informix-myview.blogspot.com/
>
> Disclaimer: Please keep in mind that my own opinions are my own opinions
and
> do not reflect on my employer, Advanced DataTools, 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 Wed, Dec 8, 2010 at 4:41 PM, Tristan Ball
> <tristanb@pronto.com.au<mailto:tristanb@pronto.com.au>> wrote:
>
>> Thanks Art.
>
>>
>
>> The service times in iostat -g iof are low, 0.0059, or 0.0060 for the
>
>> logical log chunks.
>
>>
>
>> However we do rotate through the log buffers very quickly, although I
>
>> never see the bufused for the logical log buffers go higher than 2,
>
>> however given the statement/transaction rate on this database is
>
>> fairly high (10k to 100k/sec), and my understanding that the log
>
>> buffers will flush (& rotate?) on commit/prepare's amoung other
>
>> things, that seems normal.
>
>>
>
>> Given the high rate of rotation on those buffers, I suspect it's
>
>> possible that we're waiting on buffer flushes even with low service
>
>> times from disk.
>
>>
>
>> The root of why I ask is that I'm chasing occasional slow response in
>
>> the application in front of this database, which appears to be
>
>> database related.
>
>> I'm seeing some very high individual statement runtimes in sqltrace
>
>> output, for very simple requests - however apparently our release of
>
>> IDS has bugs with regards to reporting sql trace timings, so I can't
>
>> really trust them.
>
>>
>
>> Thanks again for your time, I think I might log this with IBM and see
>
>> what they say.
>
>>
>
>> Regards,
>
>>
>
>> Tristan
>
>>
>
>> -----Original Message-----
>
>> From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of
>
>> Art Kagel
>
>> Sent: Wednesday, 8 December 2010 12:59 PM
>
>> To: ids@iiug.org
>
>> Subject: Re: onstat -l [22149]
>
>>
>
>> There are three logical log buffers: L-1, L-2, & L-3. The current
>
>> buffer rotates among these three. While one is being written to disk
>
>> the next one is used, etc. I don't remember seeing this output, but it
>
>> may indicate that one or both of the buffers which is not current are
>
>> waiting to be written out.
>
>> This can become a problem if the IO subsystem is so slow that all
>
>> three buffers are full and logical log records must wait to be written
>
>> to a buffer until one can be flushed and released for reuse. What are
>
>>
Hi Fernando.
I intend to raise a PMR, I just wanted to check with the general community as
to whether this was a common scenario, and to try and understand what the
possible impacts might be.
You're right, we only get L-1 through L-3, not sure where I pulled L-4 from.
We're not using either SDR or HDR in this instance, it's just a single
standalone server.
This particular environment has about 45 databases under a single Informix
instance. Of those, one particular DB sees about 90%+ of the traffic, because
the application uses it for amount other things, scratch storage. We could
also accept the data loss of using buffered logging on that database only, on
the grounds that I think we would end up rotating the logical log buffers much
less frequently, and if these waits are actually a problem, that may alleviate
it.
Onstat -u doesn't ever seem to show G in the flags, so perhaps this isn't
actually a problem?
Thanks for your input.
Regards,
Tristan
-----Original Message-----
From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of Fernando
Nunes
Sent: Thursday, 9 December 2010 10:19 AM
To: ids@iiug.org
Subject: Re: onstat -l [22172]
Nice... I started this reply by saying I haven't seen this output either...
But then I went into the knowledge base...
You may not believe it, but it's there since version 4.x at least. (tbstat
-l) :)
It was about time that someone documents it (assuming it isn't - I didn't look
- )
L-x means the logical buffer... Please confirm if you ever seen L-4, since Art
is right, it should be at most L-3 ioproc should be the thread identifier...
No idea what "0" means. No idea what the flags mean...
Do you have HDR or SDS setup? When you see this output you should also have
"G" flags on the onstat -u output.
This can be a serious problem if you have it frequently.
I believe there is material around this issues (when they are issues, not
saying that's your case) to write a small book :)
In HDR environments this is one of the reasons why the primary can be impacted
by secondary. We've seen several customer having problems, but too many times
the cause is related to poor configuration or too much load on the secondary
(there was a chat with the labs session that dig into this).
So, I think there hasn't been enough "pressure" to solve this, and I suppose
there is no decision about the solution. Typically this is seen in unbuffered
logging databases together with high usage systems.
In unbuffered logging, each commit forces a logical log buffer flush, and with
many sessions this sometimes makes the 3 logical log buffers not enough for
the rotation needed. A simple solution would be to get more logical log
buffers, but I believe R&D would prefer a better solution.
Not much help, but if you require documentation on this, please open a PMR and
ask about it (I know customers have other/better things to do, but that's the
quickest way to get it done).
Regards.
On Wed, Dec 8, 2010 at 1:59 AM, Art Kagel <art.kagel@gmail.com> wrote:
> There are three logical log buffers: L-1, L-2, & L-3. The current
> buffer rotates among these three. While one is being written to disk
> the next one is used, etc. I don't remember seeing this output, but it
> may indicate that one or both of the buffers which is not current are
> waiting to be written out. This can become a problem if the IO
> subsystem is so slow that all three buffers are full and logical log
> records must wait to be written to a buffer until one can be flushed
> and released for reuse. What are the IO service times reported for the
> logical log chunk(s) in onstat -g iof? If these are high, say over
> 0.025secs, you may have an IO bottleneck on those chunks.
>
> Art
>
> Art S. Kagel
> Advanced DataTools (www.advancedatatools.com) IIUG Board of Directors
> (art@iiug.org)
> Blog: http://informix-myview.blogspot.com/
>
> Disclaimer: Please keep in mind that my own opinions are my own
> opinions and do not reflect on my employer, Advanced DataTools, 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, Dec 7, 2010 at 6:58 PM, Tristan Ball <tristanb@pronto.com.au>
> wrote:
>
> > I'm seeing a couple of extra lines in the output of 'onstat -l',
> > which I can't find documented in the 11.50 administrators guide and
> > references.
> >
> > The lines in question look like this:
> >
> > Buffer Waiting
> > Buffer ioproc flags
> > L-1 0 0x1 0
> > L-2 0 0x1 0
> >
> > The exact lines varies (L-1 through to L-4 I think), and sometimes
> > the entire block simply isn't there.
> >
> > My naive assumption is that this probably represents a problem, and
> > if something is waiting on buffers long enough for it to show in
> > onstat -l> for
> > several seconds at a time?
> >
> > Is anyone familiar with what this actually means?
> >
> > Thanks,
> >
> > Tristan
> >
> >
> >
> >
>
>
*******************************************************************************
> > Forum Note: Use "Reply" to post a response in the discussion forum.
> >
> >
>
> --485b393ab8495e10a10496dc775c
>
>
>
>
*******************************************************************************
> 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...
--0015174c1102864fb90496ee5968
*******************************************************************************
Forum Note: Use "Reply" to post a response in the discussion forum.
On Thu, Dec 9, 2010 at 2:07 AM, Tristan Ball <tristanb@pronto.com.au> wrote:
> Hi Fernando.
>
> I intend to raise a PMR, I just wanted to check with the general community
> as
> to whether this was a common scenario, and to try and understand what the
> possible impacts might be.
>
> You're right, we only get L-1 through L-3, not sure where I pulled L-4
> from.
> We're not using either SDR or HDR in this instance, it's just a single
> standalone server.
>
> This particular environment has about 45 databases under a single Informix
> instance. Of those, one particular DB sees about 90%+ of the traffic,
> because
> the application uses it for amount other things, scratch storage. We could
> also accept the data loss of using buffered logging on that database only,
> on
> the grounds that I think we would end up rotating the logical log buffers
> much
> less frequently, and if these waits are actually a problem, that may
> alleviate
> it.
>
> Onstat -u doesn't ever seem to show G in the flags, so perhaps this isn't
> actually a problem?
>
If you don't get G flags, it's probably not an issue. And for the G flags to
appear, you'd probably have all 3 logical log buffers in the output.
If you have only 1 or 2, you still have 2 or 1 to go on....
This is one of the cases where onstat "rate" is not enough... a system will
probably change logical log buffers many times while you display a single
onstat interaction.
I've seen slowness due to G flags occasionally, but on that situations I've
always noticed G flags a lot. (each onstat -u brings a lot of sessions with
G flag, constantly)
Regards.
Regards.
>
> Thanks for your input.
>
> Regards,
>
> Tristan
>
> -----Original Message-----
> From: ids-bounces@iiug.org [mailto:ids-bounces@iiug.org] On Behalf Of
> Fernando
> Nunes
> Sent: Thursday, 9 December 2010 10:19 AM
> To: ids@iiug.org
> Subject: Re: onstat -l [22172]
>
> Nice... I started this reply by saying I haven't seen this output either...
> But then I went into the knowledge base...
> You may not believe it, but it's there since version 4.x at least. (tbstat
> -l) :)
> It was about time that someone documents it (assuming it isn't - I didn't
> look
> - )
>
> L-x means the logical buffer... Please confirm if you ever seen L-4, since
> Art
> is right, it should be at most L-3 ioproc should be the thread
> identifier...
> No idea what "0" means. No idea what the flags mean...
>
> Do you have HDR or SDS setup? When you see this output you should also have
> "G" flags on the onstat -u output.
> This can be a serious problem if you have it frequently.
> I believe there is material around this issues (when they are issues, not
> saying that's your case) to write a small book :)
>
> In HDR environments this is one of the reasons why the primary can be
> impacted
> by secondary. We've seen several customer having problems, but too many
> times
> the cause is related to poor configuration or too much load on the
> secondary
> (there was a chat with the labs session that dig into this).
> So, I think there hasn't been enough "pressure" to solve this, and I
> suppose
> there is no decision about the solution. Typically this is seen in
> unbuffered
> logging databases together with high usage systems.
> In unbuffered logging, each commit forces a logical log buffer flush, and
> with
> many sessions this sometimes makes the 3 logical log buffers not enough for
> the rotation needed. A simple solution would be to get more logical log
> buffers, but I believe R&D would prefer a better solution.
>
> Not much help, but if you require documentation on this, please open a PMR
> and
> ask about it (I know customers have other/better things to do, but that's
> the
> quickest way to get it done).
>
> Regards.
>
> On Wed, Dec 8, 2010 at 1:59 AM, Art Kagel <art.kagel@gmail.com> wrote:
>
> > There are three logical log buffers: L-1, L-2, & L-3. The current
> > buffer rotates among these three. While one is being written to disk
> > the next one is used, etc. I don't remember seeing this output, but it
> > may indicate that one or both of the buffers which is not current are
> > waiting to be written out. This can become a problem if the IO
> > subsystem is so slow that all three buffers are full and logical log
> > records must wait to be written to a buffer until one can be flushed
> > and released for reuse. What are the IO service times reported for the
> > logical log chunk(s) in onstat -g iof? If these are high, say over
> > 0.025secs, you may have an IO bottleneck on those chunks.
> >
> > Art
> >
> > Art S. Kagel
> > Advanced DataTools (www.advancedatatools.com) IIUG Board of Directors
> > (art@iiug.org)
> > Blog: http://informix-myview.blogspot.com/
> >
> > Disclaimer: Please keep in mind that my own opinions are my own
> > opinions and do not reflect on my employer, Advanced DataTools, 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, Dec 7, 2010 at 6:58 PM, Tristan Ball <tristanb@pronto.com.au>
> > wrote:
> >
> > > I'm seeing a couple of extra lines in the output of 'onstat -l',
> > > which I can't find documented in the 11.50 administrators guide and
> > > references.
> > >
> > > The lines in question look like this:
> > >
> > > Buffer Waiting
> > > Buffer ioproc flags
> > > L-1 0 0x1 0
> > > L-2 0 0x1 0
> > >
> > > The exact lines varies (L-1 through to L-4 I think), and sometimes
> > > the entire block simply isn't there.
> > >
> > > My naive assumption is that this probably represents a problem, and
> > > if something is waiting on buffers long enough for it to show in
> > > onstat -l> > for
> > > several seconds at a time?
> > >
> > > Is anyone familiar with what this actually means?
> > >
> > > Thanks,
> > >
> > > Tristan
> > >
> > >
> > >
> > >
> >
> >
>
>
>
*******************************************************************************
> > > Forum Note: Use "Reply" to post a response in the discussion forum.
> > >
> > >
> >
> > --485b393ab8495e10a10496dc775c
> >
> >
> >
> >
>
>
>
*******************************************************************************
> > 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...
>
> --0015174c1102864fb90496ee5968
>
>
>
>
*******************************************************************************
> Forum Note: Use "Reply" to post a response in the discussion forum.
>
>
>
>
*******************************************************************************