Re: Hung Vacuum in 8.3

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.

So false alarm, no bug here it would seem, sorry.

Mark