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@sss.pgh.pa.us>
> >To: Andres Freund <andres@2ndquadrant.com>
> >Cc: math@sai.msu.ru, pgsql-hackers@postgreSQL.org,
> >   Andrew Dunstan <andrew@dunslane.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