Re: Curious buildfarm failures (fwd)

From: Sergey Koposov <koposov(at)ast(dot)cam(dot)ac(dot)uk>
To: Andres Freund <andres(at)2ndquadrant(dot)com>
Cc: pgsql-hackers(at)postgreSQL(dot)org, Andrew Dunstan <andrew(at)dunslane(dot)net>, Tom Lane <tgl(at)sss(dot)pgh(dot)pa(dot)us>
Subject: Re: Curious buildfarm failures (fwd)
Date: 2013-01-15 19:09:27
Message-ID: alpine.LRH.2.03.1301151908390.773@ast.cam.ac.uk
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-hackers

On Tue, 15 Jan 2013, Andres Freund wrote:
> 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.

Here it is :

2013-01-15 23:06:18 MSK [50f5a8aa.1162:1] DEBUG: SlruScanDirectory invoking callback on pg_notify/0000
2013-01-15 23:06:18 MSK [50f5a8aa.1162:2] DEBUG: removing file "pg_notify/0000"
2013-01-15 23:06:18 MSK [50f5a8aa.1162:3] DEBUG: max_safe_fds = 985, usable_fds = 1000, already_open = 5
2013-01-15 23:06:18 MSK [50f5a8aa.1167:1] LOG: database system was shut down at 2013-01-15 23:06:18 MSK
2013-01-15 23:06:18 MSK [50f5a8aa.1167:2] DEBUG: checkpoint record is at 0/17700E0
2013-01-15 23:06:18 MSK [50f5a8aa.1167:3] DEBUG: redo record is at 0/17700E0; shutdown TRUE
2013-01-15 23:06:18 MSK [50f5a8aa.1167:4] DEBUG: next transaction ID: 0/686; next OID: 12031
2013-01-15 23:06:18 MSK [50f5a8aa.1167:5] DEBUG: next MultiXactId: 1; next MultiXactOffset: 0
2013-01-15 23:06:18 MSK [50f5a8aa.1167:6] DEBUG: oldest unfrozen transaction ID: 676, in database 1
2013-01-15 23:06:18 MSK [50f5a8aa.1167:7] DEBUG: transaction ID wrap limit is 2147484323, limited by database with OID 1
2013-01-15 23:06:18 MSK [50f5a8aa.1168:1] DEBUG: checkpointer updated shared memory configuration values
2013-01-15 23:06:18 MSK [50f5a8aa.116b:1] LOG: autovacuum launcher started
2013-01-15 23:06:18 MSK [50f5a8aa.1162:4] LOG: database system is ready to accept connections
2013-01-15 23:06:19 MSK [50f5a8aa.1162:5] DEBUG: forked new backend, pid=4463 socket=8
2013-01-15 23:06:19 MSK [50f5a8aa.1162:6] DEBUG: server process (PID 4463) exited with exit code 0
2013-01-15 23:06:19 MSK [50f5a8aa.1162:7] DEBUG: forked new backend, pid=4465 socket=8
2013-01-15 23:06:19 MSK [50f5a8ab.1171:1] LOG: statement: CREATE DATABASE "regression" TEMPLATE=template0
2013-01-15 23:06:19 MSK [50f5a8aa.1168:2] LOG: checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:3] DEBUG: SlruScanDirectory invoking callback on pg_multixact/offsets/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:4] DEBUG: SlruScanDirectory invoking callback on pg_multixact/members/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:5] DEBUG: attempting to remove WAL segments older than log file 000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:6] DEBUG: SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:7] LOG: checkpoint complete: wrote 3 buffers (0.0%); 0 transaction 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 23:06:19 MSK [50f5a8aa.1168:8] LOG: checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:9] DEBUG: attempting to remove WAL segments older than log file 000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:10] DEBUG: SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:11] LOG: checkpoint complete: wrote 0 buffers (0.0%); 0 transaction 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 23:06:19 MSK [50f5a8aa.1162:8] DEBUG: server process (PID 4465) exited with exit code 0
2013-01-15 23:06:19 MSK [50f5a8aa.1162:9] DEBUG: forked new backend, pid=4467 socket=8
2013-01-15 23:06:19 MSK [50f5a8ab.1173:1] LOG: statement: ALTER DATABASE "regression" SET lc_messages TO 'C';ALTER DATABASE "regression" SET lc_monetary TO 'C';ALTER DATABASE "regression" SET lc_numeric TO 'C';ALTER DATABASE "regression" SET lc_time TO 'C';ALTER DATABASE "regression" SET timezone_abbreviations TO 'Default';
2013-01-15 23:06:19 MSK [50f5a8aa.1162:10] DEBUG: server process (PID 4467) exited with exit code 0
2013-01-15 23:06:19 MSK [50f5a8aa.1162:11] DEBUG: forked new backend, pid=4469 socket=8
2013-01-15 23:06:19 MSK [50f5a8ab.1175:1] LOG: statement: CREATE TABLESPACE testspace LOCATION '/home/math/pg_git/src/test/regress/testtablespace';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:2] LOG: statement: ALTER TABLESPACE testspace SET (random_page_cost = 1.0);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:3] LOG: statement: ALTER TABLESPACE testspace SET (some_nonexistent_parameter = true);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:4] ERROR: unrecognized parameter "some_nonexistent_parameter"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:5] STATEMENT: ALTER TABLESPACE testspace SET (some_nonexistent_parameter = true);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:6] LOG: statement: ALTER TABLESPACE testspace RESET (random_page_cost = 2.0);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:7] ERROR: RESET must not include values for parameters
2013-01-15 23:06:19 MSK [50f5a8ab.1175:8] STATEMENT: ALTER TABLESPACE testspace RESET (random_page_cost = 2.0);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:9] LOG: statement: ALTER TABLESPACE testspace RESET (random_page_cost, seq_page_cost);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:10] LOG: statement: CREATE SCHEMA testschema;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:11] LOG: statement: CREATE TABLE testschema.foo (i int) TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:12] LOG: statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t, pg_catalog.pg_class c
where c.reltablespace = t.oid AND c.relname = 'foo';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:13] LOG: statement: INSERT INTO testschema.foo VALUES(1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:14] LOG: statement: INSERT INTO testschema.foo VALUES(2);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:15] LOG: statement: CREATE TABLE testschema.asselect TABLESPACE testspace AS SELECT 1;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:16] LOG: statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t, pg_catalog.pg_class c
where c.reltablespace = t.oid AND c.relname = 'asselect';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:17] LOG: statement: PREPARE selectsource(int) AS SELECT $1;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:18] LOG: statement: CREATE TABLE testschema.asexecute TABLESPACE testspace
AS EXECUTE selectsource(2);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:19] LOG: statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t, pg_catalog.pg_class c
where c.reltablespace = t.oid AND c.relname = 'asexecute';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:20] LOG: statement: CREATE INDEX foo_idx on testschema.foo(i) TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:21] DEBUG: building index "foo_idx" on table "foo"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:22] LOG: statement: SELECT relname, spcname FROM pg_catalog.pg_tablespace t, pg_catalog.pg_class c
where c.reltablespace = t.oid AND c.relname = 'foo_idx';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:23] LOG: statement: CREATE TABLE testschema.atable AS VALUES (1), (2);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:24] LOG: statement: CREATE UNIQUE INDEX anindex ON testschema.atable(column1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:25] DEBUG: building index "anindex" on table "atable"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:26] LOG: statement: ALTER TABLE testschema.atable SET TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:27] LOG: statement: ALTER INDEX testschema.anindex SET TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:28] LOG: statement: INSERT INTO testschema.atable VALUES(3);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:29] LOG: statement: INSERT INTO testschema.atable VALUES(1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:30] ERROR: duplicate key value violates unique constraint "anindex"
2013-01-15 23:06:19 MSK [50f5a8ab.1175:31] DETAIL: Key (column1)=(1) already exists.
2013-01-15 23:06:19 MSK [50f5a8ab.1175:32] STATEMENT: INSERT INTO testschema.atable VALUES(1);
2013-01-15 23:06:19 MSK [50f5a8ab.1175:33] LOG: statement: SELECT COUNT(*) FROM testschema.atable;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:34] LOG: statement: CREATE TABLESPACE badspace LOCATION '/no/such/location';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:35] ERROR: directory "/no/such/location" does not exist
2013-01-15 23:06:19 MSK [50f5a8ab.1175:36] STATEMENT: CREATE TABLESPACE badspace LOCATION '/no/such/location';
2013-01-15 23:06:19 MSK [50f5a8ab.1175:37] LOG: statement: CREATE TABLE bar (i int) TABLESPACE nosuchspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:38] ERROR: tablespace "nosuchspace" does not exist
2013-01-15 23:06:19 MSK [50f5a8ab.1175:39] STATEMENT: CREATE TABLE bar (i int) TABLESPACE nosuchspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:40] LOG: statement: DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8aa.1168:12] LOG: checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:13] DEBUG: attempting to remove WAL segments older than log file 000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:14] DEBUG: SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:15] LOG: checkpoint complete: wrote 37 buffers (0.2%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=0.000 s, sync=0.000 s, total=0.001 s; sync files=0, longest=0.000 s, average=0.000 s
2013-01-15 23:06:19 MSK [50f5a8ab.1175:41] ERROR: tablespace "testspace" is not empty
2013-01-15 23:06:19 MSK [50f5a8ab.1175:42] STATEMENT: DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:43] LOG: statement: DROP SCHEMA testschema CASCADE;
2013-01-15 23:06:19 MSK [50f5a8ab.1175:44] DEBUG: drop auto-cascades to index testschema.foo_idx
2013-01-15 23:06:19 MSK [50f5a8ab.1175:45] DEBUG: drop auto-cascades to type testschema.foo
2013-01-15 23:06:19 MSK [50f5a8ab.1175:46] DEBUG: drop auto-cascades to type testschema.foo[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:47] DEBUG: drop auto-cascades to type testschema.asselect
2013-01-15 23:06:19 MSK [50f5a8ab.1175:48] DEBUG: drop auto-cascades to type testschema.asselect[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:49] DEBUG: drop auto-cascades to type testschema.asexecute
2013-01-15 23:06:19 MSK [50f5a8ab.1175:50] DEBUG: drop auto-cascades to type testschema.asexecute[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:51] DEBUG: drop auto-cascades to index testschema.anindex
2013-01-15 23:06:19 MSK [50f5a8ab.1175:52] DEBUG: drop auto-cascades to type testschema.atable
2013-01-15 23:06:19 MSK [50f5a8ab.1175:53] DEBUG: drop auto-cascades to type testschema.atable[]
2013-01-15 23:06:19 MSK [50f5a8ab.1175:54] NOTICE: drop cascades to 4 other objects
2013-01-15 23:06:19 MSK [50f5a8ab.1175:55] DETAIL: drop cascades to table testschema.foo
drop cascades to table testschema.asselect
drop cascades to table testschema.asexecute
drop cascades to table testschema.atable
2013-01-15 23:06:19 MSK [50f5a8ab.1175:56] LOG: statement: DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8aa.1168:16] LOG: checkpoint starting: immediate force wait
2013-01-15 23:06:19 MSK [50f5a8aa.1168:17] DEBUG: attempting to remove WAL segments older than log file 000000000000000000000000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:18] DEBUG: SlruScanDirectory invoking callback on pg_subtrans/0000
2013-01-15 23:06:19 MSK [50f5a8aa.1168:19] LOG: checkpoint complete: wrote 9 buffers (0.1%); 0 transaction 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 23:06:19 MSK [50f5a8ab.1175:57] ERROR: tablespace "testspace" is not empty
2013-01-15 23:06:19 MSK [50f5a8ab.1175:58] STATEMENT: DROP TABLESPACE testspace;
2013-01-15 23:06:19 MSK [50f5a8aa.1162:12] DEBUG: server process (PID 4469) exited with exit code 0

Cheers,
S
*****************************************************
Sergey E. Koposov, PhD, Research Associate
Institute of Astronomy, University of Cambridge
Madingley road, CB3 0HA, Cambridge, UK
Tel: +44-1223-337-551 Web: http://www.ast.cam.ac.uk/~koposov/

In response to

Browse pgsql-hackers by date

  From Date Subject
Next Message Bruce Momjian 2013-01-15 19:11:23 Re: buffer assertion tripping under repeat pgbench load
Previous Message Andres Freund 2013-01-15 19:07:37 Re: unlogged tables vs. GIST