[PERFORM] Long Running Commits
Running PG 8.1.11 on AIX 5.3 Trying to track down the cause of long running commits on one of our DB servers. I can rule checkpoints out (I've set log_min_messages to debug2 and the commits are not happening during checkpoints). We have this problem over a period of ~ 35 minutes per day only. during that period we have no change in our write load, but we do have substantial increase in reads on one table (pretty much all being served by index scans from the buffer pool - which most likely points to a shift in activity over the time period, and not the problem itself). Over the same time, we also see an abnormally large number of connections being opened and closed. We can see this in the DB connection pool logs as well as the DB logs). This is most likely being driven by the activity shift that we can see in the stats. What we do see is connections being opened and closed rapidly during this same period of time (DB logs below). I'm wondering if the commits are waiting on something at the file system level due to the processes. Ulimit settings on the server: ulimit -a core file size(blocks, -c) soft data seg size (kbytes, -d) soft file size (blocks, -f) unlimited max memory size (kbytes, -m) hard open files(-n) 4096 pipe size (512 bytes, -p) 64 stack size(kbytes, -s) soft cpu time (seconds, -t) unlimited max user processes(-u) 10240 virtual memory(kbytes, -v) unlimited DB logs: 2009-03-04 09:56:13.465 CUT [561402]DEBUG: forked new backend, pid=794696 socket=9 2009-03-04 09:56:13.645 CUT [561402]DEBUG: forked new backend, pid=2101474 socket=9 2009-03-04 09:56:13.645 CUT [561402]DEBUG: server process (PID 516334) exited with exit code 0 2009-03-04 09:56:13.646 CUT [561402]DEBUG: server process (PID 1458332) exited with exit code 0 2009-03-04 09:56:13.646 CUT [561402]DEBUG: server process (PID 2174998) exited with exit code 0 2009-03-04 09:56:13.647 CUT [561402]DEBUG: server process (PID 1519662) exited with exit code 0 2009-03-04 09:56:13.647 CUT [561402]DEBUG: server process (PID 1646618) exited with exit code 0 2009-03-04 09:56:13.647 CUT [561402]DEBUG: server process (PID 999648) exited with exit code 0 2009-03-04 09:56:13.648 CUT [561402]DEBUG: server process (PID 2285774) exited with exit code 0 2009-03-04 09:56:13.648 CUT [561402]DEBUG: server process (PID 1622108) exited with exit code 0 2009-03-04 09:56:13.648 CUT [561402]DEBUG: server process (PID 1024216) exited with exit code 0 2009-03-04 09:56:13.649 CUT [561402]DEBUG: server process (PID 1392706) exited with exit code 0 2009-03-04 09:56:13.665 CUT [561402]DEBUG: forked new backend, pid=1392708 socket=9 2009-03-04 09:56:13.666 CUT [561402]DEBUG: server process (PID 1773680) exited with exit code 0 2009-03-04 09:56:13.669 CUT [561402]DEBUG: forked new backend, pid=1773682 socket=9 2009-03-04 09:56:13.805 CUT [561402]DEBUG: forked new backend, pid=1024218 socket=9 2009-03-04 09:56:13.805 CUT [561402]DEBUG: server process (PID 1589374) exited with exit code 0 2009-03-04 09:56:13.806 CUT [561402]DEBUG: server process (PID 995536) exited with exit code 0 2009-03-04 09:56:13.806 CUT [561402]DEBUG: server process (PID 688336) exited with exit code 0 2009-03-04 09:56:13.806 CUT [561402]DEBUG: server process (PID 2035798) exited with exit code 0 2009-03-04 09:56:13.807 CUT [561402]DEBUG: server process (PID 1429700) exited with exit code 0 2009-03-04 09:56:13.807 CUT [561402]DEBUG: server process (PID 2043960) exited with exit code 0 2009-03-04 09:56:13.807 CUT [561402]DEBUG: server process (PID 2158782) exited with exit code 0 2009-03-04 09:56:13.808 CUT [561402]DEBUG: server process (PID 2306144) exited with exit code 0 2009-03-04 09:56:13.808 CUT [561402]DEBUG: server process (PID 884978) exited with exit code 0 2009-03-04 09:56:13.808 CUT [561402]DEBUG: server process (PID 1781930) exited with exit code 0 2009-03-04 09:56:13.809 CUT [561402]DEBUG: server process (PID 2277572) exited with exit code 0 2009-03-04 09:56:13.809 CUT [561402]DEBUG: server process (PID 663656) exited with exit code 0 2009-03-04 09:56:13.809 CUT [561402]DEBUG: server process (PID 2343006) exited with exit code 0 2009-03-04 09:56:13.810 CUT [561402]DEBUG: server process (PID 889026) exited with exit code 0 2009-03-04 09:56:13.810 CUT [561402]DEBUG: server process (PID 2404546) exited with exit code 0 2009-03-04 09:56:13.810 CUT [561402]DEBUG: server process (PID 581830) exited with exit code 0 2009-03-04 09:56:13.811 CUT [561402]DEBUG: server process (PID 1433846) exited with exit code 0 2009-03-04 09:56:13.811 CUT [561402]DEBUG: server process (PID 667690) exited with exit code 0 2009-03-04 09:56:13.932 CUT [561402]DEBUG: forked new backen
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Fri, 14 Sep 2007, Peter Childs wrote: Are you suggesting that reducing bgwriter_delay and bg_writer_percent would reduce the time spent doing commits? I get quite a few commits that take over 500ms (the point when i start logging queries). One very common cause for transactions blocking for as much as several seconds is hitting a checkpoint, which in current versions causes a large amount of data to be written and synchronized to the physical disk. If you're already tracking long transactions and trying to figure out what's causing them, you should set checkpoint_warning to a high value (the maximum of 3600 is generally fine). That will give you a harmless warning every time a checkpoint occurs. If the slow transactions line up with checkpoints, then you might consider tuning or re-tuning the background writer to elimite the delay. In this particular case, their system had already been tuned so aggressively that I wondered if the background writer was being a problem rather than a solution. Reducing the percentage would turn it down a bit; so would *increasing* the delay--they had already decreased it considerably, making it 4X as active as the default. -- * Greg Smith [EMAIL PROTECTED] http://www.gregsmith.com Baltimore, MD ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PERFORM] Long Running Commits - Not Checkpoints
> I'm having a problem with long running commits appearing in my database > logs. It may be hardware related, as the problem appeared when we moved > the database to a new server connected to a different disk array. The > disk array is a lower class array, but still more than powerful enough > to handle the IO requirements. One big difference though is that the > old array had 16 GB of cache, the new one has 4 GB. Maybe the old disk array had battery backed up ram that was used as a write cache and the new only has read cache? Without battery backed up ram (or flash or whatever) then a commit need to flush data down onto the pysical disk. /Dennis ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [PERFORM] Long Running Commits - Not Checkpoints
On 14/09/2007, Peter Childs <[EMAIL PROTECTED]> wrote: > > > > On 13/09/2007, Greg Smith <[EMAIL PROTECTED]> wrote: > > > > > > Every time the all scan writes a buffer that is frequently used, that > > write has a good chance that it was wasted because the block will be > > modified again before checkpoint time. Your settings are beyond regular > > > > aggressive and into the hyperactive terrority where I'd expect such > > redundant writes are happening often. I'd suggest you try to move > > toward > > dropping bgwriter_all_percent dramatically from its current setting and > > see how far down you can go before it starts to introduce blocks at > > checkpoint time. With bgwriter_delay set to 1/4 the default, I would > > expect that even 5% would be a high setting for you. That may be a more > > dramatic change than you want to make at once though, so lowering it in > > that direction more slowly (perhaps drop 5% each day) and seeing whether > > things improve as that happens may make more sense. > > > > > Are you suggesting that reducing bgwriter_delay and bg_writer_percent > would reduce the time spent doing commits? > > I get quite a few commits that take over 500ms (the point when i start > logging queries). I always thought oh just one of those things but if they > can be reduced by changing a few config variables that would be great. I'm > just trying to workout what figures are worth trying to see if I can reduce > them. > > From time to time I get commits that take 6 or 7 seconds but not all the > time. > > I'm currently working with the defaults. > > Peter Childs > Hmm Always read the manual, Increase them from the defaults... Peter.
Re: [PERFORM] Long Running Commits - Not Checkpoints
On 13/09/2007, Greg Smith <[EMAIL PROTECTED]> wrote: > > > Every time the all scan writes a buffer that is frequently used, that > write has a good chance that it was wasted because the block will be > modified again before checkpoint time. Your settings are beyond regular > aggressive and into the hyperactive terrority where I'd expect such > redundant writes are happening often. I'd suggest you try to move toward > dropping bgwriter_all_percent dramatically from its current setting and > see how far down you can go before it starts to introduce blocks at > checkpoint time. With bgwriter_delay set to 1/4 the default, I would > expect that even 5% would be a high setting for you. That may be a more > dramatic change than you want to make at once though, so lowering it in > that direction more slowly (perhaps drop 5% each day) and seeing whether > things improve as that happens may make more sense. > > Are you suggesting that reducing bgwriter_delay and bg_writer_percent would reduce the time spent doing commits? I get quite a few commits that take over 500ms (the point when i start logging queries). I always thought oh just one of those things but if they can be reduced by changing a few config variables that would be great. I'm just trying to workout what figures are worth trying to see if I can reduce them. >From time to time I get commits that take 6 or 7 seconds but not all the time. I'm currently working with the defaults. Peter Childs
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Thu, 13 Sep 2007, Brad Nicholson wrote: A sysadmin looked at cache usage on the disk array. The read cache is being used heavily, and the write cache is not. Given that information, you can take the below (which I was just about to send before the above update came in) as something to think about and test but perhaps not your primary line of attack. Even if my theory about the exact mechanism involved isn't correct, the background writer is still problematic in terms of its impact on the system when run as aggressively as you're doing it; I'm not sure but I think that's even more true on 8.1 than it is on 8.2 where I did most my testing in this area. bgwriter_delay = 50 bgwriter_lru_percent = 20.0 bgwriter_lru_maxpages = 300 bgwriter_all_percent = 20 bgwriter_all_maxpages = 600 That was what I was expecting. Your all scan has the potential to be writing 600*8K*(1/50 msec)=98MB/sec worth of data to your disk array. Since some of this data has a random access component to it, your array cannot be expected to keep with a real peak load; the only thing saving you if something starts dirtying buffers as far as possible is that the array cache is buffering things. And that 4GB worth of cache could be filling in very little time. Every time the all scan writes a buffer that is frequently used, that write has a good chance that it was wasted because the block will be modified again before checkpoint time. Your settings are beyond regular aggressive and into the hyperactive terrority where I'd expect such redundant writes are happening often. I'd suggest you try to move toward dropping bgwriter_all_percent dramatically from its current setting and see how far down you can go before it starts to introduce blocks at checkpoint time. With bgwriter_delay set to 1/4 the default, I would expect that even 5% would be a high setting for you. That may be a more dramatic change than you want to make at once though, so lowering it in that direction more slowly (perhaps drop 5% each day) and seeing whether things improve as that happens may make more sense. -- * Greg Smith [EMAIL PROTECTED] http://www.gregsmith.com Baltimore, MD ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Thu, 2007-09-13 at 12:12 -0400, Greg Smith wrote: > Since you're probably not monitoring I/O waits and similar statistics on > how the disk array's cache is being used, whether this is happening or not > to you won't be obvious from what the operating system is reporting. A sysadmin looked at cache usage on the disk array. The read cache is being used heavily, and the write cache is not. -- Brad Nicholson 416-673-4106 Database Administrator, Afilias Canada Corp. ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PERFORM] Long Running Commits - Not Checkpoints
Brad Nicholson wrote: > On Thu, 2007-09-13 at 12:19 -0400, Brad Nicholson wrote: > > On Thu, 2007-09-13 at 12:12 -0400, Greg Smith wrote: > > > On Thu, 13 Sep 2007, Brad Nicholson wrote: > > > > > I'd be curious to see how you've got your background writer configured to > > > see if it matches situations like this I've seen in the past. The > > > parameters controlling the all scan are the ones you'd might consider > > > turning down, definately the percentage and possibly the maxpages as well. > > > > > > bgwriter_delay = 50 # 10-1 milliseconds between > > rounds > > bgwriter_lru_percent = 20.0 # 0-100% of LRU buffers > > scanned/round > > bgwriter_lru_maxpages = 300 # 0-1000 buffers max > > written/round > > bgwriter_all_percent = 20 # 0-100% of all buffers > > scanned/round > > bgwriter_all_maxpages = 600 # 0-1000 buffers max > > written/round > > I should add, there are 6 back ends running on this disk array > (different servers and different data partitions) with these bgwriter > settings. Maybe it is running deferred triggers or something? -- Alvaro Herrerahttp://www.advogato.org/person/alvherre "I suspect most samba developers are already technically insane... Of course, since many of them are Australians, you can't tell." (L. Torvalds) ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Thu, 2007-09-13 at 12:19 -0400, Brad Nicholson wrote: > On Thu, 2007-09-13 at 12:12 -0400, Greg Smith wrote: > > On Thu, 13 Sep 2007, Brad Nicholson wrote: > > > I'd be curious to see how you've got your background writer configured to > > see if it matches situations like this I've seen in the past. The > > parameters controlling the all scan are the ones you'd might consider > > turning down, definately the percentage and possibly the maxpages as well. > > > bgwriter_delay = 50 # 10-1 milliseconds between > rounds > bgwriter_lru_percent = 20.0 # 0-100% of LRU buffers > scanned/round > bgwriter_lru_maxpages = 300 # 0-1000 buffers max > written/round > bgwriter_all_percent = 20 # 0-100% of all buffers > scanned/round > bgwriter_all_maxpages = 600 # 0-1000 buffers max > written/round I should add, there are 6 back ends running on this disk array (different servers and different data partitions) with these bgwriter settings. -- Brad Nicholson 416-673-4106 Database Administrator, Afilias Canada Corp. ---(end of broadcast)--- TIP 7: You can help support the PostgreSQL project by donating at http://www.postgresql.org/about/donate
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Thu, 2007-09-13 at 12:12 -0400, Greg Smith wrote: > On Thu, 13 Sep 2007, Brad Nicholson wrote: > I'd be curious to see how you've got your background writer configured to > see if it matches situations like this I've seen in the past. The > parameters controlling the all scan are the ones you'd might consider > turning down, definately the percentage and possibly the maxpages as well. bgwriter_delay = 50 # 10-1 milliseconds between rounds bgwriter_lru_percent = 20.0 # 0-100% of LRU buffers scanned/round bgwriter_lru_maxpages = 300 # 0-1000 buffers max written/round bgwriter_all_percent = 20 # 0-100% of all buffers scanned/round bgwriter_all_maxpages = 600 # 0-1000 buffers max written/round -- Brad Nicholson 416-673-4106 Database Administrator, Afilias Canada Corp. ---(end of broadcast)--- TIP 6: explain analyze is your friend
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Thu, 13 Sep 2007, Brad Nicholson wrote: One big difference though is that the old array had 16 GB of cache, the new one has 4 GB. We have enough IO to spare that we have the bgwriter cranked up pretty high, dirty buffers are getting quickly. If your system is very active, running the bgwriter very aggressively will result in the cache on the disk array being almost continuously filled with pending writes that then trickle their way onto real disk eventually. If the typical working set on this system results in the amount of background writer cached writes regularly being >4GB but <16GB, that would explain what you're seeing. The resolution is actually unexpected by most people: you make the background writer less aggressive so that it's spewing less redundant writes clogging the array's cache, leaving more cache to buffer the actual commits so they don't block. This will increase the odds that there will be a checkpoint block instead, but if you're seeing none of them right now you may have some margin there to reduce the BGW activity without aggrevating checkpoints. Since you're probably not monitoring I/O waits and similar statistics on how the disk array's cache is being used, whether this is happening or not to you won't be obvious from what the operating system is reporting. One or two blocked writes every couple of minutes won't even show up on the gross statistics for operating system I/O waits; on average, they'll still be 0. So it's possible you may think you have plenty of I/O to spare, when in fact you don't quite have enough--what you've got is enough cache that the OS can't see where the real I/O bottleneck is. I'd be curious to see how you've got your background writer configured to see if it matches situations like this I've seen in the past. The parameters controlling the all scan are the ones you'd might consider turning down, definately the percentage and possibly the maxpages as well. -- * Greg Smith [EMAIL PROTECTED] http://www.gregsmith.com Baltimore, MD ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Thu, 2007-09-13 at 11:10 -0400, Tom Lane wrote: > Brad Nicholson <[EMAIL PROTECTED]> writes: > > On Thu, 2007-09-13 at 10:15 -0400, Brad Nicholson wrote: > >> I'm having a problem with long running commits appearing in my database > >> logs. It may be hardware related, as the problem appeared when we moved > >> the database to a new server connected to a different disk array. > > > More on this - we also have long running commits on installations that > > do have the wal files on a separate partition. > > What's your definition of "long running commit" --- seconds? milliseconds? > Exactly what are you measuring? Can you correlate the problem with what log_min_duration is set to 150ms Commits running over that up to 788ms. Here is what we see in the logs (with obfuscated dbname, username and IP): 2007-09-13 10:01:49.787 CUT [782426] dbname username 1.2.3.171 LOG: duration: 224.286 ms statement: EXECUTE [PREPARE: commit] 2007-09-13 10:19:16.373 CUT [737404] dbname username 1.2.3.174 LOG: duration: 372.545 ms statement: EXECUTE [PREPARE: commit] 2007-09-13 10:19:24.437 CUT [1806498] dbname username 11.2.3.171 LOG: duration: 351.544 ms statement: EXECUTE [PREPARE: commit] 2007-09-13 10:33:11.204 CUT [962598] dbname username 1.2.3.170 LOG: duration: 504.057 ms statement: EXECUTE [PREPARE: commit] 2007-09-13 10:40:33.735 CUT [1282104] dbname username 1.2.3.174 LOG: duration: 250.127 ms statement: EXECUTE [PREPARE: commit] 2007-09-13 10:49:54.752 CUT [1188032] dbname username 1.2.3.170 LOG: duration: 382.781 ms statement: EXECUTE [PREPARE: commit] 2007-09-13 11:30:43.339 CUT [1589464] dbname username 1.2.3.172 LOG: duration: 408.463 ms statement: EXECUTE [PREPARE: commit] -- Brad Nicholson 416-673-4106 Database Administrator, Afilias Canada Corp. ---(end of broadcast)--- TIP 1: if posting/reading through Usenet, please send an appropriate subscribe-nomail command to [EMAIL PROTECTED] so that your message can get through to the mailing list cleanly
Re: [PERFORM] Long Running Commits - Not Checkpoints
Brad Nicholson <[EMAIL PROTECTED]> writes: > On Thu, 2007-09-13 at 10:15 -0400, Brad Nicholson wrote: >> I'm having a problem with long running commits appearing in my database >> logs. It may be hardware related, as the problem appeared when we moved >> the database to a new server connected to a different disk array. > More on this - we also have long running commits on installations that > do have the wal files on a separate partition. What's your definition of "long running commit" --- seconds? milliseconds? Exactly what are you measuring? Can you correlate the problem with what the transaction was doing? regards, tom lane ---(end of broadcast)--- TIP 3: Have you checked our extensive FAQ? http://www.postgresql.org/docs/faq
Re: [PERFORM] Long Running Commits - Not Checkpoints
On Thu, 2007-09-13 at 10:15 -0400, Brad Nicholson wrote: > I'm having a problem with long running commits appearing in my database > logs. It may be hardware related, as the problem appeared when we moved > the database to a new server connected to a different disk array. The > disk array is a lower class array, but still more than powerful enough > to handle the IO requirements. One big difference though is that the > old array had 16 GB of cache, the new one has 4 GB. > > Running Postgres 8.1.8 on AIX 5.3 > > We have enough IO to spare that we have the bgwriter cranked up pretty > high, dirty buffers are getting quickly. Vmstat indicates 0 io wait > time, no swapping or anything nasty like that going on. > > The long running commits do not line up with checkpoint times. > > The postgresql.conf config are identical except that wal_buffers was 8 > on the old master, and it is set to 16 on the new one. > > We have other installations of this product running on the same array > (different servers though) and they are not suffering from this > problem. > > The only other thing of note is that the wal files sit on the same disk > as the data directory. This has not changed between the old and new > config, but the installs that are running fine do have their wal files > on a separate partition. > > Any ideas where the problem could lie? Could having the wal files on > the same data partition cause long running commits when there is plenty > of IO to spare? More on this - we also have long running commits on installations that do have the wal files on a separate partition. -- Brad Nicholson 416-673-4106 Database Administrator, Afilias Canada Corp. ---(end of broadcast)--- TIP 2: Don't 'kill -9' the postmaster
[PERFORM] Long Running Commits - Not Checkpoints
I'm having a problem with long running commits appearing in my database logs. It may be hardware related, as the problem appeared when we moved the database to a new server connected to a different disk array. The disk array is a lower class array, but still more than powerful enough to handle the IO requirements. One big difference though is that the old array had 16 GB of cache, the new one has 4 GB. Running Postgres 8.1.8 on AIX 5.3 We have enough IO to spare that we have the bgwriter cranked up pretty high, dirty buffers are getting quickly. Vmstat indicates 0 io wait time, no swapping or anything nasty like that going on. The long running commits do not line up with checkpoint times. The postgresql.conf config are identical except that wal_buffers was 8 on the old master, and it is set to 16 on the new one. We have other installations of this product running on the same array (different servers though) and they are not suffering from this problem. The only other thing of note is that the wal files sit on the same disk as the data directory. This has not changed between the old and new config, but the installs that are running fine do have their wal files on a separate partition. Any ideas where the problem could lie? Could having the wal files on the same data partition cause long running commits when there is plenty of IO to spare? -- Brad Nicholson 416-673-4106 Database Administrator, Afilias Canada Corp. ---(end of broadcast)--- TIP 5: don't forget to increase your free space map settings
