Help: 8.0.3 Vacuum of an empty table never completes ...

James Robinson <jlrobins@socialserve.com> writes:

Comparing the logs further with when it did complete, it seems that
one table in particular (at least) seems afflicted:

social=# vacuum verbose analyze agency.swlog_client;

hangs up forever -- have to control-c the client. Likewise for w/o
'analyze'.

Given that it's not eating CPU time, one would guess that it's blocked
waiting for a lock. Can you find any relevant locks in pg_locks?

regards, tom lane

As fate would have it, the vacuumdb frontend and backend which were
initially afflicted are still in existence:

sscadmin 19236 19235 0 Nov25 ? 00:00:00 /usr/local/pgsql/bin/
vacuumdb -U postgres --all --analyze --verbose
postgres 19244 3596 0 Nov25 ? 00:00:02 postgres: postgres
social [local] VACUUM

pid 19244.

And here's pg_locks:

social=# select * from pg_locks;
relation | database | transaction |  pid  |           mode            
| granted
----------+----------+-------------+-------+-------------------------- 
+---------
           |          |    38790657 | 19244 |  
ExclusiveLock            | t
   6586066 |  6585892 |             | 28406 |  
ShareUpdateExclusiveLock | f
           |          |    39097312 | 28861 |  
ExclusiveLock            | t
           |          |    39089744 | 28756 |  
ExclusiveLock            | t
   6586066 |  6585892 |             | 28756 |  
ShareUpdateExclusiveLock | f
   6586066 |  6585892 |             | 19244 |  
ShareUpdateExclusiveLock | t
   6586066 |  6585892 |             | 19244 |  
ShareUpdateExclusiveLock | t
   8417138 |  6585892 |             | 19244 |  
ShareUpdateExclusiveLock | t
     16839 |  6585892 |             | 28861 |  
AccessShareLock          | t
           |          |    39063661 | 28560 |  
ExclusiveLock            | t
           |          |    39056736 | 28406 |  
ExclusiveLock            | t
   6586066 |  6585892 |             | 28560 |  
ShareUpdateExclusiveLock | f
(12 rows)

pid
-------
19244
28406
28560
28756
28861
(5 rows)

Of those 5 pids:

19244 -- vaccuum backend initally afflicted -- status in argv:
'postgres: postgres social [local] VACUUM'
28406 -- a 10AM today vacuum started up by cron this morning after I
got things half-way working again early in the diagnosis of this
situation. args: 'postgres: postgres social [local] VACUUM waiting'
28560 -- a 10:16 today by-hand vacuum session futher in diagnosis
land. args: 'postgres: postgres social [local] VACUUM waiting'
28756 -- 11AM cron'd process. Yes, I see a quickly mounting issue
here. args: 'postgres: postgres social [local] VACUUM waiting'
28861 -- production servicing backend, now back in idle state. [ not
in tx idle by regular idle ].

On Nov 28, 2005, at 11:09 AM, Tom Lane wrote:

James Robinson <jlrobins@socialserve.com> writes:

Comparing the logs further with when it did complete, it seems that
one table in particular (at least) seems afflicted:

social=# vacuum verbose analyze agency.swlog_client;

hangs up forever -- have to control-c the client. Likewise for w/o
'analyze'.

Given that it's not eating CPU time, one would guess that it's blocked
waiting for a lock. Can you find any relevant locks in pg_locks?

regards, tom lane

----
James Robinson
Socialserve.com

James Robinson <jlrobins@socialserve.com> writes:

As fate would have it, the vacuumdb frontend and backend which were
initially afflicted are still in existence:

OK, so pid 19244 isn't blocked on any lmgr lock; else we'd see an entry
with granted = f for it in pg_locks. It could be blocked on a lower
level lock though. Can you attach to that PID with gdb and get a stack
trace? Something like (as postgres user)

gdb /path/to/postgres-executable 19244
gdb> bt
gdb> quit
ok to detach? yes

regards, tom lane

Here ya go -- BTW -- your guys support is the _best_. But you know
that already:

