Long Checkpoints - cond wait(logbf2) with HDR and ER defined
Andrew reported 45-150 second checkpoints on IDS 10.0.UC5/RHEL3 during large deletes, with the deleting sqlexec thread often in 'cond wait(logbf2)', despite only ~3000 dirty pages flushed; the server was an HDR primary also doing ER to five read-only targets. Madison Pruet ruled out ER as a checkpoint blocker (no CRCOLS in use) and pointed at DRINTERVAL (left at the default 30) and the HDR send buffer, which is sized from LOGBUFF. TBP suggested shrinking LOGBUFF; Andrew argued for enlarging it, and Pruet agreed that a bigger log buffer increases HDR in-flight data and should ease the log-buffer waits, noting a future Cheetah change. No confirmed test result is recorded.
Auto-generated by DrWatson from the posts below — may be imperfect; read the full thread.
I'm running into some seriously long checkpoints (45 - 150 seconds) when
trying to delete data from a table (same results if dbdelete or straight
delete sql used).
lru_min_dirty and lru_max_dirty are configured in such a way that I am only
writing 3000 pages to disk at checkpoint time. I have verified that the
number of pages to be written to disk at checkpoint time is consistently
around the 3000 page number during normal operation (0 second checkpoints)
and when the delete is running. I am pretty confident this is not the
issue.
System Config:
IDS 10.0.UC5 on RHEL3.
HDR is configured with an average ping time of 0.149 ms between the two
servers.
ER is configured as Primary/Read-only replicating approx 400 tables from the
Primary HDR server to 5 Read-only servers (these servers are not explicitly
defined as leaf servers).
The database is using unbuffered logging.
When deletes are not running, the checkpoing times are consistently 0
seconds.
I notice that the state of the sqlexec thread for the delete session is
regurally 'cond wait(logbf2)' and onstat -l reports the following when the
checkpoints start to get nasty.
Logical Logging
Buffer bufused bufsize numrecs numpages numwrits recs/pages
pages/io
L-1 15 16 448937 42960 30056 10.5 1.4
Subsystem numrecs Log Space used
OLDRSAM 447569 36229356
CDR 1368 54792
Buffer Waiting
Buffer ioproc flags
L-1 69e768d4 0x1 0
L-3 6bf2a3a8 0x1 0
Is it possible that I am running into a contention problem with my log
buffers that is possibly being magnified by the need to replicate changes to
the secondary HDR server and the 5 ER servers which can cause my delete
session to spend more time than normal in a critical section?
Thanks in advance,
Andrew
Andrew Ford wrote:
> I'm running into some seriously long checkpoints (45 - 150 seconds) when
> trying to delete data from a table (same results if dbdelete or straight
> delete sql used).
>
> lru_min_dirty and lru_max_dirty are configured in such a way that I am only
On both the HDR primary and the HDR secondary??? Don't forget that the
HDR secondary has to flush the pages at checkpoint time as well.
> writing 3000 pages to disk at checkpoint time. I have verified that the
> number of pages to be written to disk at checkpoint time is consistently
> around the 3000 page number during normal operation (0 second checkpoints)
> and when the delete is running. I am pretty confident this is not the
> issue.
>
> System Config:
>
> IDS 10.0.UC5 on RHEL3.
>
> HDR is configured with an average ping time of 0.149 ms between the two
> servers.
>
> ER is configured as Primary/Read-only replicating approx 400 tables from the
> Primary HDR server to 5 Read-only servers (these servers are not explicitly
> defined as leaf servers).
>
> The database is using unbuffered logging.
>
> When deletes are not running, the checkpoing times are consistently 0
> seconds.
>
> I notice that the state of the sqlexec thread for the delete session is
> regurally 'cond wait(logbf2)' and onstat -l reports the following when the
> checkpoints start to get nasty.
>
> Logical Logging
> Buffer bufused bufsize numrecs numpages numwrits recs/pages
> pages/io
> L-1 15 16 448937 42960 30056 10.5 1.4
> Subsystem numrecs Log Space used
> OLDRSAM 447569 36229356
> CDR 1368 54792
>
> Buffer Waiting
> Buffer ioproc flags
> L-1 69e768d4 0x1 0
> L-3 6bf2a3a8 0x1 0
>
>
> Is it possible that I am running into a contention problem with my log
> buffers that is possibly being magnified by the need to replicate changes to
> the secondary HDR server and the 5 ER servers which can cause my delete
> session to spend more time than normal in a critical section?
The ER traffic would not cause the checkpoint to be blocked. However ER
would require that the rows be written to the delete tables if you have
configured CRCOLS.
Since the
>
> Thanks in advance,
>
> Andrew
>
>
> Andrew Ford wrote:
>> I'm running into some seriously long checkpoints (45 - 150 seconds) when
>> trying to delete data from a table (same results if dbdelete or straight
>> delete sql used).
>>
>> lru_min_dirty and lru_max_dirty are configured in such a way that I am
>> only
>
> On both the HDR primary and the HDR secondary??? Don't forget that the
> HDR secondary has to flush the pages at checkpoint time as well.
>
>
>> writing 3000 pages to disk at checkpoint time. I have verified that the
>> number of pages to be written to disk at checkpoint time is consistently
>> around the 3000 page number during normal operation (0 second
>> checkpoints) and when the delete is running. I am pretty confident this
>> is not the issue.
>>
>> System Config:
>>
>> IDS 10.0.UC5 on RHEL3.
>>
>> HDR is configured with an average ping time of 0.149 ms between the two
>> servers.
>>
>> ER is configured as Primary/Read-only replicating approx 400 tables from
>> the Primary HDR server to 5 Read-only servers (these servers are not
>> explicitly defined as leaf servers).
>>
>> The database is using unbuffered logging.
>>
>> When deletes are not running, the checkpoing times are consistently 0
>> seconds.
>>
>> I notice that the state of the sqlexec thread for the delete session is
>> regurally 'cond wait(logbf2)' and onstat -l reports the following when
>> the checkpoints start to get nasty.
>>
>> Logical Logging
>> Buffer bufused bufsize numrecs numpages numwrits recs/pages
>> pages/io
>> L-1 15 16 448937 42960 30056 10.5 1.4
>> Subsystem numrecs Log Space used
>> OLDRSAM 447569 36229356
>> CDR 1368 54792
>>
>> Buffer Waiting
>> Buffer ioproc flags
>> L-1 69e768d4 0x1 0
>> L-3 6bf2a3a8 0x1 0
>>
>>
>> Is it possible that I am running into a contention problem with my log
>> buffers that is possibly being magnified by the need to replicate changes
>> to the secondary HDR server and the 5 ER servers which can cause my
>> delete session to spend more time than normal in a critical section?
>
>
> The ER traffic would not cause the checkpoint to be blocked. However ER
> would require that the rows be written to the delete tables if you have
> configured CRCOLS.
>
> Since the
>>
>> Thanks in advance,
>>
>> Andrew
> On both the HDR primary and the HDR secondary??? Don't forget that the
> HDR secondary has to flush the pages at checkpoint time as well.
Both have the same lru_min/lru_max parameters. The checkpoints on the
secondary server are shorter than the checkpoints on the primary (example:
48 second ckpt on the primary, 8 second ckpt on the secondary at approx the
same start time).
> The ER traffic would not cause the checkpoint to be blocked. However ER
> would require that the rows be written to the delete tables if you have
> configured CRCOLS.
No CRCOLS defined on any of the 400 replicated tables, all Primary/Target
with ignore conflict resolution.
Andrew
Andrew Ford wrote:
>> Andrew Ford wrote:
>>> I'm running into some seriously long checkpoints (45 - 150 seconds) when
>>> trying to delete data from a table (same results if dbdelete or straight
>>> delete sql used).
>>>
>>> lru_min_dirty and lru_max_dirty are configured in such a way that I am
>>> only
>> On both the HDR primary and the HDR secondary??? Don't forget that the
>> HDR secondary has to flush the pages at checkpoint time as well.
DRINTERVAL???
>>
>>
>>> writing 3000 pages to disk at checkpoint time. I have verified that the
>>> number of pages to be written to disk at checkpoint time is consistently
>>> around the 3000 page number during normal operation (0 second
>>> checkpoints) and when the delete is running. I am pretty confident this
>>> is not the issue.
>>>
>>> System Config:
>>>
>>> IDS 10.0.UC5 on RHEL3.
>>>
>>> HDR is configured with an average ping time of 0.149 ms between the two
>>> servers.
>>>
>>> ER is configured as Primary/Read-only replicating approx 400 tables from
>>> the Primary HDR server to 5 Read-only servers (these servers are not
>>> explicitly defined as leaf servers).
>>>
>>> The database is using unbuffered logging.
>>>
>>> When deletes are not running, the checkpoing times are consistently 0
>>> seconds.
>>>
>>> I notice that the state of the sqlexec thread for the delete session is
>>> regurally 'cond wait(logbf2)' and onstat -l reports the following when
>>> the checkpoints start to get nasty.
>>>
>>> Logical Logging
>>> Buffer bufused bufsize numrecs numpages numwrits recs/pages
>>> pages/io
>>> L-1 15 16 448937 42960 30056 10.5 1.4
>>> Subsystem numrecs Log Space used
>>> OLDRSAM 447569 36229356
>>> CDR 1368 54792
>>>
>>> Buffer Waiting
>>> Buffer ioproc flags
>>> L-1 69e768d4 0x1 0
>>> L-3 6bf2a3a8 0x1 0
>>>
>>>
>>> Is it possible that I am running into a contention problem with my log
>>> buffers that is possibly being magnified by the need to replicate changes
>>> to the secondary HDR server and the 5 ER servers which can cause my
>>> delete session to spend more time than normal in a critical section?
>>
>> The ER traffic would not cause the checkpoint to be blocked. However ER
>> would require that the rows be written to the delete tables if you have
>> configured CRCOLS.
>>
>> Since the
>>> Thanks in advance,
>>>
>>> Andrew
>
>
>> On both the HDR primary and the HDR secondary??? Don't forget that the
>> HDR secondary has to flush the pages at checkpoint time as well.
>
> Both have the same lru_min/lru_max parameters. The checkpoints on the
> secondary server are shorter than the checkpoints on the primary (example:
> 48 second ckpt on the primary, 8 second ckpt on the secondary at approx the
> same start time).
>
>> The ER traffic would not cause the checkpoint to be blocked. However ER
>> would require that the rows be written to the delete tables if you have
>> configured CRCOLS.
>
> No CRCOLS defined on any of the 400 replicated tables, all Primary/Target
> with ignore conflict resolution.
>
> Andrew
>
>
> Andrew Ford wrote:
>>> Andrew Ford wrote:
>>>> I'm running into some seriously long checkpoints (45 - 150 seconds)
>>>> when trying to delete data from a table (same results if dbdelete or
>>>> straight delete sql used).
>>>>
>>>> lru_min_dirty and lru_max_dirty are configured in such a way that I am
>>>> only
>>> On both the HDR primary and the HDR secondary??? Don't forget that the
>>> HDR secondary has to flush the pages at checkpoint time as well.
>
> DRINTERVAL???
>
>>>
>>>
>>>> writing 3000 pages to disk at checkpoint time. I have verified that
>>>> the number of pages to be written to disk at checkpoint time is
>>>> consistently around the 3000 page number during normal operation (0
>>>> second checkpoints) and when the delete is running. I am pretty
>>>> confident this is not the issue.
>>>>
>>>> System Config:
>>>>
>>>> IDS 10.0.UC5 on RHEL3.
>>>>
>>>> HDR is configured with an average ping time of 0.149 ms between the two
>>>> servers.
>>>>
>>>> ER is configured as Primary/Read-only replicating approx 400 tables
>>>> from the Primary HDR server to 5 Read-only servers (these servers are
>>>> not explicitly defined as leaf servers).
>>>>
>>>> The database is using unbuffered logging.
>>>>
>>>> When deletes are not running, the checkpoing times are consistently 0
>>>> seconds.
>>>>
>>>> I notice that the state of the sqlexec thread for the delete session is
>>>> regurally 'cond wait(logbf2)' and onstat -l reports the following when
>>>> the checkpoints start to get nasty.
>>>>
>>>> Logical Logging
>>>> Buffer bufused bufsize numrecs numpages numwrits recs/pages
>>>> pages/io
>>>> L-1 15 16 448937 42960 30056 10.5
>>>> 1.4
>>>> Subsystem numrecs Log Space used
>>>> OLDRSAM 447569 36229356
>>>> CDR 1368 54792
>>>>
>>>> Buffer Waiting
>>>> Buffer ioproc flags
>>>> L-1 69e768d4 0x1 0
>>>> L-3 6bf2a3a8 0x1 0
>>>>
>>>>
>>>> Is it possible that I am running into a contention problem with my log
>>>> buffers that is possibly being magnified by the need to replicate
>>>> changes to the secondary HDR server and the 5 ER servers which can
>>>> cause my delete session to spend more time than normal in a critical
>>>> section?
>>>
>>> The ER traffic would not cause the checkpoint to be blocked. However ER
>>> would require that the rows be written to the delete tables if you have
>>> configured CRCOLS.
>>>
>>> Since the
>>>> Thanks in advance,
>>>>
>>>> Andrew
>>
>>
>>> On both the HDR primary and the HDR secondary??? Don't forget that the
>>> HDR secondary has to flush the pages at checkpoint time as well.
>>
>> Both have the same lru_min/lru_max parameters. The checkpoints on the
>> secondary server are shorter than the checkpoints on the primary
>> (example: 48 second ckpt on the primary, 8 second ckpt on the secondary
>> at approx the same start time).
>>
>>> The ER traffic would not cause the checkpoint to be blocked. However ER
>>> would require that the rows be written to the delete tables if you have
>>> configured CRCOLS.
>>
>> No CRCOLS defined on any of the 400 replicated tables, all Primary/Target
>> with ignore conflict resolution.
>>
>> Andrew
>
>
It is the default value of 30.
Will decreasing this value reduce checkpoint times?
Thanks,
Andrew
Andrew Ford wrote:
>> Andrew Ford wrote:
>>>> Andrew Ford wrote:
>>>>> I'm running into some seriously long checkpoints (45 - 150 seconds)
>>>>> when trying to delete data from a table (same results if dbdelete or
>>>>> straight delete sql used).
>>>>>
>>>>> lru_min_dirty and lru_max_dirty are configured in such a way that I am
>>>>> only
>>>> On both the HDR primary and the HDR secondary??? Don't forget that the
>>>> HDR secondary has to flush the pages at checkpoint time as well.
>> DRINTERVAL???
>>
>>>>
>>>>> writing 3000 pages to disk at checkpoint time. I have verified that
>>>>> the number of pages to be written to disk at checkpoint time is
>>>>> consistently around the 3000 page number during normal operation (0
>>>>> second checkpoints) and when the delete is running. I am pretty
>>>>> confident this is not the issue.
>>>>>
>>>>> System Config:
>>>>>
>>>>> IDS 10.0.UC5 on RHEL3.
>>>>>
>>>>> HDR is configured with an average ping time of 0.149 ms between the two
>>>>> servers.
>>>>>
>>>>> ER is configured as Primary/Read-only replicating approx 400 tables
>>>>> from the Primary HDR server to 5 Read-only servers (these servers are
>>>>> not explicitly defined as leaf servers).
>>>>>
>>>>> The database is using unbuffered logging.
>>>>>
>>>>> When deletes are not running, the checkpoing times are consistently 0
>>>>> seconds.
>>>>>
>>>>> I notice that the state of the sqlexec thread for the delete session is
>>>>> regurally 'cond wait(logbf2)' and onstat -l reports the following when
>>>>> the checkpoints start to get nasty.
>>>>>
>>>>> Logical Logging
>>>>> Buffer bufused bufsize numrecs numpages numwrits recs/pages
>>>>> pages/io
>>>>> L-1 15 16 448937 42960 30056 10.5
>>>>> 1.4
>>>>> Subsystem numrecs Log Space used
>>>>> OLDRSAM 447569 36229356
>>>>> CDR 1368 54792
>>>>>
>>>>> Buffer Waiting
>>>>> Buffer ioproc flags
>>>>> L-1 69e768d4 0x1 0
>>>>> L-3 6bf2a3a8 0x1 0
>>>>>
>>>>>
>>>>> Is it possible that I am running into a contention problem with my log
>>>>> buffers that is possibly being magnified by the need to replicate
>>>>> changes to the secondary HDR server and the 5 ER servers which can
>>>>> cause my delete session to spend more time than normal in a critical
>>>>> section?
On the assumption that you have just one process running, doing the
deletes, on this instance, for experimentation, reduce the LOGBUFF down
to 8 or 4 pages (i.e. 16k or 8k). You are not getting much out of 16
pages => 1.4.pages per IO.
> Andrew Ford wrote:
>>> Andrew Ford wrote:
>>>>> Andrew Ford wrote:
>>>>>> I'm running into some seriously long checkpoints (45 - 150 seconds)
>>>>>> when trying to delete data from a table (same results if dbdelete or
>>>>>> straight delete sql used).
>>>>>>
>>>>>> lru_min_dirty and lru_max_dirty are configured in such a way that I
>>>>>> am
>>>>>> only
>>>>> On both the HDR primary and the HDR secondary??? Don't forget that
>>>>> the
>>>>> HDR secondary has to flush the pages at checkpoint time as well.
>>> DRINTERVAL???
>>>
>>>>>
>>>>>> writing 3000 pages to disk at checkpoint time. I have verified that
>>>>>> the number of pages to be written to disk at checkpoint time is
>>>>>> consistently around the 3000 page number during normal operation (0
>>>>>> second checkpoints) and when the delete is running. I am pretty
>>>>>> confident this is not the issue.
>>>>>>
>>>>>> System Config:
>>>>>>
>>>>>> IDS 10.0.UC5 on RHEL3.
>>>>>>
>>>>>> HDR is configured with an average ping time of 0.149 ms between the
>>>>>> two
>>>>>> servers.
>>>>>>
>>>>>> ER is configured as Primary/Read-only replicating approx 400 tables
>>>>>> from the Primary HDR server to 5 Read-only servers (these servers are
>>>>>> not explicitly defined as leaf servers).
>>>>>>
>>>>>> The database is using unbuffered logging.
>>>>>>
>>>>>> When deletes are not running, the checkpoing times are consistently 0
>>>>>> seconds.
>>>>>>
>>>>>> I notice that the state of the sqlexec thread for the delete session
>>>>>> is
>>>>>> regurally 'cond wait(logbf2)' and onstat -l reports the following
>>>>>> when
>>>>>> the checkpoints start to get nasty.
>>>>>>
>>>>>> Logical Logging
>>>>>> Buffer bufused bufsize numrecs numpages numwrits recs/pages
>>>>>> pages/io
>>>>>> L-1 15 16 448937 42960 30056 10.5
>>>>>> 1.4
>>>>>> Subsystem numrecs Log Space used
>>>>>> OLDRSAM 447569 36229356
>>>>>> CDR 1368 54792
>>>>>>
>>>>>> Buffer Waiting
>>>>>> Buffer ioproc flags
>>>>>> L-1 69e768d4 0x1 0
>>>>>> L-3 6bf2a3a8 0x1 0
>>>>>>
>>>>>>
>>>>>> Is it possible that I am running into a contention problem with my
>>>>>> log
>>>>>> buffers that is possibly being magnified by the need to replicate
>>>>>> changes to the secondary HDR server and the 5 ER servers which can
>>>>>> cause my delete session to spend more time than normal in a critical
>>>>>> section?
>
> On the assumption that you have just one process running, doing the
> deletes, on this instance, for experimentation, reduce the LOGBUFF down
> to 8 or 4 pages (i.e. 16k or 8k). You are not getting much out of 16
> pages => 1.4.pages per IO.
I was actually thinking of increasing the size of the log buffers since the
HDR send and recieve buffers are always the same size as the log bufferes.
With unbuffered logging you don't get much out of the larger log buffers as
they are almost always immediately flushed to disk but there might be
something gained by increasing the buffer size for the HDR send and recieve
buffers that are drained when they become full.
Any thoughts on this?
Thanks,
Andrew
Andrew Ford wrote:
>> Andrew Ford wrote:
>>>> Andrew Ford wrote:
>>>>>> Andrew Ford wrote:
>>>>>>> I'm running into some seriously long checkpoints (45 - 150 seconds)
>>>>>>> when trying to delete data from a table (same results if dbdelete or
>>>>>>> straight delete sql used).
>>>>>>>
>>>>>>> lru_min_dirty and lru_max_dirty are configured in such a way that I
>>>>>>> am
>>>>>>> only
>>>>>> On both the HDR primary and the HDR secondary??? Don't forget that
>>>>>> the
>>>>>> HDR secondary has to flush the pages at checkpoint time as well.
>>>> DRINTERVAL???
>>>>
>>>>>>> writing 3000 pages to disk at checkpoint time. I have verified that
>>>>>>> the number of pages to be written to disk at checkpoint time is
>>>>>>> consistently around the 3000 page number during normal operation (0
>>>>>>> second checkpoints) and when the delete is running. I am pretty
>>>>>>> confident this is not the issue.
>>>>>>>
>>>>>>> System Config:
>>>>>>>
>>>>>>> IDS 10.0.UC5 on RHEL3.
>>>>>>>
>>>>>>> HDR is configured with an average ping time of 0.149 ms between the
>>>>>>> two
>>>>>>> servers.
>>>>>>>
>>>>>>> ER is configured as Primary/Read-only replicating approx 400 tables
>>>>>>> from the Primary HDR server to 5 Read-only servers (these servers are
>>>>>>> not explicitly defined as leaf servers).
>>>>>>>
>>>>>>> The database is using unbuffered logging.
>>>>>>>
>>>>>>> When deletes are not running, the checkpoing times are consistently 0
>>>>>>> seconds.
>>>>>>>
>>>>>>> I notice that the state of the sqlexec thread for the delete session
>>>>>>> is
>>>>>>> regurally 'cond wait(logbf2)' and onstat -l reports the following
>>>>>>> when
>>>>>>> the checkpoints start to get nasty.
>>>>>>>
>>>>>>> Logical Logging
>>>>>>> Buffer bufused bufsize numrecs numpages numwrits recs/pages
>>>>>>> pages/io
>>>>>>> L-1 15 16 448937 42960 30056 10.5
>>>>>>> 1.4
>>>>>>> Subsystem numrecs Log Space used
>>>>>>> OLDRSAM 447569 36229356
>>>>>>> CDR 1368 54792
>>>>>>>
>>>>>>> Buffer Waiting
>>>>>>> Buffer ioproc flags
>>>>>>> L-1 69e768d4 0x1 0
>>>>>>> L-3 6bf2a3a8 0x1 0
>>>>>>>
>>>>>>>
>>>>>>> Is it possible that I am running into a contention problem with my
>>>>>>> log
>>>>>>> buffers that is possibly being magnified by the need to replicate
>>>>>>> changes to the secondary HDR server and the 5 ER servers which can
>>>>>>> cause my delete session to spend more time than normal in a critical
>>>>>>> section?
>> On the assumption that you have just one process running, doing the
>> deletes, on this instance, for experimentation, reduce the LOGBUFF down
>> to 8 or 4 pages (i.e. 16k or 8k). You are not getting much out of 16
>> pages => 1.4.pages per IO.
>
> I was actually thinking of increasing the size of the log buffers since the
> HDR send and recieve buffers are always the same size as the log bufferes.
> With unbuffered logging you don't get much out of the larger log buffers as
> they are almost always immediately flushed to disk but there might be
> something gained by increasing the buffer size for the HDR send and recieve
> buffers that are drained when they become full.
The DR Send Buffers will buddy bunch multiple log flushes into a single
DR xmit buffer - and not send them until it is either full or the
DRINTERVAL has expired for that HDR send buffer.
Since the DR Send Buffer is sized according to the log buffer page, by
increasing the buffer size, you will increase the size of the in-flight
data that HDR can hold. It might be a bit wasteful from the viewpoint
of the log space buffers, but would also tend to relieve some pressure
from the log buffer waiting issue that your are seeing.
BTW - I think that some code that I'm working on for the Cheetah release
will go a long way to remove this issue - and make it easier to provide
availability for those situations where there is some issue with the
network.
>
> Any thoughts on this?
>
> Thanks,
>
> Andrew
>
>
>
>