 | |
[Info-Ingres] interpreting log_trace output
comp.databases.ingres comp.databases.ingres
 |
| | Thread Tools | Display Modes |
#1
 
| |||
| |||
|
[Info-Ingres] interpreting log_trace output -
05-14-2009
, 04:01 AM
#2
| |||
| |||
|
|
Hi everyone, I'm running on 9.0.4 and it appears to be logging excessively. I have an insert of 140000 rows, each row being 171 bytes. The log file is composedof 500000 x 4k buffers. The table being inserted is a heap structure with no secondary indexes or constraints. There are no rules being fired by the insert. The only transaction in the logfile is this insert. And yet it blows the log file. Using log_trace on a small scale example:…. ************************************************** ****************** LOG: BT Size written/reserved: 80/ 56 Flags: LOG: PUT Size written/reserved: 276/ 152 Flags: …and then 10 more puts … LOG: ALLOC Size written/reserved: 101/ 148 Flags: LOG: OVERFLOW Size written/reserved: 101/ 148 Flags: LOG: PUT Size written/reserved: 276/ 152 Flags: …and then 10 more puts … LOG: BMINI Size written/reserved: 0/ 0 Flags: LOG: EXTEND Size written/reserved: 676/ 676 Flags: LOG: EMINI Size written/reserved: 40/ 0 Flags: CLR LOG: ALLOC Size written/reserved: 101/ 148 Flags: LOG: OVERFLOW Size written/reserved: 101/ 148 Flags: LOG: PUT Size written/reserved: 276/ 152 Flags: To me, this looks like it’s saying each row takes 276 bytes to write and that we appear to be getting 11 rows per buffer. So then: 1. Why is an insert of 171 bytes taking 276 to log? I thought the logging overhead was about 70bytes not 105. Or am I misinterpretting the written/reserved figures? 2. 11 * 276 = 3036 < 4096…so it doesn't look like we are filling thelog buffers. But if we get 11 rows per buffer, the entire transaction should take (140000/11)=12727 buffers. Double that for CLR's, and call it 26000 buffers. How the hell did we just blow the 500000 buffer log file out of the water? Martin Bowes _______________________________________________ Info-Ingres mailing list Info-Ingres (AT) kettleriverconsulting (DOT) com http://www.kettleriverconsulting.com...fo/info-ingres |
--
Paul Mason
#3
| |||
| |||
|
|
From the log_trace information that you have provided shows that when you have filled a page another one is being "added" to the heap, this is |
LOG: ALLOC Size written/reserved: 101/ 148 Flags:
LOG: OVERFLOW Size written/reserved: 101/ 148 Flags:
So you need to add that to your calculation.
When the table has reached the end of its allocated pages, the default
is 4 pages, then the table is extended, the default is 16 pages, when an
extend is done this is seen as:
LOG: BMINI Size written/reserved: 0/ 0 Flags:
LOG: EXTEND Size written/reserved: 676/ 676 Flags:
LOG: EMINI Size written/reserved: 40/ 0 Flags: CLR
So you need to add that to your calculation.
It is better to pre-allocate the space up front, use the modify
statement with clause "allocation = n" and allocate something large and
also use the modify with clause "extend = n" again to something larger
than 16. Both of these will cut down on the log writes and will also
speed up the insert process.
As for how much is being logged per row, remember that there is not only
a "logging overhead" per row but there is also a row overhead because
you are using a page size greater that 2K.
Hope this helps
John
From: info-ingres-bounces (AT) kettleriver...ting (DOT) com
[mailto:info-ingres-bounces (AT) kettleriverconsulting (DOT) com] On Behalf Of
Martin Bowes
Sent: 14 May 2009 10:02
To: Ingres and related product discussion forum
Subject: [Info-Ingres] interpreting log_trace output
Hi everyone,
I'm running on 9.0.4 and it appears to be logging excessively. I have an
insert of 140000 rows, each row being 171 bytes. The log file is
composed of 500000 x 4k buffers. The table being inserted is a heap
structure with no secondary indexes or constraints. There are no rules
being fired by the insert. The only transaction in the logfile is this
insert.
And yet it blows the log file.
Using log_trace on a small scale example:....
************************************************** ******************
LOG: BT Size written/reserved: 80/ 56 Flags:
LOG: PUT Size written/reserved: 276/ 152 Flags:
...and then 10 more puts ...
LOG: ALLOC Size written/reserved: 101/ 148 Flags:
LOG: OVERFLOW Size written/reserved: 101/ 148 Flags:
LOG: PUT Size written/reserved: 276/ 152 Flags:
...and then 10 more puts ...
LOG: BMINI Size written/reserved: 0/ 0 Flags:
LOG: EXTEND Size written/reserved: 676/ 676 Flags:
LOG: EMINI Size written/reserved: 40/ 0 Flags: CLR
LOG: ALLOC Size written/reserved: 101/ 148 Flags:
LOG: OVERFLOW Size written/reserved: 101/ 148 Flags:
LOG: PUT Size written/reserved: 276/ 152 Flags:
To me, this looks like it's saying each row takes 276 bytes to write and
that we appear to be getting 11 rows per buffer.
So then:
1. Why is an insert of 171 bytes taking 276 to log? I thought the
logging overhead was about 70bytes not 105. Or am I misinterpretting the
written/reserved figures?
2. 11 * 276 = 3036 < 4096...so it doesn't look like we are filling the
log buffers.
But if we get 11 rows per buffer, the entire transaction should take
(140000/11)=12727 buffers.
Double that for CLR's, and call it 26000 buffers.
How the hell did we just blow the 500000 buffer log file out of the
water?
Martin Bowes
#4
| |||
| |||
|
|
Hi everyone, I'm running on 9.0.4 and it appears to be logging excessively. ... [snip] To me, this looks like it’s saying each row takes 276 bytes to write and that we appear to be getting 11 rows per buffer. So then: 1. Why is an insert of 171 bytes taking 276 to log? I thought the logging overhead was about 70bytes not 105. Or am I misinterpretting the written/reserved figures? The log record overhead for a put is on the order of 36 bytes plus |
log record header, which is about 50-ish bytes. But it turns out
that it
also logs the table name and owner as part of the put record. That
is probably
where your extra bytes are.
Quote:
|
2. 11 * 276 = 3036 < 4096…so it doesn't look like we are filling the log buffers. The EMINI's are forced, so the log buffer is written unconditionally |
no matter how full it is. They aren't often enough to explain your
numbers,
though.
It might be forcing because of writing out cache pages, but that
seems a bit odd
as well; no reason that the table pages should be so picked on.
I wonder if your version was still forcing ALLOC's. That would
explain some of
the excessive log writing, at least. There was a change dated early
last
year to stop forcing ALLOC log records on fast commit, sole-cache
servers;
I have no idea how that change date translates to versions and
patches, though.
If your Ingres predates this change, it will be forcing ALLOC's and
EXTEND's;
the latter occurs immediately before the EMINI which is also forced. It
could be wasting the equivalent of 3 or 4 log buffers at every extend
point,
which is 16 table pages for the default extend= setting.
Quote:
|
But if we get 11 rows per buffer, the entire transaction should take (140000/11)=12727 buffers. Double that for CLR's, and call it 26000 buffers. How the hell did we just blow the 500000 buffer log file out of the water? Well, remember that force abort limit is usually something like 70% of |
something is astray, or at least not understood.
Karl
#5
| |||
| |||
|
#6
| |||
| |||
|
|
Paranoid…me? Why are you all against me! Marty |
#7
| |||
| |||
|
|
Hi everyone, I'm running on 9.0.4 and it appears to be logging excessively. ... [snip] To me, this looks like it's saying each row takes 276 bytes to write and that we appear to be getting 11 rows per buffer. So then: 1. Why is an insert of 171 bytes taking 276 to log? I thought the logging overhead was about 70bytes not 105. Or am I misinterpretting the written/reserved figures? The log record overhead for a put is on the order of 36 bytes plus |
log record header, which is about 50-ish bytes. But it turns out
that it
also logs the table name and owner as part of the put record. That
is probably
where your extra bytes are.
Quote:
|
2. 11 * 276 = 3036 < 4096...so it doesn't look like we are filling the log buffers. The EMINI's are forced, so the log buffer is written unconditionally |
no matter how full it is. They aren't often enough to explain your
numbers,
though.
It might be forcing because of writing out cache pages, but that
seems a bit odd
as well; no reason that the table pages should be so picked on.
I wonder if your version was still forcing ALLOC's. That would
explain some of
the excessive log writing, at least. There was a change dated early
last
year to stop forcing ALLOC log records on fast commit, sole-cache
servers;
I have no idea how that change date translates to versions and
patches, though.
If your Ingres predates this change, it will be forcing ALLOC's and
EXTEND's;
the latter occurs immediately before the EMINI which is also forced. It
could be wasting the equivalent of 3 or 4 log buffers at every extend
point,
which is 16 table pages for the default extend= setting.
Quote:
|
But if we get 11 rows per buffer, the entire transaction should take (140000/11)=12727 buffers. Double that for CLR's, and call it 26000 buffers. How the hell did we just blow the 500000 buffer log file out of the water? Well, remember that force abort limit is usually something like 70% of |
something is astray, or at least not understood.
Karl
_______________________________________________
Info-Ingres mailing list
Info-Ingres (AT) kettleriverconsulting (DOT) com
http://www.kettleriverconsulting.com...fo/info-ingres
#8
| |||
| |||
|
|
Hi everyone, I'm running on 9.0.4 and it appears to be logging excessively. ... [snip] To me, this looks like it's saying each row takes 276 bytes to write and that we appear to be getting 11 rows per buffer. So then: 1. Why is an insert of 171 bytes taking 276 to log? I thought the logging overhead was about 70bytes not 105. Or am I misinterpretting the written/reserved figures? The log record overhead for a put is on the order of 36 bytes plus |
log record header, which is about 50-ish bytes. But it turns out
that it
also logs the table name and owner as part of the put record. That
is probably
where your extra bytes are.
Quote:
|
2. 11 * 276 = 3036 < 4096...so it doesn't look like we are filling the log buffers. The EMINI's are forced, so the log buffer is written unconditionally |
no matter how full it is. They aren't often enough to explain your
numbers,
though.
It might be forcing because of writing out cache pages, but that
seems a bit odd
as well; no reason that the table pages should be so picked on.
I wonder if your version was still forcing ALLOC's. That would
explain some of
the excessive log writing, at least. There was a change dated early
last
year to stop forcing ALLOC log records on fast commit, sole-cache
servers;
I have no idea how that change date translates to versions and
patches, though.
If your Ingres predates this change, it will be forcing ALLOC's and
EXTEND's;
the latter occurs immediately before the EMINI which is also forced. It
could be wasting the equivalent of 3 or 4 log buffers at every extend
point,
which is 16 table pages for the default extend= setting.
Quote:
|
But if we get 11 rows per buffer, the entire transaction should take (140000/11)=12727 buffers. Double that for CLR's, and call it 26000 buffers. How the hell did we just blow the 500000 buffer log file out of the water? Well, remember that force abort limit is usually something like 70% of |
something is astray, or at least not understood.
Karl
_______________________________________________
Info-Ingres mailing list
Info-Ingres (AT) kettleriverconsulting (DOT) com
http://www.kettleriverconsulting.com...fo/info-ingres
_______________________________________________
Info-Ingres mailing list
Info-Ingres (AT) kettleriverconsulting (DOT) com
http://www.kettleriverconsulting.com...fo/info-ingres
#9
| |||
| |||
|
|
What exact version are you on? The bug Karl is referring to is bug 119663, I believe: 119663 (GENERIC) The transaction logging process reserves far more space than is required for recovery, especially when the transaction log file has a large buffer size. |
deeper than just reservations; it caused a lot of excess log forcing,
which wastes written (not just reserved) log space.
Karl
Quote:
|
-----Original Message----- From: info-ingres-bounces (AT) kettleriver...ting (DOT) com [mailto:info-ingres-bounces (AT) kettleriverconsulting (DOT) com] On Behalf Of Karl & Betty Schendel Sent: 14 May 2009 12:19 To: Ingres and related product discussion forum Subject: Re: [Info-Ingres] interpreting log_trace output On May 14, 2009, at 5:01 AM, Martin Bowes wrote: Hi everyone, I'm running on 9.0.4 and it appears to be logging excessively. ... [snip] To me, this looks like it's saying each row takes 276 bytes to write and that we appear to be getting 11 rows per buffer. So then: 1. Why is an insert of 171 bytes taking 276 to log? I thought the logging overhead was about 70bytes not 105. Or am I misinterpretting the written/reserved figures? The log record overhead for a put is on the order of 36 bytes plus the standard log record header, which is about 50-ish bytes. But it turns out that it also logs the table name and owner as part of the put record. That is probably where your extra bytes are. 2. 11 * 276 = 3036 < 4096...so it doesn't look like we are filling the log buffers. The EMINI's are forced, so the log buffer is written unconditionally at that point, no matter how full it is. They aren't often enough to explain your numbers, though. It might be forcing because of writing out cache pages, but that seems a bit odd as well; no reason that the table pages should be so picked on. I wonder if your version was still forcing ALLOC's. That would explain some of the excessive log writing, at least. There was a change dated early last year to stop forcing ALLOC log records on fast commit, sole-cache servers; I have no idea how that change date translates to versions and patches, though. If your Ingres predates this change, it will be forcing ALLOC's and EXTEND's; the latter occurs immediately before the EMINI which is also forced. It could be wasting the equivalent of 3 or 4 log buffers at every extend point, which is 16 table pages for the default extend= setting. But if we get 11 rows per buffer, the entire transaction should take (140000/11)=12727 buffers. Double that for CLR's, and call it 26000 buffers. How the hell did we just blow the 500000 buffer log file out of the water? Well, remember that force abort limit is usually something like 70% of the log, so you don't really have 500,000 blocks. But it does seem like something is astray, or at least not understood. Karl _______________________________________________ Info-Ingres mailing list Info-Ingres (AT) kettleriverconsulting (DOT) com http://www.kettleriverconsulting.com...fo/info-ingres _______________________________________________ Info-Ingres mailing list Info-Ingres (AT) kettleriverconsulting (DOT) com http://www.kettleriverconsulting.com...fo/info-ingres |
#10
| |||
| |||
|
|
« Previous Thread
|
Next Thread »
| Thread Tools | |
| Display Modes | |
Linear Mode
| |
Powered by vBulletin Version 3.5.3
Copyright ©2000 - 2012, Jelsoft Enterprises Ltd.
Copyright ©2000 - 2012, Jelsoft Enterprises Ltd.