waiting on write of the logical log buffer

Hi , I am facing some locking issues like waiting on write of the logical log buffer following locks found in onstat -u G-BPX-- 8439 G-BPX-- 8945 G-BPX-- 9119 G-BPX-- 8838 G-BPX-- 9129 G-BPX-- 8911 How can we overcome this? Please suggest me

On Thu, Jan 27, 2011 at 5:52 PM, KHURRAM SHAHZAD <kshahzad02@i2cinc.com>wrote: > Hi , > I am facing some locking issues like waiting on write of the logical log > buffer > > following locks found in onstat -u > G-BPX-- 8439 > G-BPX-- 8945 > G-BPX-- 9119 > G-BPX-- 8838 > G-BPX-- 9129 > G-BPX-- 8911 > > How can we overcome this? Please suggest me > > > > ******************************************************************************* > Forum Note: Use "Reply" to post a response in the discussion forum. > > Do you have HDR setup? Do you think that is a problem? I'm asking because on high activity engines this is easy to spot, but does not necessarily means you have a problem. Can you post the first lines of onstat -l? You probably have "non buffered logging" databases. Do you know the difference to "buffered logging" databases? Would you consider using the later (there are implications involved in case of a crash) This can be a very complex issue, specially if you have HDR active. Madison could provide the dirty details, but I can explain the issue in general. If you have HDR, make sure your secondary server is working well, not overloaded and that your recovery threads are properly configured (more on this later.... it was explained in a chat with the labs...). Also make sure your network is ok. Not in terms of bandwidth, but in terms of round trip time (ping...) Regards. -- Fernando Nunes Portugal http://informix-technology.blogspot.com My email works... but I don't check it frequently... --0015174c104e879c7b049ad7e7b3

Yes We have HDR + 2 RSS using buffered loging. Round trip time is: ---- PING Statistics---- 9 packets transmitted, 9 packets received, 0% packet loss round-trip (ms) min/avg/max/stddev = 0.397/0.510/0.923/0.16 output of onstat -l: Physical Logging Buffer bufused bufsize numpages numwrits pages/io P-2 55 128 963312 8336 115.56 phybegin physize phypos phyused %used 30:301395 350000 36924 7516 2.15 Logical Logging Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io L-2 0 128 13290853 1524197 835881 8.7 1.8 Subsystem numrecs Log Space used OLDRSAM 13290767 1988418260 HA 86 3784 address number flags uniqid begin size used %used 11f374f98 1 U-B---- 79243 1:7573 25000 25000 100.00 121065d28 2 U-B---- 79244 1:32573 25000 25000 100.00 121065d90 3 U-B---- 79245 1:57573 25000 25000 100.00 121065df8 4 U-B---- 79246 1:82573 25000 24973 99.89 121065e60 5 U-B---- 79247 4:53 51200 51200 100.00 121065ec8 6 U-B---- 79248 4:51253 51200 51200 100.00 121065f30 7 U-B---- 79249 4:102453 51200 3785 7.39 121065f98 8 U-B---- 79250 4:153653 51200 51200 100.00 11f4e4f50 9 U-B---- 79251 4:204853 51200 51200 100.00 11f4e4fb8 10 U-B---- 79252 4:256053 51200 51200 100.00 11f4cbf50 11 U-B---- 79253 4:307253 51200 5316 10.38 11f4cbfb8 12 U-B---- 79254 4:358453 51200 51200 100.00 1211f3028 13 U-B---- 79255 4:409653 51200 42268 82.55 1211f3090 14 U-B---- 79256 4:460853 51200 51200 100.00 1211f30f8 15 U-B---- 79257 4:512053 51200 51200 100.00 1211f3160 16 U-B---- 79258 4:563253 51200 455 0.89 1211f31c8 17 U-B---- 79259 4:614453 51200 51200 100.00 1211f3230 18 U-B---- 79260 4:665653 51200 48300 94.34 1211f3298 19 U-B---- 79261 4:716853 51200 51200 100.00 1211f3300 20 U-B---- 79262 4:768053 51200 51200 100.00 1211f3368 21 U-B---- 79263 4:819253 51200 38121 74.46 1211f33d0 22 U-B---- 79264 4:870453 51200 51200 100.00 1211f3438 23 U-B---- 79265 4:921653 51200 51200 100.00 1211f34a0 24 U-B---- 79266 32:53 256000 255109 99.65 1211f3508 25 U-B---- 79267 32:256053 256000 146088 57.07 1211f3570 26 U---C-L 79268 32:512053 256000 125904 49.18 1211f35d8 27 U-B---- 79237 32:768053 256000 40527 15.83 1211f3640 28 U-B---- 79238 32:1024053 256000 57629 22.51 1211f36a8 29 U-B---- 79239 32:1280053 256000 105294 41.13 1211f3710 30 U-B---- 79240 32:1536053 256000 33614 13.13 1211f3778 31 U-B---- 79241 32:1792053 152549 24496 16.06 1211f37e0 32 U-B---- 79242 32:1944602 152550 68854 45.14 32 active, 32 total

