From: Andres Freund <andres@anarazel.de>
To: Martijn van Oosterhout <kleptog@svana.org>
Cc: PostgreSQL-development <pgsql-hackers@postgresql.org>
Subject: Re: WAL logging problem in 9.4.3?
Date: Fri, 3 Jul 2015 00:21:02 +0200
Message-ID: <20150702222102.GG30708@awork2.anarazel.de> (raw)
In-Reply-To: <20150702220524.GA9392@svana.org>
References: <20150702220524.GA9392@svana.org>
List-Unsubscribe: <mailto:majordomo@postgresql.org?body=unsub%20pgsql-hackers>
Hi,
On 2015-07-03 00:05:24 +0200, Martijn van Oosterhout wrote:
> === Start with an empty database
My guess is you have wal_level = minimal?
> ctmp=# begin;
> BEGIN
> ctmp=# create table test(id serial primary key);
> CREATE TABLE
> ctmp=# truncate table test;
> TRUNCATE TABLE
> ctmp=# commit;
> COMMIT
> ctmp=# select relname, relfilenode from pg_class where relname like 'test%';
> relname | relfilenode
> -------------+-------------
> test | 16389
> test_id_seq | 16387
> test_pkey | 16393
> (3 rows)
>
> === Note the index file is 8KB.
> === At this point nuke the database server (in this case it was simply
> === destroying the container it was running in.
How did you continue from there? The container has persistent storage?
Or are you repapplying the WAL to somewhere else?
> === Dump the xlogs just to show what got recorded. Note there's a
> === truncate for the data file and the index file.
That should be ok.
> martijn@martijn-jessie:$ sudo /usr/lib/postgresql/9.4/bin/pg_xlogdump -p /data/postgres/pg_xlog/ 000000010000000000000001 |grep -wE '16389|16387|16393'
> rmgr: XLOG len (rec/tot): 72/ 104, tx: 0, lsn: 0/016A9240, prev 0/016A9200, bkp: 0000, desc: checkpoint: redo 0/16A9240; tli 1; prev tli 1; fpw true; xid 0/686; oid 16387; multi 1; offset 0; oldest xid 673 in DB 1; oldest multi 1 in DB 1; oldest running xid 0; shutdown
> rmgr: Storage len (rec/tot): 16/ 48, tx: 0, lsn: 0/016A92D0, prev 0/016A92A8, bkp: 0000, desc: file create: base/16385/16387
> rmgr: Sequence len (rec/tot): 158/ 190, tx: 686, lsn: 0/016B5E50, prev 0/016B5D88, bkp: 0000, desc: log: rel 1663/16385/16387
> rmgr: Storage len (rec/tot): 16/ 48, tx: 686, lsn: 0/016B5F10, prev 0/016B5E50, bkp: 0000, desc: file create: base/16385/16389
> rmgr: Storage len (rec/tot): 16/ 48, tx: 686, lsn: 0/016BB028, prev 0/016BAFD8, bkp: 0000, desc: file create: base/16385/16393
> rmgr: Sequence len (rec/tot): 158/ 190, tx: 686, lsn: 0/016BE4F8, prev 0/016BE440, bkp: 0000, desc: log: rel 1663/16385/16387
> rmgr: Storage len (rec/tot): 16/ 48, tx: 686, lsn: 0/016BE6B0, prev 0/016BE660, bkp: 0000, desc: file truncate: base/16385/16389 to 0 blocks
> rmgr: Storage len (rec/tot): 16/ 48, tx: 686, lsn: 0/016BE6E0, prev 0/016BE6B0, bkp: 0000, desc: file truncate: base/16385/16393 to 0 blocks
> pg_xlogdump: FATAL: error in WAL record at 0/16BE710: record with zero length at 0/16BE740
Note that the truncate will lead to a new, different, relfilenode.
> === Start the DB up again
>
> database_1 | LOG: database system was interrupted; last known up at 2015-07-02 21:08:05 UTC
> database_1 | LOG: database system was not properly shut down; automatic recovery in progress
> database_1 | LOG: redo starts at 0/16A92A8
> database_1 | LOG: record with zero length at 0/16BE740
> database_1 | LOG: redo done at 0/16BE710
> database_1 | LOG: last completed transaction was at log time 2015-07-02 21:34:45.664989+00
> database_1 | LOG: database system is ready to accept connections
> database_1 | LOG: autovacuum launcher started
>
> === Oops, the index file is empty now
That's probably just the old index file?
> martijn@martijn-jessie:$ sudo ls -l /data/postgres/base/16385/{16389,16387,16393}
> -rw------- 1 messagebus ssl-cert 8192 Jul 2 23:37 /data/postgres/base/16385/16387
> -rw------- 1 messagebus ssl-cert 0 Jul 2 23:34 /data/postgres/base/16385/16389
> -rw------- 1 messagebus ssl-cert 0 Jul 2 23:37 /data/postgres/base/16385/16393
>
> martijn@martijn-jessie:$ psql ctmp -h localhost -U username
> Password for user username:
> psql (9.4.3)
> Type "help" for help.
>
> === And now the index is broken. I think the only reason it doesn't
> === complain about the data file is because zero bytes there is OK. But if
> === the table had data before it would be gone now.
>
> ctmp=# select * from test;
> ERROR: could not read block 0 in file "base/16385/16393": read only 0 of 8192 bytes
Hm. I can't reproduce this. Can you include a bit more details about how
to reproduce?
Greetings,
Andres Freund
--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Reply to all the recipients using the --to and --cc options:
reply via email
To: pgsql-hackers@postgresql.org
Cc: andres@anarazel.de, kleptog@svana.org
Subject: Re: WAL logging problem in 9.4.3?
In-Reply-To: <20150702222102.GG30708@awork2.anarazel.de>
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
This inbox is served by DDX for PostgreSQL; see mirroring instructions
for how to clone and mirror all data and code used for this inbox