BUG #13472: VACUUM ANALYZE hangs on certain tables

The following bug has been logged on the website:

Bug reference: 13472
Logged by: Matthew Seaman
Email address: matthew(dot)seaman(at)adestra(dot)com
PostgreSQL version: 9.2.10
Operating system: FreeBSD 10.1-RELEASE-p9
Description:

We have two tables which we have not been able to vacuum sucessfully on one
of our database servers. The vacuum process just hangs almost
instantaneously after issuing the 'VACUUM ANALYZE' command.

Here's the result of truss'ing the psql process like so: db-21a:/tmp:# truss
-p 85976 -d -s 128 -f -o /tmp/postgres-vacuum.truss

db-21a:/tmp:# cat postgres-vacuum.truss
85976: -1435316384.769176354 SIGNAL 17 (SIGSTOP)
85976: 3.038535625 recvfrom(10,"Q\0\0\0\^_VACUUM ANALYZE page_tags
;\0",8192,0x0,NULL,0x0) = 32 (0x20)
85976: 3.038826780 open("pg_stat_tmp/pgstat.stat",O_RDONLY,0666) = 21
(0x15)
85976: 3.038891300 fstat(21,{ mode=-rw-------
,inode=7142821,size=862100,blksize=32768 }) = 0 (0x0)
85976: 3.039011646
read(21,"\M^Z\M-<\M-%\^A\M-*\M-}\M-_gh\M-<\^A\0+B\0\0\0\0\0\0#\^U\0\0\0\0\0\0o\M-2\M-\\M^F\0\0\0\0\M-)3;\0\0\0\0\0\M-g\^^`2\0\0\0\0\M-H"...,32768)
= 32768 (0x8000)
85976: 3.040517980 close(21) = 0 (0x0)
85976: 3.040590876
sendto(9,"\^A\0\0\0\^P\0\0\0g\M^H\^Xhh\M-<\^A\0",16,0x0,NULL,0x0) = 16
(0x10)
85976: 3.050990883 select(0,0x0,0x0,0x0,{0.010000 }) = 0 (0x0)
85976: 3.051077076 open("pg_stat_tmp/pgstat.stat",O_RDONLY,0666) = 21
(0x15)
85976: 3.051124309 fstat(21,{ mode=-rw-------
,inode=7142808,size=862100,blksize=32768 }) = 0 (0x0)
85976: 3.051211802 read(21,"\M^Z\M-<\M-%\^A\M-z0
hh\M-<\^A\0+B\0\0\0\0\0\0#\^U\0\0\0\0\0\0o\M-2\M-\\M^F\0\0\0\0\M-)3;\0\0\0\0\0\M-g\^^`2\0\0\0\0\M-H\M-V\M^P"...,32768)
= 32768 (0x8000)
85976: 3.052608356 close(21) = 0 (0x0)
85976: 3.052693536 open("pg_stat_tmp/pgstat.stat",O_RDONLY,0666) = 21
(0x15)
85976: 3.052743522 fstat(21,{ mode=-rw-------
,inode=7142808,size=862100,blksize=32768 }) = 0 (0x0)
85976: 3.052812245 read(21,"\M^Z\M-<\M-%\^A\M-z0
hh\M-<\^A\0+B\0\0\0\0\0\0#\^U\0\0\0\0\0\0o\M-2\M-\\M^F\0\0\0\0\M-)3;\0\0\0\0\0\M-g\^^`2\0\0\0\0\M-H\M-V\M^P"...,32768)
= 32768 (0x8000)
85976: 3.054225196
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\M^D"...,32768)
= 32768 (0x8000)
85976: 3.055429568
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.056594506
read(21,"\0\0\^A\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.057768974
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T\M-\\M-v%\0\0\0\0\0K\^B\0\0\0\0\0\0\^F\b\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.058982546
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T1\M-x%\0\0\0\0\0\^D\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.060145744
read(21,"\0O\M^V$\M--\\\M-<\^A\0:\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^A\M-?$\M--\\\M-<\^A\0:\0\0\0\0\0\0\0\M-A8z\^S\M-O\M-7\^A"...,32768)
= 32768 (0x8000)
85976: 3.061483712
read(21,"\0\0\0\M-3\^_\0\0\0\0\0\0$\^]\0\0\0\0\0\0\M-e\M-oC\M--\\\M-<\^A\0:\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0(at)\M-sC\M--\\\M-<"...,32768)
= 32768 (0x8000)
85976: 3.062796877
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\M-I\M-V\^P\M-0\\"...,32768)
= 32768 (0x8000)
85976: 3.064062535
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.065262827
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.066425202
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0T\M^(at)\n\0\0\0\0\0\0\^C\0\0\0\0\0\0\0\^C\0\0\0\0\0\0\0\^C\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.067633907
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T:\^C\0\0\0\0\0\0\^B\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.068792535
read(21,"\^A\08\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0>\M-K"\M-.\\\M-<\^A\08\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T\M^[_&"...,32768)
= 32768 (0x8000)
85976: 3.069993310
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\M-h\M^F\M-,\M--\\\M-<\^A\08\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\M-k\M^G\M-,\M--\\\M-<\^A\08\0"...,32768)
= 32768 (0x8000)
85976: 3.071352321
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^A\0\0\0\0\0\0\0\t\0\0\0\0\0\0\0\^E\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.072538236
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\M^PI\M--\M-."...,32768)
= 32768 (0x8000)
85976: 3.073751354
read(21,"\0\0\0\^A\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^A\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^A\0\0\0\0\0\0\0\b\0\0"...,32768)
= 32768 (0x8000)
85976: 3.074951546
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.076144411
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T\M-v\^P\M^N\0\0\0\0\0\^A\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.077484792
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0T\M-|\^]\M-!\0\0\0\0\0\M^L"...,32768)
= 32768 (0x8000)
85976: 3.078847630
read(21,"\0\0\0\0\0O"\M-$\M-:\\\M-<\^A\0005\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.080215317
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\M-<\M-?}\M-a\\\M-<\^A\0/\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.081569181
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0{\^E\0\0\0\0\0\0B\^D\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 32768 (0x8000)
85976: 3.082836663
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\M-_\M-+\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\^RL\0\0\0\0\0\0.\t\0\0\0\0\0\0^\M^N"...,32768)
= 32768 (0x8000)
85976: 3.084285987
read(21,"\0\0\0\0\0v+\^B\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0v+\^B\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\M-v\M-b"...,32768)
= 32768 (0x8000)
85976: 3.085686937
read(21,"\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"...,32768)
= 10132 (0x2794)
85976: 3.086923792 close(21) = 0 (0x0)
85976: 3.087002286 lseek(11,0x0,SEEK_END) = 8192 (0x2000)
85976: 3.087083538 lseek(17,0x0,SEEK_END) = 483328 (0x76000)
85976: 3.088391400
madvise(0x80507c000,0x1000,0x5,0xaaaaaaaaaaaaaaab,0x805003eb8,0x802759be0) =
0 (0x0)
85976: 3.088444000
madvise(0x805217000,0x8000,0x5,0xaaaaaaaaaaaaaaab,0x805003eb8,0x802759be0) =
0 (0x0)
85976: 3.088511966
madvise(0x8052a1000,0x58000,0x5,0xaaaaaaaaaaaaaaab,0x805003eb8,0x802759be0)
= 0 (0x0)
85976: 3.088565242
madvise(0x805252000,0x2000,0x5,0xaaaaaaaaaaaaaaab,0x7fffffffcd00,0x802759be0)
= 0 (0x0)
85976: 3.088629049
madvise(0x805248000,0xa000,0x5,0xaaaaaaaaaaaaaaab,0x7fffffffcd00,0x802759be0)
= 0 (0x0)
85976: 3.088672235
madvise(0x805254000,0x4000,0x5,0xaaaaaaaaaaaaaaab,0x7fffffffcd00,0x802759be0)
= 0 (0x0)
85976: 3.088742918
madvise(0x805281000,0x20000,0x5,0xaaaaaaaaaaaaaaab,0x7fffffffcd00,0x802759be0)
= 0 (0x0)
85976: 3.088807845
madvise(0x80525f000,0x1c000,0x5,0xaaaaaaaaaaaaaaab,0x805003888,0x802759be0)
= 0 (0x0)
85976: 3.088875758 setitimer(0,{0.000000, 1.000000 },0x0) = 0 (0x0)
85976: 4.089210052 semop(0x3000b,0x7fffffffd550,0x1,0x0,0x20,0x1431e650f0)
ERR#4 'Interrupted system call'
85976: 4.089210052 SIGNAL 14 (SIGALRM)
85976: 4.089414257 sigprocmask(SIG_SETMASK,SIGALRM,0x0) = 0 (0x0)
85976: 4.089493593
semop(0x3000b,0x7fffffffcb28,0x1,0x0,0x6559a0,0x1431e650f0) = 0 (0x0)
85976: 4.089541500
sigreturn(0x7fffffffcb80,0x7fffffffcb80,0x301,0x0,0xfffffffffffffbc0,0x1431e650f0)
ERR#4 'Interrupted system call'
85976: 4.089594057 semop(0x3000b,0x7fffffffd550,0x1,0x0,0x20,0x1431e650f0) =
0 (0x0)
85976: 4.089914562 write(2,"\0\0N\^A\M-XO\^A\0t2015-06-26 11:59:47 BST 85976
pgsql [local] psql amf_more2 2015-06-26 11:38:43 BST [11]LOG: process 85976
st"...,343) = 343 (0x157)