Re: Blocking excessively in FOR UPDATE

On Thu, Nov 3, 2011 at 8:45 PM, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us> wrote:
>  But before pursuing that idea, probably first you should
> back up and confirm whether the process is actually waiting, or running,
> or just really slow due to CPU contention.  It might be useful to see
> what strace has to say about it.

Thanks for the tip, it seems locks had nothing to do with it.

strace suggests those queries get blocked on write().

This is an explain analyze without for update:

"Index Scan using idx_track_logs_track_id on track_logs
(cost=0.00..26.75 rows=1 width=8) (actual time=0.056..38.119 rows=1
loops=1)"
" Index Cond: (track_id = <some id>)"
" Filter: ((track_status_id = 1) AND (date >= (now() - '01:00:00'::interval)))"
" Buffers: shared hit=140 read=3127"
"Total runtime: 38.147 ms"

This is with for update that goes fast:

"LockRows (cost=0.00..26.76 rows=1 width=14) (actual
time=0.075..37.420 rows=1 loops=1)"
" Buffers: shared hit=63 read=3205"
" -> Index Scan using idx_track_logs_track_id on track_logs
(cost=0.00..26.75 rows=1 width=14) (actual time=0.058..37.402 rows=1
loops=1)"
" Index Cond: (track_id = <some id>)"
" Filter: ((track_status_id = 1) AND (date >= (now() -
'01:00:00'::interval)))"
" Buffers: shared hit=62 read=3205"
"Total runtime: 37.462 ms"

I cannot hit one that goes slow yet, but when I did (and didn't
capture the output :( ) it was kinda like:

"LockRows (cost=0.00..26.76 rows=1 width=14) (actual
time=0.075..37.420 rows=1 loops=1)"
" Buffers: shared hit=63 read=3205"
" -> Index Scan using idx_track_logs_track_id on track_logs
(cost=0.00..26.75 rows=1 width=14) (actual time=0.058..37.402 rows=1
loops=1)"
" Index Cond: (track_id = <some id>)"
" Filter: ((track_status_id = 1) AND (date >= (now() -
'01:00:00'::interval)))"
" Buffers: shared hit=62 read=3205 written=135"
"Total runtime: 37000.462 ms"

Now, I'm thinking those writes are catching the DB at a bad moment -
we do have regular very write-intensive peaks.

Maybe I should look into increasing shared buffers?
Checkpoints are well spread and very fast

What are those writes about? HOT vacuuming perhaps?