postgres@db01:/home/sscadmin> gdb /usr/local/pgsql/bin/postgres 19244
GNU gdb 6.2.1
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and
you are
welcome to change it and/or distribute copies of it under certain
conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for
details.
This GDB was configured as "i586-suse-linux"...Using host
libthread_db library "/lib/tls/libthread_db.so.1".

Attaching to program: /usr/local/pgsql/bin/postgres, process 19244
Reading symbols from /lib/libz.so.1...done.
Loaded symbols for /lib/libz.so.1
Reading symbols from /lib/libreadline.so.5...done.
Loaded symbols for /lib/libreadline.so.5
Reading symbols from /lib/libcrypt.so.1...done.
Loaded symbols for /lib/libcrypt.so.1
Reading symbols from /lib/libresolv.so.2...done.
Loaded symbols for /lib/libresolv.so.2
Reading symbols from /lib/libnsl.so.1...done.
Loaded symbols for /lib/libnsl.so.1
Reading symbols from /lib/libdl.so.2...done.
Loaded symbols for /lib/libdl.so.2
Reading symbols from /lib/tls/libm.so.6...done.
Loaded symbols for /lib/tls/libm.so.6
Reading symbols from /lib/tls/libc.so.6...done.
Loaded symbols for /lib/tls/libc.so.6
Reading symbols from /lib/libncurses.so.5...done.
Loaded symbols for /lib/libncurses.so.5
Reading symbols from /lib/ld-linux.so.2...done.
Loaded symbols for /lib/ld-linux.so.2
Reading symbols from /lib/libnss_compat.so.2...done.
Loaded symbols for /lib/libnss_compat.so.2
Reading symbols from /lib/libnss_nis.so.2...done.
Loaded symbols for /lib/libnss_nis.so.2
Reading symbols from /lib/libnss_files.so.2...done.
Loaded symbols for /lib/libnss_files.so.2
0xffffe410 in ?? ()
(gdb) bt
#0 0xffffe410 in ?? ()
#1 0xbfffd508 in ?? ()
#2 0x082aef97 in PqSendBuffer ()
#3 0xbfffd4f0 in ?? ()
#4 0xb7ec03e1 in send () from /lib/tls/libc.so.6
#5 0x08137d27 in secure_write ()
#6 0x0813c2a7 in internal_flush ()
#7 0x0813c4ff in pq_flush ()
#8 0x0820bfec in EmitErrorReport ()
#9 0x0820b5ac in errfinish ()
#10 0x0811d0a8 in lazy_vacuum_rel ()
#11 0x0811ac5a in vacuum_rel ()
#12 0x0811bb93 in vacuum ()
#13 0x0819c84d in PortalRunUtility ()
#14 0x0819d9b8 in PortalRun ()
#15 0x0819b221 in PostgresMain ()
#16 0x0816ffa9 in ServerLoop ()
#17 0x08170de9 in PostmasterMain ()
#18 0x0813e5e5 in main ()
(gdb) quit

----
James Robinson
Socialserve.com

James Robinson <jlrobins@socialserve.com> writes:

(gdb) bt
#0 0xffffe410 in ?? ()
#1 0xbfffd508 in ?? ()
#2 0x082aef97 in PqSendBuffer ()
#3 0xbfffd4f0 in ?? ()
#4 0xb7ec03e1 in send () from /lib/tls/libc.so.6
#5 0x08137d27 in secure_write ()
#6 0x0813c2a7 in internal_flush ()
#7 0x0813c4ff in pq_flush ()
#8 0x0820bfec in EmitErrorReport ()
#9 0x0820b5ac in errfinish ()
#10 0x0811d0a8 in lazy_vacuum_rel ()
#11 0x0811ac5a in vacuum_rel ()
#12 0x0811bb93 in vacuum ()
#13 0x0819c84d in PortalRunUtility ()
#14 0x0819d9b8 in PortalRun ()
#15 0x0819b221 in PostgresMain ()
#16 0x0816ffa9 in ServerLoop ()
#17 0x08170de9 in PostmasterMain ()
#18 0x0813e5e5 in main ()
(gdb) quit