It's not the ping time. It's the usage of the offline recovery threads on the secondary servers. What is the number of CPUVPS on the HDR primary/HDR secondary? What is OFF_RECVRY_THREADS set to on those two instances? From: "KHURRAM SHAHZAD" <kshahzad02@i2cinc.com> To: ids@iiug.org Date: 01/27/2011 12:40 PM Subject: Re: waiting on write of the logical log buffer [22614] Sent by: ids-bounces@iiug.org Yes We have HDR + 2 RSS using buffered loging. Round trip time is: ---- PING Statistics---- 9 packets transmitted, 9 packets received, 0% packet loss round-trip (ms) min/avg/max/stddev = 0.397/0.510/0.923/0.16 output of onstat -l: Physical Logging Buffer bufused bufsize numpages numwrits pages/io P-2 55 128 963312 8336 115.56 phybegin physize phypos phyused %used 30:301395 350000 36924 7516 2.15 Logical Logging Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io L-2 0 128 13290853 1524197 835881 8.7 1.8 Subsystem numrecs Log Space used OLDRSAM 13290767 1988418260 HA 86 3784 address number flags uniqid begin size used %used 11f374f98 1 U-B---- 79243 1:7573 25000 25000 100.00 121065d28 2 U-B---- 79244 1:32573 25000 25000 100.00 121065d90 3 U-B---- 79245 1:57573 25000 25000 100.00 121065df8 4 U-B---- 79246 1:82573 25000 24973 99.89 121065e60 5 U-B---- 79247 4:53 51200 51200 100.00 121065ec8 6 U-B---- 79248 4:51253 51200 51200 100.00 121065f30 7 U-B---- 79249 4:102453 51200 3785 7.39 121065f98 8 U-B---- 79250 4:153653 51200 51200 100.00 11f4e4f50 9 U-B---- 79251 4:204853 51200 51200 100.00 11f4e4fb8 10 U-B---- 79252 4:256053 51200 51200 100.00 11f4cbf50 11 U-B---- 79253 4:307253 51200 5316 10.38 11f4cbfb8 12 U-B---- 79254 4:358453 51200 51200 100.00 1211f3028 13 U-B---- 79255 4:409653 51200 42268 82.55 1211f3090 14 U-B---- 79256 4:460853 51200 51200 100.00 1211f30f8 15 U-B---- 79257 4:512053 51200 51200 100.00 1211f3160 16 U-B---- 79258 4:563253 51200 455 0.89 1211f31c8 17 U-B---- 79259 4:614453 51200 51200 100.00 1211f3230 18 U-B---- 79260 4:665653 51200 48300 94.34 1211f3298 19 U-B---- 79261 4:716853 51200 51200 100.00 1211f3300 20 U-B---- 79262 4:768053 51200 51200 100.00 1211f3368 21 U-B---- 79263 4:819253 51200 38121 74.46 1211f33d0 22 U-B---- 79264 4:870453 51200 51200 100.00 1211f3438 23 U-B---- 79265 4:921653 51200 51200 100.00 1211f34a0 24 U-B---- 79266 32:53 256000 255109 99.65 1211f3508 25 U-B---- 79267 32:256053 256000 146088 57.07 1211f3570 26 U---C-L 79268 32:512053 256000 125904 49.18 1211f35d8 27 U-B---- 79237 32:768053 256000 40527 15.83 1211f3640 28 U-B---- 79238 32:1024053 256000 57629 22.51 1211f36a8 29 U-B---- 79239 32:1280053 256000 105294 41.13 1211f3710 30 U-B---- 79240 32:1536053 256000 33614 13.13 1211f3778 31 U-B---- 79241 32:1792053 152549 24496 16.06 1211f37e0 32 U-B---- 79242 32:1944602 152550 68854 45.14 32 active, 32 total ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

