pg.ddx.io pgsql-performance@postgresql.org mailing list archive
help / color / mirror / Atom feedVERY slow queries at random
11+ messages / 6 participants
[nested] [flat]
* VERY slow queries at random
@ 2007-06-06 19:20 Gunther Mayer <gunther.mayer@googlemail.com>
0 siblings, 2 replies; 11+ messages in thread
From: Gunther Mayer @ 2007-06-06 19:20 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-06 19:56 Andrew Sullivan <ajs@crankycanuck.ca>
parent: Gunther Mayer <gunther.mayer@googlemail.com>
1 sibling, 1 reply; 11+ messages in thread
From: Andrew Sullivan @ 2007-06-06 19:56 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-06 21:27 Scott Marlowe <smarlowe@g2switchworks.com>
parent: Gunther Mayer <gunther.mayer@googlemail.com>
1 sibling, 2 replies; 11+ messages in thread
From: Scott Marlowe @ 2007-06-06 21:27 UTC (permalink / raw)
To: Gunther Mayer <gunther.mayer@googlemail.com>; +Cc: pgsql-performance
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.
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-07 07:09 Kristo Kaiv <kristo.kaiv@skype.net>
parent: Scott Marlowe <smarlowe@g2switchworks.com>
1 sibling, 1 reply; 11+ messages in thread
From: Kristo Kaiv @ 2007-06-07 07:09 UTC (permalink / raw)
To: Scott Marlowe <smarlowe@g2switchworks.com>; +Cc: Gunther Mayer <gunther.mayer@googlemail.com>; pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-07 14:22 Gunther Mayer <gunther.mayer@googlemail.com>
parent: Andrew Sullivan <ajs@crankycanuck.ca>
0 siblings, 1 reply; 11+ messages in thread
From: Gunther Mayer @ 2007-06-07 14:22 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-07 15:32 Gunther Mayer <gunther.mayer@googlemail.com>
parent: Scott Marlowe <smarlowe@g2switchworks.com>
1 sibling, 1 reply; 11+ messages in thread
From: Gunther Mayer @ 2007-06-07 15:32 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-07 15:38 Gunther Mayer <gunther.mayer@googlemail.com>
parent: Kristo Kaiv <kristo.kaiv@skype.net>
0 siblings, 1 reply; 11+ messages in thread
From: Gunther Mayer @ 2007-06-07 15:38 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-07 15:45 Andrew Sullivan <ajs@crankycanuck.ca>
parent: Gunther Mayer <gunther.mayer@googlemail.com>
0 siblings, 0 replies; 11+ messages in thread
From: Andrew Sullivan @ 2007-06-07 15:45 UTC (permalink / raw)
To: pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-07 15:58 Alvaro Herrera <alvherre@commandprompt.com>
parent: Gunther Mayer <gunther.mayer@googlemail.com>
0 siblings, 0 replies; 11+ messages in thread
From: Alvaro Herrera @ 2007-06-07 15:58 UTC (permalink / raw)
To: Gunther Mayer <gunther.mayer@googlemail.com>; +Cc: pgsql-performance
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.
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-07 19:42 Greg Smith <gsmith@gregsmith.com>
parent: Gunther Mayer <gunther.mayer@googlemail.com>
0 siblings, 1 reply; 11+ messages in thread
From: Greg Smith @ 2007-06-07 19:42 UTC (permalink / raw)
To: Gunther Mayer <gunther.mayer@googlemail.com>; +Cc: pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
* Re: VERY slow queries at random
@ 2007-06-08 08:27 Kristo Kaiv <kristo.kaiv@skype.net>
parent: Greg Smith <gsmith@gregsmith.com>
0 siblings, 0 replies; 11+ messages in thread
From: Kristo Kaiv @ 2007-06-08 08:27 UTC (permalink / raw)
To: Greg Smith <gsmith@gregsmith.com>; +Cc: Gunther Mayer <gunther.mayer@googlemail.com>; pgsql-performance
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
^ permalink raw reply [nested|flat] 11+ messages in thread
end of thread, other threads:[~2007-06-08 08:27 UTC | newest]
Thread overview: 11+ messages (download: mbox mbox.gz follow: Atom feed)
-- links below jump to the message on this page --
2007-06-06 19:20 VERY slow queries at random Gunther Mayer <gunther.mayer@googlemail.com>
2007-06-06 19:56 ` Andrew Sullivan <ajs@crankycanuck.ca>
2007-06-07 14:22 ` Gunther Mayer <gunther.mayer@googlemail.com>
2007-06-07 15:45 ` Andrew Sullivan <ajs@crankycanuck.ca>
2007-06-06 21:27 ` Scott Marlowe <smarlowe@g2switchworks.com>
2007-06-07 07:09 ` Kristo Kaiv <kristo.kaiv@skype.net>
2007-06-07 15:38 ` Gunther Mayer <gunther.mayer@googlemail.com>
2007-06-07 19:42 ` Greg Smith <gsmith@gregsmith.com>
2007-06-08 08:27 ` Kristo Kaiv <kristo.kaiv@skype.net>
2007-06-07 15:32 ` Gunther Mayer <gunther.mayer@googlemail.com>
2007-06-07 15:58 ` Alvaro Herrera <alvherre@commandprompt.com>
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox