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

> Deletes are always expensive. Sometimes cheaper to re-write the table > than perform them. You can also use fragmentation and drop/add fragment > to manage them. You can also break the delete into bite size mouthfuls > and feed them to the engine (i have an example of this being done > programmtically if you care - works fairly well). > > What are your b-tree cleaner threads up to while all this is going on? I > imagine they would be busy - although that should have no impact on the > checkpoint. > > j. > >>From: Andrew Ford <aford@networkip.net> >>Date: 2007/02/07 Wed PM 03:32:48 CST >>To: informix-list@iiug.org >>Subject: 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: