Thread: VERY slow queries at random
Hi there, We run a small ISP with a FreeBSD/freeradius/postgresql 8.2.4 backend and 200+ users. Authentication happens via UAM/hotspot and I see a lot of authorisation and accounting packets that are handled via PL/PGSQL functions directly in the database. Everything seems to work 100% except that a few times a day I see Jun 6 10:41:31 caligula postgres[57347]: [4-1] radiususer: LOG: duration: 19929.291 ms statement: SELECT fn_accounting_start(...) in my logs. I'm logging slow queries with log_min_duration_statement = 500 in my postgresql.conf. Sometimes another query runs equally slow or even slower (I've seen 139 seconds!!!) a few minutes before or after as well, but then everything is back to normal. Even though I haven't yet indexed my data I know that the system is performant because my largest table (the accounting one) only has 5000+ rows, the entire database is only a few MB's and I have plenty of memory (2GB), shared_buffers = 100MB and max_fsm_pages = 179200. Also from briefly enabling log_parser_stats = on log_planner_stats = on log_executor_stats = on I saw that most queries are 100% satisfied from cache so the disk doesn't even get hit. Finally, the problem seems unrelated to load because it happens at 4am just as likely as at peak traffic time. What the heck could cause such erratic behaviour? I suspect some type of resource problem but what and how could I dig deeper? Gunther
On Wed, Jun 06, 2007 at 09:20:54PM +0200, Gunther Mayer wrote:
>
> What the heck could cause such erratic behaviour? I suspect some type of
> resource problem but what and how could I dig deeper?
Is something (perhaps implicitly) locking the table? That will cause
this.
A
--
Andrew Sullivan | ajs@crankycanuck.ca
"The year's penultimate month" is not in truth a good way of saying
November.
--H.W. Fowler
Gunther Mayer wrote: > Hi there, > > We run a small ISP with a FreeBSD/freeradius/postgresql 8.2.4 backend > and 200+ users. Authentication happens via UAM/hotspot and I see a lot > of authorisation and accounting packets that are handled via PL/PGSQL > functions directly in the database. > > Everything seems to work 100% except that a few times a day I see > > Jun 6 10:41:31 caligula postgres[57347]: [4-1] radiususer: LOG: > duration: 19929.291 ms statement: SELECT fn_accounting_start(...) > > in my logs. I'm logging slow queries with log_min_duration_statement = > 500 in my postgresql.conf. Sometimes another query runs equally slow or > even slower (I've seen 139 seconds!!!) a few minutes before or after as > well, but then everything is back to normal. > > Even though I haven't yet indexed my data I know that the system is > performant because my largest table (the accounting one) only has 5000+ > rows, the entire database is only a few MB's and I have plenty of memory > (2GB), shared_buffers = 100MB and max_fsm_pages = 179200. Also from > briefly enabling > > log_parser_stats = on > log_planner_stats = on > log_executor_stats = on > > I saw that most queries are 100% satisfied from cache so the disk > doesn't even get hit. Finally, the problem seems unrelated to load > because it happens at 4am just as likely as at peak traffic time. > > What the heck could cause such erratic behaviour? I suspect some type of > resource problem but what and how could I dig deeper? Maybe your hard drive is set to spin down after a certain period of idle, and since most all your data is coming from memory, then it might be that on the rare occasion when it needs to hit the drive it's not spun up anymore. Maybe some other process is cranking up (cron jobs???) that are chewing up all your I/O bandwidth? Hard to say. Anything in the system logs that would give you a hint? Try correlating them by the time of the slow pgsql queries.
could be that the checkpoints are done too seldom. what is your wal checkpoint config? Kristo On 07.06.2007, at 0:27, Scott Marlowe wrote: > Gunther Mayer wrote: >> Hi there, >> >> We run a small ISP with a FreeBSD/freeradius/postgresql 8.2.4 backend >> and 200+ users. Authentication happens via UAM/hotspot and I see a >> lot >> of authorisation and accounting packets that are handled via PL/PGSQL >> functions directly in the database. >> >> Everything seems to work 100% except that a few times a day I see >> >> Jun 6 10:41:31 caligula postgres[57347]: [4-1] radiususer: LOG: >> duration: 19929.291 ms statement: SELECT fn_accounting_start(...) >> >> in my logs. I'm logging slow queries with >> log_min_duration_statement = >> 500 in my postgresql.conf. Sometimes another query runs equally >> slow or >> even slower (I've seen 139 seconds!!!) a few minutes before or >> after as >> well, but then everything is back to normal. >> >> Even though I haven't yet indexed my data I know that the system is >> performant because my largest table (the accounting one) only has >> 5000+ >> rows, the entire database is only a few MB's and I have plenty of >> memory >> (2GB), shared_buffers = 100MB and max_fsm_pages = 179200. Also from >> briefly enabling >> >> log_parser_stats = on >> log_planner_stats = on >> log_executor_stats = on >> >> I saw that most queries are 100% satisfied from cache so the disk >> doesn't even get hit. Finally, the problem seems unrelated to load >> because it happens at 4am just as likely as at peak traffic time. >> >> What the heck could cause such erratic behaviour? I suspect some >> type of >> resource problem but what and how could I dig deeper? > > Maybe your hard drive is set to spin down after a certain period of > idle, and since most all your data is coming from memory, then it > might be that on the rare occasion when it needs to hit the drive > it's not spun up anymore. > > Maybe some other process is cranking up (cron jobs???) that are > chewing up all your I/O bandwidth? > > Hard to say. Anything in the system logs that would give you a > hint? Try correlating them by the time of the slow pgsql queries. > > > ---------------------------(end of > broadcast)--------------------------- > TIP 2: Don't 'kill -9' the postmaster
Andrew Sullivan wrote: > On Wed, Jun 06, 2007 at 09:20:54PM +0200, Gunther Mayer wrote: > >> What the heck could cause such erratic behaviour? I suspect some type of >> resource problem but what and how could I dig deeper? >> > > Is something (perhaps implicitly) locking the table? That will cause > this. > There are a whole bunch of update queries that fire all the time but afaik none of them ever lock the entire table. To the best of my knowledge UPDATE ... WHERE ... only locks those rows that it actually operates on, in my case this is always a single row. No explicit locking is done anywhere, but perhaps you're right and it is a locking issue. Question is, how do I find out about locks at the time when I only get told about the slow query *after* it has completed and postgres has told me so by logging a slow query entry in my logs? Gunther
Scott Marlowe wrote: > Gunther Mayer wrote: >> Hi there, >> >> We run a small ISP with a FreeBSD/freeradius/postgresql 8.2.4 backend >> and 200+ users. Authentication happens via UAM/hotspot and I see a lot >> of authorisation and accounting packets that are handled via PL/PGSQL >> functions directly in the database. >> >> Everything seems to work 100% except that a few times a day I see >> >> Jun 6 10:41:31 caligula postgres[57347]: [4-1] radiususer: LOG: >> duration: 19929.291 ms statement: SELECT fn_accounting_start(...) >> >> in my logs. I'm logging slow queries with log_min_duration_statement = >> 500 in my postgresql.conf. Sometimes another query runs equally slow or >> even slower (I've seen 139 seconds!!!) a few minutes before or after as >> well, but then everything is back to normal. >> >> Even though I haven't yet indexed my data I know that the system is >> performant because my largest table (the accounting one) only has 5000+ >> rows, the entire database is only a few MB's and I have plenty of memory >> (2GB), shared_buffers = 100MB and max_fsm_pages = 179200. Also from >> briefly enabling >> >> log_parser_stats = on >> log_planner_stats = on >> log_executor_stats = on >> >> I saw that most queries are 100% satisfied from cache so the disk >> doesn't even get hit. Finally, the problem seems unrelated to load >> because it happens at 4am just as likely as at peak traffic time. >> >> What the heck could cause such erratic behaviour? I suspect some type of >> resource problem but what and how could I dig deeper? > > Maybe your hard drive is set to spin down after a certain period of > idle, and since most all your data is coming from memory, then it > might be that on the rare occasion when it needs to hit the drive it's > not spun up anymore. I doubt that as a serious amount of logging is taking place on the box all the time which goes straight to disk. Also, no disk in the world would take more than a minute to spin up... > Maybe some other process is cranking up (cron jobs???) that are > chewing up all your I/O bandwidth? Hmm, I investigated that too but if that was the case the queries would run slow always at the same time of the day. > Hard to say. Anything in the system logs that would give you a hint? > Try correlating them by the time of the slow pgsql queries. Nothing relevant in the system logs at the time of the slow query appearing. I have in the mean time tweaked syslog-ng.conf such that as soon as it detects a "duration: <greater than 500>ms" log message it spawns top and top -m io and redirects the output to file. At least in that way I can check what's keeping the system busy immediately *after* a slow query has occured. Of course now Murphy's law has it that since I've done that (30 hours ago) not a single slow query has fired, but hey, I'll look at the results once I have them. On another note, autovacuum couldn't cause such issues, could it? I do have autovacuum enabled (autovacuum=on as well as stats_start_collector=on, stats_block_level = on and stats_row_level = on), is there any possibility that autovacuum is not as resource friendly as advertised? Gunther
Kristo Kaiv wrote: > could be that the checkpoints are done too seldom. > what is your wal checkpoint config? > wal checkpoint config is on pg defaults everywhere, all relevant config options are commented out. I'm no expert in wal stuff but I don't see how that could cause the problem? Gunther
On Thu, Jun 07, 2007 at 04:22:47PM +0200, Gunther Mayer wrote:
> There are a whole bunch of update queries that fire all the time but
> afaik none of them ever lock the entire table. To the best of my
> knowledge UPDATE ... WHERE ... only locks those rows that it actually
> operates on, in my case this is always a single row.
Well that shouldn't be biting you, then (you're not in SERIALIZABLE
mode, right?). The other obvious bit would be checkpoint storms.
What's your bgwriter config like?
> Question is, how do I find out about locks at the time when I only get
> told about the slow query *after* it has completed and postgres has told
> me so by logging a slow query entry in my logs?
You can't :(
A
--
Andrew Sullivan | ajs@crankycanuck.ca
This work was visionary and imaginative, and goes to show that visionary
and imaginative work need not end up well.
--Dennis Ritchie
Gunther Mayer wrote: > On another note, autovacuum couldn't cause such issues, could it? I do > have autovacuum enabled (autovacuum=on as well as > stats_start_collector=on, stats_block_level = on and stats_row_level = > on), is there any possibility that autovacuum is not as resource > friendly as advertised? Hmm. I am not sure where did you read that but I don't think it has ever been stated that autovacuum is resource friendly in the default configuration (I, for one, have never tried, intended or wanted to state that). I suggest tuning the autovacuum_vacuum_cost_delay parameters if you want it to interfere less with your regular operation. -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.
On Thu, 7 Jun 2007, Gunther Mayer wrote: > wal checkpoint config is on pg defaults everywhere, all relevant config > options are commented out. I'm no expert in wal stuff but I don't see how > that could cause the problem? Checkpoints are very resource intensive and can cause other processes (including your selects) to hang for a considerable period of time while they are processing. With the default parameters, they can happen very frequently. Normally checkpoint_segments and checkpoint_timeout are increased in order to keep this from happening. This would normally be an issue only if you're writing a substantial amount of data to your tables. If there are a lot of writes going on, you might get some improvement by adjusting those parameters upward; the defaults are pretty low. Make sure you read http://www.postgresql.org/docs/8.2/static/wal-configuration.html first so you know what you're playing with, there are some recovery implications invoved. -- * Greg Smith gsmith@gregsmith.com http://www.gregsmith.com Baltimore, MD
On 07.06.2007, at 22:42, Greg Smith wrote: > On Thu, 7 Jun 2007, Gunther Mayer wrote: > >> wal checkpoint config is on pg defaults everywhere, all relevant >> config options are commented out. I'm no expert in wal stuff but I >> don't see how that could cause the problem? > > Checkpoints are very resource intensive and can cause other > processes (including your selects) to hang for a considerable > period of time while they are processing. With the default > parameters, they can happen very frequently. Normally > checkpoint_segments and checkpoint_timeout are increased in order > to keep this from happening. > > This would normally be an issue only if you're writing a > substantial amount of data to your tables. If there are a lot of > writes going on, you might get some improvement by adjusting those > parameters upward; the defaults are pretty low. Make sure you read > http://www.postgresql.org/docs/8.2/static/wal-configuration.html > first so you know what you're playing with, there are some recovery > implications invoved. I remember us having problems with 8.0 background writer, you might want to try turning it off. Not sure if it behaves as badly in 8.2. increasing wal buffers might be a good idea also. Kristo