Hmm, what this says is that the backend is blocked trying to send an
error or notice message to the client. We can't tell anything about
what the message was, but that's not so relevant ... the focus now
has to shift to the network or client side, ie, why in the world is
the backend waiting on the client to accept a message?

Can you get a similar backtrace from the vacuumdb process? (Obviously,
give gdb the vacuumdb executable not the postgres one.)

regards, tom lane

On Nov 28, 2005, at 11:38 AM, Tom Lane wrote:

Can you get a similar backtrace from the vacuumdb process?
(Obviously,
give gdb the vacuumdb executable not the postgres one.)

OK:

(gdb) bt
#0 0xffffe410 in ?? ()
#1 0xbfffe4f8 in ?? ()
#2 0x00000030 in ?? ()
#3 0x08057b68 in ?? ()
#4 0xb7e98533 in __write_nocancel () from /lib/tls/libc.so.6
#5 0xb7e4aae6 in _IO_new_file_write () from /lib/tls/libc.so.6
#6 0xb7e4a7e5 in new_do_write () from /lib/tls/libc.so.6
#7 0xb7e4aa63 in _IO_new_file_xsputn () from /lib/tls/libc.so.6
#8 0xb7e413a2 in fputs () from /lib/tls/libc.so.6
#9 0xb7fd8f99 in defaultNoticeProcessor () from /usr/local/pgsql/lib/
libpq.so.4
#10 0xb7fd8fe5 in defaultNoticeReceiver () from /usr/local/pgsql/lib/
libpq.so.4
#11 0xb7fe2d34 in pqGetErrorNotice3 () from /usr/local/pgsql/lib/
libpq.so.4
#12 0xb7fe3921 in pqParseInput3 () from /usr/local/pgsql/lib/libpq.so.4
#13 0xb7fdb174 in parseInput () from /usr/local/pgsql/lib/libpq.so.4
#14 0xb7fdca99 in PQgetResult () from /usr/local/pgsql/lib/libpq.so.4
#15 0xb7fdcc4b in PQexecFinish () from /usr/local/pgsql/lib/libpq.so.4
#16 0x0804942c in vacuum_one_database ()
#17 0x080497a1 in main ()

Things to know which could possibly be of use. This cron is kicked
off on the backup database box, and the vacuumdb is run via ssh to
the primary box. The primary box is running the vacuumdb operation
with --analyze --verbose, with the output being streamed to a logfile
on the backup box. Lemme guess __write_nocancel calls syscall write,
and 0x00000030 might could well be the syscall entry point? Something
gumming up the networking or sshd itself could have stopped up the
ouput queues, and the backups populated all the way down to this level?

If so, only dummies backup / vacuum direct to remote?

----
James Robinson
Socialserve.com

James Robinson <jlrobins@socialserve.com> writes:

On Nov 28, 2005, at 11:38 AM, Tom Lane wrote:

Can you get a similar backtrace from the vacuumdb process?

OK:

(gdb) bt
#0 0xffffe410 in ?? ()
#1 0xbfffe4f8 in ?? ()
#2 0x00000030 in ?? ()
#3 0x08057b68 in ?? ()
#4 0xb7e98533 in __write_nocancel () from /lib/tls/libc.so.6
#5 0xb7e4aae6 in _IO_new_file_write () from /lib/tls/libc.so.6
#6 0xb7e4a7e5 in new_do_write () from /lib/tls/libc.so.6
#7 0xb7e4aa63 in _IO_new_file_xsputn () from /lib/tls/libc.so.6
#8 0xb7e413a2 in fputs () from /lib/tls/libc.so.6
#9 0xb7fd8f99 in defaultNoticeProcessor () from /usr/local/pgsql/lib/
libpq.so.4
#10 0xb7fd8fe5 in defaultNoticeReceiver () from /usr/local/pgsql/lib/
libpq.so.4
#11 0xb7fe2d34 in pqGetErrorNotice3 () from /usr/local/pgsql/lib/
libpq.so.4
#12 0xb7fe3921 in pqParseInput3 () from /usr/local/pgsql/lib/libpq.so.4
#13 0xb7fdb174 in parseInput () from /usr/local/pgsql/lib/libpq.so.4
#14 0xb7fdca99 in PQgetResult () from /usr/local/pgsql/lib/libpq.so.4
#15 0xb7fdcc4b in PQexecFinish () from /usr/local/pgsql/lib/libpq.so.4
#16 0x0804942c in vacuum_one_database ()
#17 0x080497a1 in main ()

