Re: 9.2 recovery/startup problems - Mailing list pgsql-hackers
| From | Jeff Janes |
|---|---|
| Subject | Re: 9.2 recovery/startup problems |
| Date | |
| Msg-id | CAMkU=1zm8A=XS7xp6xBhMgLtBtgjxxcEw+poeSJENLmVd+B8QA@mail.gmail.com Whole thread Raw |
| In response to | 9.2 recovery/startup problems (Jeff Janes <jeff.janes@gmail.com>) |
| Responses |
Re: 9.2 recovery/startup problems
(Robert Haas <robertmhaas@gmail.com>)
|
| List | pgsql-hackers |
On Tue, Nov 25, 2014 at 9:30 PM, Jeff Janes <jeff.janes@gmail.com> wrote:
Using both 9.2.9 and 9_2_STABLE 9b468bcec15f1ea7433d4, I get a fairly reproducible startup failure.What I was doing is restore a database from a base backup and roll it forward with a recovery.conf until it completes and starts up. Then I truncate an unlogged table and start repopulating it with a large slow 'insert into ...select from' query.While that is running, if I reboot the server, when it restarts it does not come back up initially.This is what I get in the log from the attempted restart:PST LOG: database system was interrupted; last known up at 2014-11-25 15:40:33 PSTPST LOG: database system was not properly shut down; automatic recovery in progressPST LOG: redo starts at 84/EF000080PST LOG: record with zero length at 84/EF09AE18PST LOG: redo done at 84/EF09AD28PST LOG: last completed transaction was at log time 2014-11-25 15:42:09.173599-08PST LOG: checkpoint starting: end-of-recovery immediatePST LOG: checkpoint complete: wrote 103 buffers (0.2%); 0 transaction log file(s) added, 246 removed, 7 recycled; write=0.002 s, sync=0.020 s, total=0.526 s; sync files=51, longest=0.003 s, average=0.000 sPST FATAL: could not create file "base/16416/59288": File existsPST LOG: startup process (PID 2472) exited with exit code 1PST LOG: aborting startup due to startup process failureoid2name doesn't show me any 59288, so I think it is the new copy of the unlogged table which is being created at the moment of the reboot.
59288 is not the new (uncommitted) unlogged table itself, but is the new (uncommitted) toast table associated with that unlogged table.
immediately before the 'sudo /sbin/reboot', while the 'truncate unlogged_table; insert into unlogged_table from select...' is running, the two files below exist and have zero size.
base/16416/59288_init
base/16416/59288
Immediately after the system has come back up, the file base/16416/59288_init no longer exists.
I can't reproduce this behavior without the reboot. It seems to depend on the sequencing and timing of the signals which the kernel delivers to the running processes during the reboot.
If I do a pg_ctl stop -mf, then both files go away. If I do a pg_ctl stop -mi, then neither goes away. It is only with the /sbin/reboot that I get the fatal combination of _init being gone but the other still present.
Then once the system is back and I restart postmaster, the first pass through ResetUnloggedRelationsInDbspaceDir doesn't remove base/16416/59288, because base/16416/59288_init doesn't exist to trigger the deletion. On the 2nd pass through, base/16416/59288_init exists because it was created by WAL replay, and the copy fails because it is expecting base/16416/59288 to have already been cleaned up by the first pass.
Should ResetUnloggedRelationsInDbspaceDir on the second pass attempt to unlink the target immediately before the copy (line 338, in 9.2) to accommodate cases like this?
Cheers,
Jeff
pgsql-hackers by date: