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


---------------------------(end of broadcast)---------------------------
TIP 6: explain analyze is your friend

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

---------------------------(end of broadcast)---------------------------
TIP 2: Don't 'kill -9' the postmaster

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

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


---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

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

---------------------------(end of broadcast)---------------------------
TIP 1: if posting/reading through Usenet, please send an appropriate
subscribe-nomail command to majordomo@postgresql.org so that your
message can get through to the mailing list cleanly

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

---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

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

---------------------------(end of broadcast)---------------------------
TIP 7: You can help support the PostgreSQL project by donating at

http://www.postgresql.org/about/donate

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

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match

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.

---------------------------(end of broadcast)---------------------------
TIP 3: Have you checked our extensive FAQ?

http://www.postgresql.org/docs/faq

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/s...iguration.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

---------------------------(end of broadcast)---------------------------
TIP 9: In versions below 8.0, the planner will ignore your desire to
choose an index scan if your joining column's datatypes do not
match