OK, so evidently the backend is sending NOTICE messages, and the
vacuumdb is blocked trying to copy those messages to stderr.

Things to know which could possibly be of use. This cron is kicked
off on the backup database box, and the vacuumdb is run via ssh to
the primary box. The primary box is running the vacuumdb operation
with --analyze --verbose, with the output being streamed to a logfile
on the backup box. Lemme guess __write_nocancel calls syscall write,
and 0x00000030 might could well be the syscall entry point? Something
gumming up the networking or sshd itself could have stopped up the
ouput queues, and the backups populated all the way down to this level?

That's what it looks like: the output queue from the vacuumdb has
stopped up somehow. Your next move is to look at the state of sshd
and whatever is running at the client end of the ssh tunnel.

regards, tom lane

On Nov 28, 2005, at 12:00 PM, Tom Lane wrote:

Your next move is to look at the state of sshd
and whatever is running at the client end of the ssh tunnel.

backtrace of the sshd doesn't look good:

(gdb) bt
#0 0xffffe410 in ?? ()
#1 0xbfffdb48 in ?? ()
#2 0x080a1e28 in ?? ()
#3 0x080a1e78 in ?? ()
#4 0xb7d379fd in ___newselect_nocancel () from /lib/tls/libc.so.6
#5 0x08054d64 in ?? ()
#6 0x0000000a in ?? ()
#7 0x080a1e78 in ?? ()
#8 0x080a1e28 in ?? ()
#9 0x00000000 in ?? ()
#10 0xbfffdb30 in ?? ()
#11 0x00000000 in ?? ()
#12 0xbfffdb48 in ?? ()
#13 0x0806c796 in ?? ()
#14 0x080a9d3c in ?? ()
#15 0x00000001 in ?? ()
#16 0xbfffdb64 in ?? ()
#17 0x08054c3d in ?? ()
#18 0x00000019 in ?? ()
#19 0x000acda0 in ?? ()
#20 0x080a9d3c in ?? ()
#21 0x00000000 in ?? ()
#22 0xbfffdb6c in ?? ()
#23 0x00000000 in ?? ()
#24 0xbfffdb78 in ?? ()
---Type <return> to continue, or q <return> to quit---
#25 0x08055632 in ?? ()
#26 0xbfffdb6c in ?? ()
#27 0x00000000 in ?? ()
#28 0x080a1e78 in ?? ()
#29 0x08098ee8 in ?? ()
#30 0x080a1e78 in ?? ()
#31 0x080a1e28 in ?? ()
#32 0x00000009 in ?? ()
#33 0x00000004 in ?? ()
#34 0x00000001 in ?? ()
#35 0x00000001 in ?? ()
#36 0xbfffdbb8 in ?? ()
#37 0x0805b816 in ?? ()
#38 0x08098ee8 in ?? ()
#39 0x080a2e10 in ?? ()
#40 0x00000007 in ?? ()
#41 0x08098ee8 in ?? ()
#42 0x08080fd2 in _IO_stdin_used ()
#43 0x08098ee8 in ?? ()
#44 0xbfffdbb8 in ?? ()
#45 0x080574a3 in ?? ()
#46 0x00000000 in ?? ()
#47 0x08098ee8 in ?? ()
#48 0x08098ee8 in ?? ()
#49 0x08098f30 in ?? ()
---Type <return> to continue, or q <return> to quit---
#50 0x08080fd2 in _IO_stdin_used ()
#51 0x08098ee8 in ?? ()
#52 0xbfffeb98 in ?? ()
#53 0x0804fc90 in ?? ()
#54 0x08098ee8 in ?? ()
#55 0x08098f74 in ?? ()
#56 0x08098f30 in ?? ()
#57 0xbfffe110 in ?? ()
#58 0xbfffe110 in ?? ()
#59 0x0808014a in _IO_stdin_used ()
#60 0xb7ffad95 in malloc () from /lib/ld-linux.so.2
Previous frame inner to this frame (corrupt stack?)

