Re: Hung Vacuum in 8.3

On 08/03/11 13:03, Mark Kirkwood wrote:
> On 08/03/11 12:55, Mark Kirkwood wrote:
>> On 23/02/11 10:18, Mark Kirkwood wrote:
>>> On 23/02/11 00:26, Greg Stark wrote:
>>>>
>>>> It's also possible there's a bug of course. If someone was using that
>>>> buffer and somehow failed to notify the vacuum that they were done it
>>>> would wait for a very long time (forever?). However if vacuum
>>>> eventually continued when the query was canceled then it seems likely
>>>> it was working as intended.
>>>>
>>>
>>> Greg, thanks for clarifying this.
>>>
>>> Unfortunately this time around I canceled the vacuum and then the
>>> query. However *next* time I'll get rid of the query 1st and see
>>> what happens.
>>>
>>
>> I have another one here:
>>
>> postgres=# select datname,procpid, query_start, current_query
>>                   from pg_stat_activity
>>                   where now() - query_start > '2 hours'::interval
>> order by query_start;
>>  datname | procpid |          query_start          |  current_query
>> ---------+---------+-------------------------------+-----------------
>>  stuff   |   23957 | 2011-03-08 06:02:02.659159+13 | VACUUM ANALYZE;
>>
>> postgres=# select datname,procpid, query_start, current_query
>>                   from pg_stat_activity
>>                   where now() - backend_start > '2 hours'::interval
>> order by query_start;
>>  datname | procpid |          query_start          |  current_query
>> ---------+---------+-------------------------------+-----------------
>>  stuff   |   23957 | 2011-03-08 06:02:02.659159+13 | VACUUM ANALYZE;
>>                                                    :
>>  stuff   |   30018 | 2011-03-08 11:57:03.214177+13 | <IDLE>
>>  stuff   |   11390 | 2011-03-08 12:27:20.390122+13 | <IDLE>
>>  stuff   |   10178 | 2011-03-08 12:28:59.328265+13 | <IDLE>
>>  stuff   |    5100 | 2011-03-08 12:30:10.318204+13 | <IDLE>
>>  stuff   |   10255 | 2011-03-08 12:32:21.520814+13 | <IDLE>
>>  stuff   |   29993 | 2011-03-08 12:32:26.562835+13 | <IDLE>
>>  stuff   |   10204 | 2011-03-08 12:40:57.059958+13 | <IDLE>
>>  stuff   |   10206 | 2011-03-08 12:41:11.708924+13 | <IDLE>
>> (9 rows)
>>
>>
>> It looks to me like whatever query buffer pins the vacuum *was*
>> waiting on should be well and truly over by now. The strace for the
>> vacuum looks the same as before:
>>
>> $ strace -p 23957
>> Process 23957 attached - interrupt to quit
>> semop(39747613, 0x7fff53d3dec0, 1
>>
>>
>> It certainly looks like the vacuum is not able to resume after
>> setting itself to sleep for some reason.
>>
>>
>>
>
> Immediately after I sent this, I saw the vacuum unlock itself and
> continue... so there *are* some queries still blocking it. I'm seeing
> some highish (1 -2 minute) lock waits for a certain table:
>
> postgres=# select datname,procpid, query_start, current_query
>            from pg_stat_activity where now() - query_start > '1 minute'
>            and procpid in (select distinct pid from pg_locks where not
> granted) order by query_start;
>  datname | procpid |          query_start          |        current_query
> ---------+---------+-------------------------------+------------------------------
>
>  stuff   |     390 | 2011-03-08 12:57:01.752234+13 | UPDATE
> content.twitter_queue
>                                                    : SET error = $1
>                                                    : WHERE
> twitter_queue_id = $2
> (30 or so)
>
> which are probably not helping.
>
>

Make that definitely not helping:

stuff=# select relname, last_vacuum
         from pg_stat_all_tables
         where last_vacuum is not null
         and last_vacuum>  '2011-03-08 06:03:06'::timestamp
         order by last_vacuum limit 3;
     relname     |          last_vacuum
----------------+-------------------------------
  headline_alert | 2011-03-08 06:03:06.182866+13
  stock_static   | 2011-03-08 06:03:06.610739+13
  twitter_queue  | 2011-03-08 12:58:03.02451+13
(3 rows)



So we were trying to vacuum 'twitter_queue' (a small 20MB table) for
approx 6 hrs.

Note that the vacuum itself was not waiting in any locks according to
pg_locks, so looks to be the pinning issue. Clearly we need to amend the
application design that results in this quite long (1-2 minute)! wait
for the lock on this table.

regards

Mark

P.s: for the interested, the process(es) that the above UPDATEs are
waiting for are sitting '<IDLE> in transaction' - i.e application end is
doing some *non database* blocking call whilst holding a lock on the
'twitter_queue' table :-/