Horton

Thread

  1. 8.1.3 and unused files

    Rod Taylor <pg@rbt.ca> — 2006-05-05T17:53:06Z

    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@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
--

  2. Re: 8.1.3 and unused files

    Tom Lane <tgl@sss.pgh.pa.us> — 2006-05-05T18:09:29Z

    Rod Taylor <pg@rbt.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

  3. Re: 8.1.3 and unused files

    Rod Taylor <pg@rbt.ca> — 2006-05-05T18:26:04Z

    On Fri, 2006-05-05 at 14:09 -0400, Tom Lane wrote:
> Rod Taylor <pg@rbt.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;

--

  4. Re: 8.1.3 and unused files

    Tom Lane <tgl@sss.pgh.pa.us> — 2006-05-05T18:31:50Z

    Rod Taylor <pg@rbt.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

  5. Re: 8.1.3 and unused files

    Rod Taylor <pg@rbt.ca> — 2006-05-05T18:52:01Z

    On Fri, 2006-05-05 at 14:31 -0400, Tom Lane wrote:
> Rod Taylor <pg@rbt.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?


--

  6. Re: 8.1.3 and unused files

    Tom Lane <tgl@sss.pgh.pa.us> — 2006-05-05T19:10:18Z

    Rod Taylor <pg@rbt.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

  7. Re: 8.1.3 and unused files

    Rod Taylor <pg@rbt.ca> — 2006-05-05T19:58:26Z

    On Fri, 2006-05-05 at 15:10 -0400, Tom Lane wrote:
> Rod Taylor <pg@rbt.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
--

  8. Re: 8.1.3 and unused files

    Tom Lane <tgl@sss.pgh.pa.us> — 2006-05-05T20:11:44Z

    Rod Taylor <pg@rbt.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

  9. Re: 8.1.3 and unused files

    Darcy Buskermolen <darcy@wavefire.com> — 2006-05-05T21:13:35Z

    On Friday 05 May 2006 13:11, Tom Lane wrote:
> Rod Taylor <pg@rbt.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

  10. Re: 8.1.3 and unused files

    Rod Taylor <pg@rbt.ca> — 2006-05-05T22:22:41Z

    On Fri, 2006-05-05 at 16:11 -0400, Tom Lane wrote:
> Rod Taylor <pg@rbt.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);
}

--

  11. Re: 8.1.3 and unused files

    Tom Lane <tgl@sss.pgh.pa.us> — 2006-05-05T22:53:11Z

    Rod Taylor <pg@rbt.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

  12. Re: 8.1.3 and unused files

    Rod Taylor <pg@rbt.ca> — 2006-05-05T23:20:42Z

    On Fri, 2006-05-05 at 18:53 -0400, Tom Lane wrote:
> Rod Taylor <pg@rbt.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?

--