PING host_sec: 56 data bytes 64 bytes from host_sec: icmp_seq=0. time=0.923 ms 64 bytes from host_sec: icmp_seq=1. time=0.482 ms 64 bytes from host_sec: icmp_seq=2. time=0.484 ms 64 bytes from host_sec: icmp_seq=3. time=0.419 ms 64 bytes from host_sec: icmp_seq=4. time=0.483 ms 64 bytes from host_sec: icmp_seq=5. time=0.496 ms 64 bytes from host_sec: icmp_seq=6. time=0.397 ms 64 bytes from host_sec: icmp_seq=7. time=0.440 ms 64 bytes from host_sec: icmp_seq=8. time=0.470 ms value of OFF_RECVRY_THREADS is 10 for both primary and HDR VPCLASS cpu,num=12,aff=6-17,noage VP_MEMORY_CACHE_KB 0 SINGLE_CPU_VP 0

Generally I recommend that OFF_RECVRY_THREADS on the HDR (and RSS) server be about 3 times the number of CPUVPs, but using a near prime number (where the number is not evenly devisable by 2,3,5,7,11. In your case, that would mean using OFF_RECVRY_THREADS to maybe 37. M.P. From: "KHURRAM SHAHZAD" <kshahzad02@i2cinc.com> To: ids@iiug.org Date: 01/27/2011 02:20 PM Subject: Re: waiting on write of the logical log buffer [22616] Sent by: ids-bounces@iiug.org PING host_sec: 56 data bytes 64 bytes from host_sec: icmp_seq=0. time=0.923 ms 64 bytes from host_sec: icmp_seq=1. time=0.482 ms 64 bytes from host_sec: icmp_seq=2. time=0.484 ms 64 bytes from host_sec: icmp_seq=3. time=0.419 ms 64 bytes from host_sec: icmp_seq=4. time=0.483 ms 64 bytes from host_sec: icmp_seq=5. time=0.496 ms 64 bytes from host_sec: icmp_seq=6. time=0.397 ms 64 bytes from host_sec: icmp_seq=7. time=0.440 ms 64 bytes from host_sec: icmp_seq=8. time=0.470 ms value of OFF_RECVRY_THREADS is 10 for both primary and HDR VPCLASS cpu,num=12,aff=6-17,noage VP_MEMORY_CACHE_KB 0 SINGLE_CPU_VP 0 ******************************************************************************* Forum Note: Use "Reply" to post a response in the discussion forum.

Hmmm... Madison already referenced the number of recovery threads. But there's something here that don't match properly... You say you're using buffered logging. But on average you just use 1.8 pages of your logical log buffer... Depending on your system page size this would be nearly 4K or 8K out of 128 pages (256K or 512K - LOGBUFF parameter). Typically the logical log buffer will be flushed when a commit on an unbuffered logging table is done.... I would verify if you have any unbuffered logging database, but before that your HDR parameters should be checked. Are you using asynchronous or synchronous HDR? I don't recall exactly what will cause the flush of the logical log buffer besides a commit for an unbuffered logging database. Would need to check. With this situation (1.8 pages/flush) your secondary must not be overloaded by queries. I usually see this on a customer site, when the secondary is overloaded (big DSS queries). You should check this possibility and try Madison's suggestion. And if you intend to use buffered logging, than you also need to check what is causing so frequent logical log buffers flushs... Regards On Thu, Jan 27, 2011 at 6:39 PM, KHURRAM SHAHZAD <kshahzad02@i2cinc.com>wrote: > Yes We have HDR + 2 RSS using buffered loging. > Round trip time is: > > ---- PING Statistics---- > 9 packets transmitted, 9 packets received, 0% packet loss > round-trip (ms) min/avg/max/stddev = 0.397/0.510/0.923/0.16 > > output of onstat -l: > Physical Logging > Buffer bufused bufsize numpages numwrits pages/io > P-2 55 128 963312 8336 115.56 > > phybegin physize phypos phyused %used > > 30:301395 350000 36924 7516 2.15 > > Logical Logging > Buffer bufused bufsize numrecs numpages numwrits recs/pages pages/io > L-2 0 128 13290853 1524197 835881 8.7 1.8 > > Subsystem numrecs Log Space used > > OLDRSAM 13290767 1988418260 > > HA 86 3784 > > address number flags uniqid begin size used %used > 11f374f98 1 U-B---- 79243 1:7573 25000 25000 100.00 > 121065d28 2 U-B---- 79244 1:32573 25000 25000 100.00 > 121065d90 3 U-B---- 79245 1:57573 25000 25000 100.00 > 121065df8 4 U-B---- 79246 1:82573 25000 24973 99.89 > 121065e60 5 U-B---- 79247 4:53 51200 51200 100.00 > 121065ec8 6 U-B---- 79248 4:51253 51200 51200 100.00 > 121065f30 7 U-B---- 79249 4:102453 51200 3785 7.39 > 121065f98 8 U-B---- 79250 4:153653 51200 51200 100.00 > 11f4e4f50 9 U-B---- 79251 4:204853 51200 51200 100.00 > 11f4e4fb8 10 U-B---- 79252 4:256053 51200 51200 100.00 > 11f4cbf50 11 U-B---- 79253 4:307253 51200 5316 10.38 > 11f4cbfb8 12 U-B---- 79254 4:358453 51200 51200 100.00 > 1211f3028 13 U-B---- 79255 4:409653 51200 42268 82.55 > 1211f3090 14 U-B---- 79256 4:460853 51200 51200 100.00 > 1211f30f8 15 U-B---- 79257 4:512053 51200 51200 100.00 > 1211f3160 16 U-B---- 79258 4:563253 51200 455 0.89 > 1211f31c8 17 U-B---- 79259 4:614453 51200 51200 100.00 > 1211f3230 18 U-B---- 79260 4:665653 51200 48300 94.34 > 1211f3298 19 U-B---- 79261 4:716853 51200 51200 100.00 > 1211f3300 20 U-B---- 79262 4:768053 51200 51200 100.00 > 1211f3368 21 U-B---- 79263 4:819253 51200 38121 74.46 > 1211f33d0 22 U-B---- 79264 4:870453 51200 51200 100.00 > 1211f3438 23 U-B---- 79265 4:921653 51200 51200 100.00 > 1211f34a0 24 U-B---- 79266 32:53 256000 255109 99.65 > 1211f3508 25 U-B---- 79267 32:256053 256000 146088 57.07 > 1211f3570 26 U---C-L 79268 32:512053 256000 125904 49.18 > 1211f35d8 27 U-B---- 79237 32:768053 256000 40527 15.83 > 1211f3640 28 U-B---- 79238 32:1024053 256000 57629 22.51 > 1211f36a8 29 U-B---- 79239 32:1280053 256000 105294 41.13 > 1211f3710 30 U-B---- 79240 32:1536053 256000 33614 13.13 > 1211f3778 31 U-B---- 79241 32:1792053 152549 24496 16.06 > 1211f37e0 32 U-B---- 79242 32:1944602 152550 68854 45.14 > 32 active, 32 total > > > > ******************************************************************************* > 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... --000e0cd1e07a0fe848049addac11