Re: 8.1.3 and unused files

Am I correct in the thought that the various files listed below are not
used by the database and can be safely removed? There were no other
active db connections when I issued this command.

I think truncate (Slony) left them behind.

ssdb=# select file
from pg_ls_dir('base/'|| (select oid from pg_database where datname =
'ssdb')) as tab(file)
where file !~ '\\..*$'
and file not in (select relfilenode from pg_class)
and file not in ('PG_VERSION', 'pgsql_tmp');

file
---------
1434986
1434984
1434985
(3 rows)

[root(at)DB1 16384]# ls -la 143498[456]*
-rw------- 1 rbt sysadmin 1073741824 May 1 20:56 1434984
-rw------- 1 rbt sysadmin 1073741824 May 1 21:11 1434984.1
-rw------- 1 rbt sysadmin 1073741824 May 1 23:21 1434984.10
-rw------- 1 rbt sysadmin 1073741824 May 1 23:36 1434984.11
-rw------- 1 rbt sysadmin 1073741824 May 1 23:50 1434984.12
-rw------- 1 rbt sysadmin 1073741824 May 2 00:06 1434984.13
-rw------- 1 rbt sysadmin 1073741824 May 2 00:23 1434984.14
-rw------- 1 rbt sysadmin 1073741824 May 2 00:39 1434984.15
-rw------- 1 rbt sysadmin 1073741824 May 2 00:57 1434984.16
-rw------- 1 rbt sysadmin 1073741824 May 2 01:14 1434984.17
-rw------- 1 rbt sysadmin 1073741824 May 2 01:31 1434984.18
-rw------- 1 rbt sysadmin 1073741824 May 2 01:50 1434984.19
-rw------- 1 rbt sysadmin 1073741824 May 1 21:25 1434984.2
-rw------- 1 rbt sysadmin 1073741824 May 2 02:07 1434984.20
-rw------- 1 rbt sysadmin 1073741824 May 2 02:23 1434984.21
-rw------- 1 rbt sysadmin 1073741824 May 2 02:41 1434984.22
-rw------- 1 rbt sysadmin 1073741824 May 2 02:55 1434984.23
-rw------- 1 rbt sysadmin 1073741824 May 2 03:09 1434984.24
-rw------- 1 rbt sysadmin 1073741824 May 2 03:24 1434984.25
-rw------- 1 rbt sysadmin 1073741824 May 2 03:37 1434984.26
-rw------- 1 rbt sysadmin 1073741824 May 2 03:53 1434984.27
-rw------- 1 rbt sysadmin 1073741824 May 2 04:09 1434984.28
-rw------- 1 rbt sysadmin 1073741824 May 2 04:24 1434984.29
-rw------- 1 rbt sysadmin 1073741824 May 1 21:40 1434984.3
-rw------- 1 rbt sysadmin 1073741824 May 2 04:40 1434984.30
-rw------- 1 rbt sysadmin 1073741824 May 2 04:56 1434984.31
-rw------- 1 rbt sysadmin 990912512 May 2 05:09 1434984.32
-rw------- 1 rbt sysadmin 1073741824 May 1 21:54 1434984.4
-rw------- 1 rbt sysadmin 1073741824 May 1 22:08 1434984.5
-rw------- 1 rbt sysadmin 1073741824 May 1 22:23 1434984.6
-rw------- 1 rbt sysadmin 1073741824 May 1 22:36 1434984.7
-rw------- 1 rbt sysadmin 1073741824 May 1 22:52 1434984.8
-rw------- 1 rbt sysadmin 1073741824 May 1 23:07 1434984.9
-rw------- 1 rbt sysadmin 8192 May 1 20:40 1434985
-rw------- 1 rbt sysadmin 1073741824 May 2 11:27 1434986
-rw------- 1 rbt sysadmin 1073741824 May 2 11:39 1434986.1
-rw------- 1 rbt sysadmin 121733120 May 2 16:53 1434986.10
-rw------- 1 rbt sysadmin 1073741824 May 2 11:56 1434986.2
-rw------- 1 rbt sysadmin 1073741824 May 2 12:15 1434986.3
-rw------- 1 rbt sysadmin 1073741824 May 2 12:43 1434986.4
-rw------- 1 rbt sysadmin 1073741824 May 2 13:15 1434986.5
-rw------- 1 rbt sysadmin 1073741824 May 2 13:53 1434986.6
-rw------- 1 rbt sysadmin 1073741824 May 2 14:35 1434986.7
-rw------- 1 rbt sysadmin 1073741824 May 2 15:38 1434986.8
-rw------- 1 rbt sysadmin 1073741824 May 2 16:53 1434986.9
--

