Re: [BUGS] Breakage with VACUUM ANALYSE + partitions

On 26 April 2016 at 22:32, Andres Freund <andres(at)anarazel(dot)de> wrote:
> On 2016-04-26 17:25:18 -0400, Robert Haas wrote:
>> On Mon, Apr 25, 2016 at 4:57 PM, Andres Freund <andres(at)anarazel(dot)de>
wrote:
>> > On 2016-04-25 16:29:36 -0400, Robert Haas wrote:
>> >> On Mon, Apr 25, 2016 at 2:05 PM, Andres Freund <andres(at)anarazel(dot)de>
wrote:
>> >> > Well, I posted a patch. I'd have applied it too (after addressing
your
>> >> > comments obviously), except that there's some interdependencies
with the
>> >> > nsmg > 0 thread (some of my tests fail spuriously without that
>> >> > fixed). Early last week I waited for a patch on that thread, but
when
>> >> > that didn't materialize by Friday I switched to work on that [1].
With
>> >> > both fixes applied I can't reproduce any problems anymore.
>> >>
>> >> OK. What are the interdependencies? You've said that a few times but
>> >> I am not clear on what the nature of those interdependencies is.
>> >
>> > I added checks to smgr/md.c that verify that the smgr state is
>> > consistent with the on-file state. Without the two issues in [1] fixed,
>> > these tests fail in a standby, while running regression tests. Adding
>> > those tests made me notice a bug in an unreleased version of the patch,
>> > so it seems they're worthwhile to run.
>>
>> Footnote [1] is used, but not defined.
>
> Oops, it's the thread you replied too..
>
>> I think it makes sense to go ahead and push this fix rather soon.
>
> Will do.

I've noticed another breakage, which I can reproduce consistently.

createdb pgbench
pgbench -i -s 100 --unlogged-tables pgbench
psql -f pgbench_partitions.sql pgbench
vacuumdb -z pgbench
createdb test

Which produces:

createdb: database creation failed: ERROR: checkpoint request failed
HINT: Consult recent messages in the server log for details.

The log shows:

2016-04-28 17:36:00 BST [18605]: [1-1] user=thom,db=postgres,client=[local]
DEBUG: postgres child[18605]: starting with (
2016-04-28 17:36:00 BST [18605]: [2-1] user=thom,db=postgres,client=[local]
DEBUG: postgres
2016-04-28 17:36:00 BST [18605]: [3-1] user=thom,db=postgres,client=[local]
DEBUG: )
2016-04-28 17:36:00 BST [18605]: [4-1] user=thom,db=postgres,client=[local]
DEBUG: InitPostgres
2016-04-28 17:36:00 BST [18605]: [5-1] user=thom,db=postgres,client=[local]
DEBUG: StartTransaction
2016-04-28 17:36:00 BST [18605]: [6-1] user=thom,db=postgres,client=[local]
DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR,
xid/subid/cid: 0/1/0, nest
lvl: 1, children:
2016-04-28 17:36:00 BST [18605]: [7-1] user=thom,db=postgres,client=[local]
DEBUG: CommitTransaction
2016-04-28 17:36:00 BST [18605]: [8-1] user=thom,db=postgres,client=[local]
DEBUG: name: unnamed; blockState: STARTED; state: INPROGR,
xid/subid/cid: 0/1/0, nest
lvl: 1, children:
2016-04-28 17:36:00 BST [18605]: [9-1] user=thom,db=postgres,client=[local]
DEBUG: StartTransactionCommand
2016-04-28 17:36:00 BST [18605]: [10-1]
user=thom,db=postgres,client=[local] STATEMENT: CREATE DATABASE test;
2016-04-28 17:36:00 BST [18605]: [11-1]
user=thom,db=postgres,client=[local] DEBUG: StartTransaction
2016-04-28 17:36:00 BST [18605]: [12-1]
user=thom,db=postgres,client=[local] STATEMENT: CREATE DATABASE test;
2016-04-28 17:36:00 BST [18605]: [13-1]
user=thom,db=postgres,client=[local] DEBUG: name: unnamed; blockState:
DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nes
tlvl: 1, children:
2016-04-28 17:36:00 BST [18605]: [14-1]
user=thom,db=postgres,client=[local] STATEMENT: CREATE DATABASE test;
2016-04-28 17:36:00 BST [18605]: [15-1]
user=thom,db=postgres,client=[local] DEBUG: ProcessUtility
2016-04-28 17:36:00 BST [18605]: [16-1]
user=thom,db=postgres,client=[local] STATEMENT: CREATE DATABASE test;
2016-04-28 17:36:00 BST [18108]: [46-1] user=,db=,client= DEBUG:
performing replication slot checkpoint
2016-04-28 17:36:00 BST [18105]: [158-1] user=,db=,client= DEBUG: server
process (PID 18582) exited with exit code 0
2016-04-28 17:36:08 BST [18108]: [47-1] user=,db=,client= DEBUG: could not
fsync file "base/24581/24594.1" but retrying: No such file or directory
2016-04-28 17:36:08 BST [18108]: [48-1] user=,db=,client= ERROR: could not
fsync file "base/24581/24594.1": No such file or directory
2016-04-28 17:36:08 BST [18605]: [17-1]
user=thom,db=postgres,client=[local] ERROR: checkpoint request failed
2016-04-28 17:36:08 BST [18605]: [18-1]
user=thom,db=postgres,client=[local] HINT: Consult recent messages in the
server log for details.
2016-04-28 17:36:08 BST [18605]: [19-1]
user=thom,db=postgres,client=[local] STATEMENT: CREATE DATABASE test;
2016-04-28 17:36:08 BST [18605]: [20-1]
user=thom,db=postgres,client=[local] DEBUG: shmem_exit(0): 1
before_shmem_exit callbacks to make
2016-04-28 17:36:08 BST [18605]: [21-1]
user=thom,db=postgres,client=[local] DEBUG: shmem_exit(0): 6 on_shmem_exit
callbacks to make
2016-04-28 17:36:08 BST [18605]: [22-1]
user=thom,db=postgres,client=[local] DEBUG: proc_exit(0): 3 callbacks to
make
2016-04-28 17:36:08 BST [18605]: [23-1]
user=thom,db=postgres,client=[local] DEBUG: exit(0)
2016-04-28 17:36:08 BST [18605]: [24-1]
user=thom,db=postgres,client=[local] DEBUG: shmem_exit(-1): 0
before_shmem_exit callbacks to make
2016-04-28 17:36:08 BST [18605]: [25-1]
user=thom,db=postgres,client=[local] DEBUG: shmem_exit(-1): 0
on_shmem_exit callbacks to make
2016-04-28 17:36:08 BST [18605]: [26-1]
user=thom,db=postgres,client=[local] DEBUG: proc_exit(-1): 0 callbacks to
make
2016-04-28 17:36:08 BST [18105]: [159-1] user=,db=,client= DEBUG: server
process (PID 18605) exited with exit code 0
2016-04-28 17:36:09 BST [18108]: [49-1] user=,db=,client= DEBUG:
checkpointer updated shared memory configuration values

Relfilenode 24594 corresponds to the empty pgbench_accounts parent table.

Thom