Re: Oddly slow queries

spreng(at)socket(dot)ch (Thomas Spreng) writes:
> On 16.04.2008, at 01:24, PFC wrote:
>>
>>> The queries in question (select's) occasionally take up to 5 mins
>>> even if they take ~2-3 sec under "normal" conditions, there are no
>>> sequencial scans done in those queries. There are not many users
>>> connected (around 3, maybe) to this database usually since it's
>>> still in a testing phase. I tried to hunt down the problem by
>>> playing around with resource usage cfg options but it didn't really
>>> made a difference.
>>
>> Could that be caused by a CHECKPOINT ?
>
> actually there are a few log (around 12 per day) entries concerning
> checkpoints:
>
> LOG: checkpoints are occurring too frequently (10 seconds apart)
> HINT: Consider increasing the configuration parameter
> "checkpoint_segments".
>
> But wouldn't that only affect write performance? The main problems I'm
> concerned about affect SELECT queries.

No, that will certainly NOT just affect write performance; if the
postmaster is busy writing out checkpoints, that will block SELECT
queries that are accessing whatever is being checkpointed.

When we were on 7.4, we would *frequently* see SELECT queries that
should be running Very Quick that would get blocked by the checkpoint
flush.

We'd periodically see hordes of queries of the form:

select id from some_table where unique_field = 'somevalue.something';

which would normally run in less than 1ms running for (say) 2s.

And the logs would show something looking rather like the following:

2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'somevalue.something'; - 952ms
2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'somevalue.something'; - 742ms
2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'another.something'; - 1341ms
2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'somevalue.something'; - 911ms
2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'another.something'; - 1244ms
2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'another.something'; - 2311ms
2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'another.something'; - 1799ms
2008-04-03 09:01:52 LOG select id from some_table where unique_field = 'somevalue.something'; - 1992ms

This was happening because the checkpoint was flushing those two
tuples, and hence blocking 8 SELECTs that came in during the flush.

There are two things worth considering:

1. If the checkpoints are taking place "too frequently," then that is
clear evidence that something is taking place that is injecting REALLY
heavy update load on your database at those times.

If the postmaster is checkpointing every 10s, that implies Rather
Heavy Load, so it is pretty well guaranteed that performance of other
activity will suck at least somewhat because this load is sucking up
all the I/O bandwidth that it can.

So, to a degree, there may be little to be done to improve on this.

2. On the other hand, if you're on 8.1 or so, you may be able to
configure the Background Writer to incrementally flush checkpoint data
earlier, and avoid the condition of 1.

Mind you, you'd have to set BgWr to be pretty aggressive, based on the
"10s periodicity" that you describe; that may not be a nice
configuration to have all the time :-(.
--
output = reverse("ofni.sesabatadxunil" "@" "enworbbc")
http://cbbrowne.com/info/multiplexor.html
Nagging is the repetition of unpalatable truths. --Baroness Edith
Summerskill