Rod Taylor <pg(at)rbt(dot)ca> writes:
> Am I correct in the thought that the various files listed below are not
> used by the database and can be safely removed? There were no other
> active db connections when I issued this command.

> I think truncate (Slony) left them behind.

I don't particularly like the casual assumption that truncate is broken.
If I were you I'd be looking harder for a plausible explanation about
where these files came from, especially seeing how large they are.
Have you tried dumping the file contents to see if the data looks
recognizable at all?

regards, tom lane

On Fri, 2006-05-05 at 14:09 -0400, Tom Lane wrote:
> Rod Taylor <pg(at)rbt(dot)ca> writes:
> > Am I correct in the thought that the various files listed below are not
> > used by the database and can be safely removed? There were no other
> > active db connections when I issued this command.
>
> > I think truncate (Slony) left them behind.
>
> I don't particularly like the casual assumption that truncate is broken.

> If I were you I'd be looking harder for a plausible explanation about
> where these files came from, especially seeing how large they are.
> Have you tried dumping the file contents to see if the data looks
> recognizable at all?

Hardware is perfectly functional and has been for about 18 months in
production with 8.0.x.

It is a completely new 8.1 database and Slony is the only entity that
has been working in it. There are not very many possibilities.

I'm fairly confident I know exactly which table they are/were a part of.
1434984 is the table data, 1434986 is the primary key of the table (only
index), and 1434985 is probably the toast structure.

The structure have different relfilenode values and valid data at this
time.

At some point it must have failed in copying the data across, aborted,
and restarted.

So it would have been something like this:

BEGIN;
TRUNCATE;
"decouple indexes -- ask Jan";
COPY;
"recouple indexes";
REINDEX <crash, abort, something else to cause a Slony to restart>;

<reconnect>
BEGIN;
TRUNCATE;
"decouple indexes -- ask Jan";
COPY; "recouple indexes";
REINDEX;
COMMIT;

--

Rod Taylor <pg(at)rbt(dot)ca> writes:
> At some point it must have failed in copying the data across, aborted,
> and restarted.

Unless you had an actual backend crash, that's not an adequate
explanation. Transaction abort does clean up created files.

regards, tom lane

On Fri, 2006-05-05 at 14:31 -0400, Tom Lane wrote:
> Rod Taylor <pg(at)rbt(dot)ca> writes:
> > At some point it must have failed in copying the data across, aborted,
> > and restarted.
>
> Unless you had an actual backend crash, that's not an adequate
> explanation. Transaction abort does clean up created files.

The only reason I noticed is because pg_database_size didn't match
sum(pg_total_relation_size()) and was investigating what I thought was a
bug in one of those functions.

I'm afraid we don't have all of the monitoring, logging, and change
control bits hooked up to the non-production DBs, so that is pretty much
all I have other than conjecture.

The only thing I can come up with is that perhaps someone forcefully
gave it a kick. SIGTERM is a necessary action once in a while to unwedge
a stuck db connection (killing the client script doesn't always get it
immediately).

Slony holds open a transaction on the master while reindexing the slave,
so perhaps someone thought the slave needed help. Making a copy of the
master takes several weeks. They may have killed slony, found the
statements still working away, SIGTERM'd them both, then restarted
slony. It wouldn't be an unusual pattern of events, particularly since
they've not been taught about pg_cancel_backend() yet (no 8.1 training).

How about this?

BEGIN;
TRUNCATE;
COPY;
REINDEX <SIGTERM during REINDEX>;

pg_class references old files. New files in their aborted state are left
behind?

--

Rod Taylor <pg(at)rbt(dot)ca> writes:
> On Fri, 2006-05-05 at 14:31 -0400, Tom Lane wrote:
>> Unless you had an actual backend crash, that's not an adequate
>> explanation. Transaction abort does clean up created files.

> The only thing I can come up with is that perhaps someone forcefully
> gave it a kick. SIGTERM is a necessary action once in a while to unwedge
> a stuck db connection (killing the client script doesn't always get it
> immediately).

SIGTERM wouldn't cause that either. I hope your people are not in the
habit of using "kill -9"?

regards, tom lane

