Re: Long Checkpoints - cond wait(logbf2) with HDR

> 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 Update for those keeping score at home: Last night I changed PHYSBUFF from 32 to 128, LOGBUFF from 32 to 256 and DRINTERVAL from 30 to 3 on both the Primary HDR server and Secondary HDR server. This did not resolve the long checkpoint/delete session waiting on cond wait(logbf1) issue and seems to have made things a little bit worse. After the configuration change and engine bounce I kicked off the delete again and experienced a 105 second checkpoint after approximately 10,000 rows were deleted and observed the same cond wait(logbf?) behaviour. This time the Primary complained of a DR: ping timeout and shutdown HDR. The Secondary HDR server was bounced and after a lengthy physical and logical recovery HDR re-established itself. I was able to eliminate ER as a cause of the problem by observing the same behaviour when performing the deletes inside of a "BEGIN WORK WITHOUT REPLICATION/COMMIT WORK" I have opened a case with support, PMR 73759,004. Primary online.log 02:16:42 Checkpoint Completed: duration was 0 seconds. 02:16:42 Checkpoint loguniq 4276, logpos 0x6bb018, timestamp: 0x58590ede 02:16:42 Maximum server connections 27 02:27:06 Checkpoint Completed: duration was 0 seconds. 02:27:06 Checkpoint loguniq 4276, logpos 0x125b018, timestamp: 0x5859f25a 02:27:06 Maximum server connections 42 ### deletes started approx @ 02:30:00 ### checkpoint begins @ 02:37:06 02:38:50 DR: ping timeout 02:38:51 Checkpoint Completed: duration was 105 seconds. 02:38:51 Checkpoint loguniq 4276, logpos 0x298c018, timestamp: 0x585ce4b2 02:38:51 Maximum server connections 84 02:39:02 DR: Receive error 02:39:02 ASF Echo-Thread Server: asfcode = -25582: oserr = 0: errstr = :Network connection is broken. 02:39:03 DR: Turned off on primary server 02:39:03 DR: Cannot connect to secondary server 02:39:14 DR: Primary server connected 02:39:14 DR: Send error 02:39:14 ASF Echo-Thread Server: asfcode = -25580: oserr = 32: errstr = :System error occurred in network function. System error = 32. 02:39:14 DR: Failure recovery error (2) 02:39:16 DR: Turned off on primary server 02:39:16 DR: Cannot connect to secondary server 02:39:26 DR: Primary server connected 02:39:26 DR: Send error 02:39:26 ASF Echo-Thread Server: asfcode = -25580: oserr = 32: errstr = :System error occurred in network function. System error = 32. 02:39:26 DR: Failure recovery error (2) 02:39:28 DR: Turned off on primary server 02:39:28 DR: Cannot connect to secondary server ... ... ... 02:47:22 DR: Primary server connected 02:47:22 DR: Send error 02:47:22 ASF Echo-Thread Server: asfcode = -25580: oserr = 32: errstr = :System error occurred in network function. System error = 32. 02:47:22 DR: Failure recovery error (2) 02:47:23 DR: Turned off on primary server 02:47:23