Re: Curious buildfarm failures (fwd)

On 2013-01-15 17:27:50 +0000, Sergey Koposov wrote:
> Hi,
>
> >Date: Tue, 15 Jan 2013 11:57:07 -0500
> >From: Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
> >To: Andres Freund <andres(at)2ndquadrant(dot)com>
> >Cc: math(at)sai(dot)msu(dot)ru, pgsql-hackers(at)postgreSQL(dot)org,
> > Andrew Dunstan <andrew(at)dunslane(dot)net>
> >Subject: Re: Curious buildfarm failures
> >
> >Well, it could be quite reproducible, if for example what's happening is
> >that the DROP is failing to wait for the checkpointer at all.
> >
> >Is there a way to enable log_checkpoints during a buildfarm run?
> >It'd be good to get timestamps added to the postmaster log entries, too.
>
> Here is the log output from the failing pg_regress after enabling checkpoints and timestamps:
>
> 2013-01-15 21:20:19 MSK [50f58fd3.589e:1] LOG: database system was shut down at 2013-01-15 21:20:19 MS
> K
> 2013-01-15 21:20:19 MSK [50f58fd3.58a2:1] LOG: autovacuum launcher started
> 2013-01-15 21:20:19 MSK [50f58fd3.5899:1] LOG: database system is ready to accept connections
> 2013-01-15 21:20:20 MSK [50f58fd3.589f:1] LOG: checkpoint starting: immediate force wait
> 2013-01-15 21:20:21 MSK [50f58fd3.589f:2] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 transact
> ion log file(s) added, 0 removed, 0 recycled; write=0.604 s, sync=0.000 s, total=0.605 s; sync files=0,
> longest=0.000 s, average=0.000 s
> 2013-01-15 21:20:21 MSK [50f58fd3.589f:3] LOG: checkpoint starting: immediate force wait
> 2013-01-15 21:20:21 MSK [50f58fd3.589f:4] LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transact
> ion log file(s) added, 0 removed, 0 recycled; write=0.000 s, sync=0.000 s, total=0.000 s; sync files=0,
> longest=0.000 s, average=0.000 s
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:1] ERROR: unrecognized parameter "some_nonexistent_parameter"
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:2] STATEMENT: ALTER TABLESPACE testspace SET (some_nonexistent_
> parameter = true);
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:3] ERROR: RESET must not include values for parameters
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:4] STATEMENT: ALTER TABLESPACE testspace RESET (random_page_cos
> t = 2.0);
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:5] ERROR: duplicate key value violates unique constraint "anind
> ex"
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:6] DETAIL: Key (column1)=(1) already exists.
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:7] STATEMENT: INSERT INTO testschema.atable VALUES(1);
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:8] ERROR: directory "/no/such/location" does not exist
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:9] STATEMENT: CREATE TABLESPACE badspace LOCATION '/no/such/loc
> ation';
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:10] ERROR: tablespace "nosuchspace" does not exist
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:11] STATEMENT: CREATE TABLE bar (i int) TABLESPACE nosuchspace;
> 2013-01-15 21:20:21 MSK [50f58fd3.589f:5] LOG: checkpoint starting: immediate force wait
> 2013-01-15 21:20:21 MSK [50f58fd3.589f:6] LOG: checkpoint complete: wrote 37 buffers (0.2%); 0 transac
> tion log file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.000 s, total=0.001 s; sync files=0
> , longest=0.000 s, average=0.000 s
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:12] ERROR: tablespace "testspace" is not empty
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:13] STATEMENT: DROP TABLESPACE testspace;
> 2013-01-15 21:20:21 MSK [50f58fd3.589f:7] LOG: checkpoint starting: immediate force wait
> 2013-01-15 21:20:21 MSK [50f58fd3.589f:8] LOG: checkpoint complete: wrote 9 buffers (0.1%); 0 transact
> ion log file(s) added, 0 removed, 0 recycled; write=0.001 s, sync=0.000 s, total=0.001 s; sync files=0,
> longest=0.000 s, average=0.000 s
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:14] ERROR: tablespace "testspace" is not empty
> 2013-01-15 21:20:21 MSK [50f58fd5.58ac:15] STATEMENT: DROP TABLESPACE testspace;
>
>
> And I do see the tblspc file left after the finish of "make check":
> tmp_check/data/pg_tblspc/16385/PG_9.3_201212081/16384/16387
>
> Cheers,
> S
>
> PS I wouldn't be surprised that it is a compiler bug though. But I did see
> the failure with newer icc as well.

Any chance you could run make check again but with log_statement=all and
log_min_messages=debug2? That might tell us a bit more, whether the
dependency code doesn't work right or whether the checkpoint is doing
strange things.

Thannks,

Andres Freund

--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services