On Fri, 2006-05-05 at 15:10 -0400, Tom Lane wrote:
> Rod Taylor <pg(at)rbt(dot)ca> writes:
> > On Fri, 2006-05-05 at 14:31 -0400, Tom Lane wrote:
> >> Unless you had an actual backend crash, that's not an adequate
> >> explanation. Transaction abort does clean up created files.
>
> > The only thing I can come up with is that perhaps someone forcefully
> > gave it a kick. SIGTERM is a necessary action once in a while to unwedge
> > a stuck db connection (killing the client script doesn't always get it
> > immediately).
>
> SIGTERM wouldn't cause that either. I hope your people are not in the
> habit of using "kill -9"?

Command line records, etc. are not available, but I did track down a a
snippet of logs from the backups (daily log rotation). Sorry, I didn't
realize there were backups initially -- it's unusual. Appears it did
crash or get killed in some way "exited with exit code 1".

It's a temp DB to try a different database encoding (prep for 8.1
upgrade) with production data.

Is there something you would like me to try doing in an attempt to
reproduce? Preferably with a smaller structure.

The truncate would have happened as part of the prepareTableForCopy()
call.

slony%ssdb 10171 4621947 2006-05-02 05:09:40 EDTLOG: 00000: duration: 30526368.316 ms statement: select "_ssrep".prepareTableForCopy(1010); copy <SNIP> from stdin;
slony%ssdb 10171 4621947 2006-05-02 05:09:40 EDTLOCATION: exec_simple_query, postgres.c:1103
slony%ssdb 10171 4621947 2006-05-02 05:09:40 EDTLOCATION: exec_simple_query, postgres.c:1103
slony%ssdb 10181 0 2006-05-02 15:32:06 EDTLOG: 08P01: unexpected EOF on client connection
slony%ssdb 10181 0 2006-05-02 15:32:06 EDTLOCATION: SocketBackend, postgres.c:295
slony%ssdb 10154 0 2006-05-02 15:32:06 EDTLOG: 08P01: unexpected EOF on client connection
slony%ssdb 10154 0 2006-05-02 15:32:06 EDTLOCATION: SocketBackend, postgres.c:295
slony%ssdb 10173 0 2006-05-02 16:30:53 EDTLOG: 08P01: unexpected EOF on client connection
slony%ssdb 10173 0 2006-05-02 16:30:53 EDTLOCATION: SocketBackend, postgres.c:295
slony%ssdb 10755 0 2006-05-02 16:30:53 EDTLOG: 08P01: unexpected EOF on client connection
slony%ssdb 10755 0 2006-05-02 16:30:53 EDTLOCATION: SocketBackend, postgres.c:295
slony%ssdb 300 0 2006-05-02 16:55:18 EDTLOG: 08P01: unexpected EOF on client connection
slony%ssdb 300 0 2006-05-02 16:55:18 EDTLOCATION: SocketBackend, postgres.c:295
slony%ssdb 301 0 2006-05-02 16:55:18 EDTLOG: 08P01: unexpected EOF on client connection
slony%ssdb 301 0 2006-05-02 16:55:18 EDTLOCATION: SocketBackend, postgres.c:295
% 1960 2006-05-02 17:03:19 EDTLOG: 00000: server process (PID 10171) exited with exit code 1
% 1960 2006-05-02 17:03:19 EDTLOCATION: LogChildExit, postmaster.c:2416
% 1960 2006-05-02 17:03:19 EDTLOG: 00000: terminating any other active server processes
% 1960 2006-05-02 17:03:19 EDTLOCATION: HandleChildCrash, postmaster.c:2306
% 1960 2006-05-02 17:03:19 EDTLOCATION: HandleChildCrash, postmaster.c:2306
% 1960 2006-05-02 17:03:19 EDTLOG: 00000: all server processes terminated; reinitializing
% 1960 2006-05-02 17:03:19 EDTLOCATION: reaper, postmaster.c:2206
< snip connection attempts >
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: database system was interrupted at 2006-05-02 16:06:20 EDT
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4374
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: checkpoint record is at 59/E0B56920
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4442
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: redo record is at 59/E0B56920; undo record is at 0/0; shutdown FALSE
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4469
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: next transaction ID: 4863932; next OID: 1441853
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4472
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: next MultiXactId: 1; next MultiXactOffset: 0
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4475
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: database system was not properly shut down; automatic recovery in progress
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4532
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: redo starts at 59/E0B56970
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4569
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: record with zero length at 59/E0E429B8
% 5826 2006-05-02 17:03:22 EDTLOCATION: ReadRecord, xlog.c:2764
% 5826 2006-05-02 17:03:22 EDTLOG: 00000: redo done at 59/E0E42988
% 5826 2006-05-02 17:03:22 EDTLOCATION: StartupXLOG, xlog.c:4627
% 5826 2006-05-02 17:03:23 EDTLOG: 00000: database system is ready
% 5826 2006-05-02 17:03:23 EDTLOCATION: StartupXLOG, xlog.c:4821
% 5826 2006-05-02 17:03:23 EDTLOG: 00000: transaction ID wrap limit is 1073749769, limited by database "ssdb"
% 5826 2006-05-02 17:03:23 EDTLOCATION: SetTransactionIdLimit, varsup.c:234
--