The client-side ssh is worse -- 507 frames before it reports
'(corrupt stack?)'.

At this moment in time, should we kill off the offending processes
from Nov 25 -- starting from client-most side all the way to the
vacuumdb process on the production server. The other vacuums would
probably then complete happily, and we'd be cool again, eh?

I suppose we're darn lucky the process got ultimately gummed up on a
table that sees no traffic at all to it, eh? The lock that vacuum has
taken out on it would prevent at least some things happening to the
table in question -- possibly even new inserts or updates?

Could this potentially be alleviated in the future by a little code
reordering in vacuumdb or postmaster by completing working on the
current table completely before emitting output, either postmaster ->
vacuumdb client, or possibly the vacuumdb client -> whatever stdout
is directed to so as to get gummed up in a state when no locks are
being held? Or would that uglify the code too much and/or people
would find that additional buffering a damnable offense?

----
James Robinson
Socialserve.com

James Robinson <jlrobins@socialserve.com> writes:

backtrace of the sshd doesn't look good:

Stripped executable :-( ... you won't get much info there. What of
the client at the far end of the ssh connection? You should probably
assume that the blockage is there, rather than in a commonly used bit
of software like ssh.

At this moment in time, should we kill off the offending processes
from Nov 25 -- starting from client-most side all the way to the
vacuumdb process on the production server. The other vacuums would
probably then complete happily, and we'd be cool again, eh?

If you just want to get out of it, killing the vacuumdb should be the
least dangerous way to get out of the problem. I'd suggest taking a
little more time to try to find out what's stuck though.

I suppose we're darn lucky the process got ultimately gummed up on a
table that sees no traffic at all to it, eh? The lock that vacuum has
taken out on it would prevent at least some things happening to the
table in question -- possibly even new inserts or updates?

No, since it's a lazy vacuum it's not going to block either reads or
writes. Just other vacuums and DDL changes on the table.

Could this potentially be alleviated in the future by a little code
reordering in vacuumdb or postmaster by completing working on the
current table completely before emitting output,

Wouldn't help. I would imagine that by the time we got to this state,
the backend side is quite a few tables past the point where the end
client stopped accepting output. You'd normally expect there to be
several Kb worth of buffering in the network channel, and the backend
isn't going to be blocked till that's *all* used up.

BTW, I suppose this was a VACUUM VERBOSE? Without the verbose output,
you'd likely not have seen any problem ...

regards, tom lane

On Nov 28, 2005, at 1:46 PM, Tom Lane wrote:

James Robinson <jlrobins@socialserve.com> writes:

backtrace of the sshd doesn't look good:

Stripped executable :-( ... you won't get much info there. What of
the client at the far end of the ssh connection? You should probably
assume that the blockage is there, rather than in a commonly used bit
of software like ssh.

Ok: cron fired off a bash running our script which performs the
backup + vacuuming on the backup box side, and that script was at the
point of driving vacuumdb

sscadmin 20612 20610 0 Nov25 ? 00:00:00 bash /usr/local/bin/
db_backup.sh
sscadmin 20622 20612 0 Nov25 ? 00:00:00 ssh -c blowfish [ ssh
identity file + host edited out ] /usr/local/pgsql/bin/vacuumdb -U
postgres --all --analyze --verbose

[ yes, verbose vacuum. Who knew that'd be the camel-breaking straw ??! ]

The lines in the script invoking the ssh'd vacuumdb is:
--
# Vacuum all databases, storing log results.
$SSHCMD $DBHOST /usr/local/pgsql/bin/vacuumdb -U postgres --all --
analyze --verb
ose >& $DATE/vacuum.log
--

Unfortunately the dir holding that date + hour's vacuum.log was swept
away by the next day's activities.

The stuck bash is backtraceable:

(gdb) bt
#0 0xffffe410 in ?? ()
#1 0xbffff928 in ?? ()
#2 0x00000000 in ?? ()
#3 0xbffff918 in ?? ()
#4 0xb7ed1513 in __waitpid_nocancel () from /lib/tls/libc.so.6
#5 0x080935bf in default_tty_job_signals ()
#6 0x080949ca in wait_for ()
#7 0x0808acd7 in execute_command_internal ()
#8 0x0808a4f0 in execute_command ()
#9 0x0808241d in reader_loop ()
#10 0x08081364 in main ()
(gdb)

Nothing unexpected there. Funny though, file reports /bin/bash as
being stripped ( as it does for /usr/bin/ssh and /usr/sbin/sshd ),
but I could get far better debugging support from it. Could the
debugging issue be ssh / sshd's apparent multithreadedness:

gdb /usr/bin/ssh
GNU gdb 6.2.1
Copyright 2004 Free Software Foundation, Inc.
GDB is free software, covered by the GNU General Public License, and
you are
welcome to change it and/or distribute copies of it under certain
conditions.
Type "show copying" to see the conditions.
There is absolutely no warranty for GDB. Type "show warranty" for
details.
This GDB was configured as "i586-suse-linux"...(no debugging symbols
found)...Using host libthread_db library "/lib/tls/libthread_db.so.1".

(gdb) run localhost
Starting program: /usr/bin/ssh localhost
(no debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...[Thread
debugging using libthread_db enabled]
[New Thread 1078408704 (LWP 29932)]
(no debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...(no
debugging symbols found)...(no debugging symbols found)...The
authenticity of host 'localhost (127.0.0.1)' can't be established.
RSA key fingerprint is f4:cd:bc:37:d7:08:bc:4f:04:91:45:9b:44:cf:d5:b9.
Are you sure you want to continue connecting (yes/no)?
Program received signal SIGINT, Interrupt.
[Switching to Thread 1078408704 (LWP 29932)]
0xffffe410 in ?? ()
(gdb) bt
#0 0xffffe410 in ?? ()
#1 0xbfffb9e8 in ?? ()
#2 0x00000001 in ?? ()
#3 0xbfffb3af in ?? ()
#4 0x402f94b3 in __read_nocancel () from /lib/tls/libc.so.6
#5 0x080742e1 in mkstemp64 ()
#6 0x080684c8 in error ()
#7 0x08054e91 in ?? ()
#8 0xbfffcac0 in ?? ()
#9 0x00000001 in ?? ()
#10 0x08096230 in ?? ()
#11 0xbfffcac0 in ?? ()
....

I know you have far better things to do than teach someone how to use
gdb on multithreaded programs, but could a proper backtrace be
salvageable on the ssh client? If you really care, that is, otherwise
I'm off to kill that vacuumdb client.

At this moment in time, should we kill off the offending processes
from Nov 25 -- starting from client-most side all the way to the
vacuumdb process on the production server. The other vacuums would
probably then complete happily, and we'd be cool again, eh?

If you just want to get out of it, killing the vacuumdb should be the
least dangerous way to get out of the problem. I'd suggest taking a
little more time to try to find out what's stuck though.

Given the other culprits in play are bash running a straightforward
shellscript line with redirected output to a simple file on a non-
full filesystem, I'm leaning more towards the odds that something
related to the sshd + tcp/ip + ssh client portion of things went
crazy. Just seems that's where more complexity is -- bash is doing
nothing but waiting for the ssh client to finish, and its stdout /
stderr were redired to the fileystem before the bash child exec'd
ssh. Even if the filesystem became full somehow during that run, one
would expect the ssh client's writes to the file being error'd out as
opposed to blocking. Funky.

I suppose we're darn lucky the process got ultimately gummed up on a
table that sees no traffic at all to it, eh? The lock that vacuum has
taken out on it would prevent at least some things happening to the
table in question -- possibly even new inserts or updates?

No, since it's a lazy vacuum it's not going to block either reads or
writes. Just other vacuums and DDL changes on the table.

Good to know.

Could this potentially be alleviated in the future by a little code
reordering in vacuumdb or postmaster by completing working on the
current table completely before emitting output,

Wouldn't help. I would imagine that by the time we got to this state,
the backend side is quite a few tables past the point where the end
client stopped accepting output. You'd normally expect there to be
several Kb worth of buffering in the network channel, and the backend
isn't going to be blocked till that's *all* used up.

But when it does get blocked up, albeit after-the-fact, it wouldn't
be holding and postgres-level locks. But, since this was lazy vacuum,
only other lazy vacuums or DDL would be blocked. But had some other
poor chap been running full vacuum, then it could have been worse.

BTW, I suppose this was a VACUUM VERBOSE? Without the verbose output,
you'd likely not have seen any problem ...

Yep -- see above.

I do believe we've agreed internally to separate out the vacuuming
bit from the backup bit, and have that be driven by a separate cron'd
script on the primary database box itself to simplify the system for
this case. And with 8.1 we'll move to the autovacuum service, so as
to obliterate the need altogether. So, our vacuuming would be
happening in a globally far simpler system -- no remote host
networking involved at all.

Again, thanks again for all of your time and superb support.

----
James Robinson
Socialserve.com

James Robinson <jlrobins@socialserve.com> writes:

Given the other culprits in play are bash running a straightforward
shellscript line with redirected output to a simple file on a non-
full filesystem, I'm leaning more towards the odds that something
related to the sshd + tcp/ip + ssh client portion of things went
crazy.

Yeah, could be. Anyway it doesn't seem like we can learn much more
today. You might as well just zing the vacuumdb process and let
things get back to normal. If it happens again, we'd have reason
to dig deeper.

regards, tom lane

On Nov 28, 2005, at 4:13 PM, Tom Lane wrote:

Yeah, could be. Anyway it doesn't seem like we can learn much more
today. You might as well just zing the vacuumdb process and let
things get back to normal. If it happens again, we'd have reason
to dig deeper.

Final report [ and apologies to hackers list in general -- sorry for
the noise today ].

Killed the vacuumdb frontend. Then went off killing processes spawned
by cron on Nov25th related to the cronjob. All of the related
backends exited peacefully, and all is well. Manual vacuum verbose
analyze completes successfully.

One possibly curious thing -- one final process remains on the backup
box dated Nov25:

root 19912 3 0 Nov25 ? 00:00:12 [pdflush]

Coincidence? This is some sort of kernel thread, right? Flushes dirty
pages to disk? There are two on this machine:

root 9211 3 0 Nov22 ? 00:02:56 [pdflush]
root 19912 3 0 Nov25 ? 00:00:12 [pdflush]

The Nov25'ths pdflush's pid is suspiciously close to the pids which
would be in use around the beginning of the cron'd process. [ checks /
var/log/messages ... ] -- yep -- real close -- last known cross-
referencable pid is:

Nov 25 04:59:01 db02 /usr/sbin/cron[20590]: (root) CMD ( rm -f /var/
spool/cron/lastrun/cron.hourly)

and the vacuumdb sshd connection on the production db box is logged
at 05:02:22 AM, so that pdflush would have been started real close to
the time which the remote backup + vacuum script would have been
running.

Any Linux 2.6 gurus lurking? Under what circumstances do pdflush'es
get spawned? The filesystem upon which the outputs were going is a
software raid partition (raid-0? raid-1? Always confuse the two) --
the interleaved one anyway, not mirrored -- formatted reiser3.

Neither pdflush instance on this machine was started anywhere near
the boot time of the machine -- both much later. Whereas on the
production box the two pdflush instances are both dated from machine
boot time. Does this perchance indicate unhappiness afoot perhaps
hardware-wise?

----
James Robinson
Socialserve.com