Rod Taylor <pg(at)rbt(dot)ca> writes:
> % 1960 2006-05-02 17:03:19 EDTLOG: 00000: server process (PID 10171) exited with exit code 1

Hm. I wonder if there are any uses of "exit(1)" in the Slony triggers.

regards, tom lane

On Friday 05 May 2006 13:11, Tom Lane wrote:
> Rod Taylor <pg(at)rbt(dot)ca> writes:
> > % 1960 2006-05-02 17:03:19 EDTLOG: 00000: server process (PID 10171)
> > exited with exit code 1
>
> Hm. I wonder if there are any uses of "exit(1)" in the Slony triggers.

No, there are no calls to exit() in the database loaded funcs.

>
> regards, tom lane
>
> ---------------------------(end of broadcast)---------------------------
> TIP 5: don't forget to increase your free space map settings

--
Darcy Buskermolen
Wavefire Technologies Corp.

http://www.wavefire.com
ph: 250.717.0200
fx: 250.763.1759

On Fri, 2006-05-05 at 16:11 -0400, Tom Lane wrote:
> Rod Taylor <pg(at)rbt(dot)ca> writes:
> > % 1960 2006-05-02 17:03:19 EDTLOG: 00000: server process (PID 10171) exited with exit code 1
>
> Hm. I wonder if there are any uses of "exit(1)" in the Slony triggers.

It doesn't appear so. It does have this though:

Datum
_Slony_I_killBackend(PG_FUNCTION_ARGS)
{
int32 pid;
int32 signo;
text *signame;

if (!superuser())
elog(ERROR, "Slony-I: insufficient privilege for killBackend");

pid = PG_GETARG_INT32(0);
signame = PG_GETARG_TEXT_P(1);

if (VARSIZE(signame) == VARHDRSZ + 4 &&
memcmp(VARDATA(signame), "NULL", 0) == 0)
{
signo = 0;
}
else if (VARSIZE(signame) == VARHDRSZ + 4 &&
memcmp(VARDATA(signame), "TERM", 0) == 0)
{
signo = SIGTERM;
}
else
{
elog(ERROR, "Slony-I: unsupported signal");
}

if (kill(pid, signo) < 0)
PG_RETURN_INT32(-1);

PG_RETURN_INT32(0);
}

--

Rod Taylor <pg(at)rbt(dot)ca> writes:
> On Fri, 2006-05-05 at 16:11 -0400, Tom Lane wrote:
>> Hm. I wonder if there are any uses of "exit(1)" in the Slony triggers.

> It doesn't appear so. It does have this though:

Well, a SIGTERM would have resulted in a bleat in the postmaster log.
The striking thing about your log is that the backend went down without
saying a word; which would be understandable if it had crashed (eg SEGV
or kill -9) but then the postmaster would have seen some other exit
status. I'm fairly certain there are no paths in the standard backend
code that will exit(1) without any attempt to print a message. That's
why I'm wondering about add-ons.

regards, tom lane

On Fri, 2006-05-05 at 18:53 -0400, Tom Lane wrote:
> Rod Taylor <pg(at)rbt(dot)ca> writes:
> > On Fri, 2006-05-05 at 16:11 -0400, Tom Lane wrote:
> >> Hm. I wonder if there are any uses of "exit(1)" in the Slony triggers.
>
> > It doesn't appear so. It does have this though:
>
> Well, a SIGTERM would have resulted in a bleat in the postmaster log.
> The striking thing about your log is that the backend went down without
> saying a word; which would be understandable if it had crashed (eg SEGV
> or kill -9) but then the postmaster would have seen some other exit
> status. I'm fairly certain there are no paths in the standard backend
> code that will exit(1) without any attempt to print a message. That's
> why I'm wondering about add-ons.

Add-ons are slim. Slony. We don't have any C based functions and only a
few plpgsql functions in that DB.

I did trim out a ton of autovacuum log entries (it likes to log once a
minute) but I don't see anything interesting in that area nor autovac
the pid that exited.

My knowledge of signal handling is pretty basic. Any chance that
multiple SIGTERMs could have caused it to avoid the logging?

--