Thread: BUG #8059: sequence crash recovery is not working properly
The following bug has been logged on the website:
Bug reference: 8059
Logged by: Tarvi Pillessaar
Email address: tarvip@gmail.com
PostgreSQL version: 9.2.4
Operating system: linux
Description: =
Very simple example:
postgres@sbox /usr/local/pgsql $ /usr/local/pgsql/bin/psql test
psql (9.2.4)
Type "help" for help.
test=3D# create sequence s;
CREATE SEQUENCE
test=3D# begin;
BEGIN
test=3D# select nextval('s');
nextval =
---------
1
(1 row)
Now let's crash the cluster:
postgres@sbox /usr/local/pgsql $ pgrep -lf writer
13638 postgres: writer process
13639 postgres: wal writer process
postgres@sbox /usr/local/pgsql $ kill -9 13638
postgres@sbox /usr/local/pgsql $ tail logfile =
HINT: In a moment you should be able to reconnect to the database and
repeat your command.
LOG: all server processes terminated; reinitializing
LOG: database system was interrupted; last known up at 2013-04-12 14:28:26
EEST
LOG: database system was not properly shut down; automatic recovery in
progress
LOG: redo starts at 0/177C9E0
LOG: record with zero length at 0/1791888
LOG: redo done at 0/1791858
LOG: last completed transaction was at log time 2013-04-12
14:29:48.562356+03
LOG: database system is ready to accept connections
LOG: autovacuum launcher started
postgres@sbox /usr/local/pgsql $ =
test=3D# select nextval('s');
WARNING: terminating connection because of crash of another server process
DETAIL: The postmaster has commanded this server process to roll back the
current transaction and exit, because another server process exited
abnormally and possibly corrupted shared memory.
HINT: In a moment you should be able to reconnect to the database and
repeat your command.
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
The connection to the server was lost. Attempting reset: Succeeded.
test=3D# select nextval('s');
nextval =
---------
1
(1 row)
test=3D# =
This problem occurs on the same conditions as described in commit
af026b5d9b8ae6ef4c75a796bdac209df6411181.
For another example i'm going to use very simple python script:
import psycopg2
cur =3D psycopg2.connect('dbname=3Dtest host=3D/tmp/').cursor()
while True:
try:
cur.execute("select nextval('s')")
val=3Dcur.fetchone()[0]
except Exception, e:
print "%s\n%s" % (val,e)
break
This script consumes a lot of values from sequence 's' within a single
transaction, when crash occurs it prints out last value that the script got
from database.
postgres@sbox /usr/local/pgsql $ python test.py =
132119
server closed the connection unexpectedly
This probably means the server terminated abnormally
before or while processing the request.
postgres@sbox /usr/local/pgsql $ /usr/local/pgsql/bin/psql test
psql (9.2.4)
Type "help" for help.
test=3D# select nextval('s');
nextval =
---------
130501
(1 row)
test=3D#
On 2013-04-12 12:27:01 +0000, tarvip@gmail.com wrote:
> The following bug has been logged on the website:
>
> Bug reference: 8059
> Logged by: Tarvi Pillessaar
> Email address: tarvip@gmail.com
> PostgreSQL version: 9.2.4
> Operating system: linux
> Description:
>
> Very simple example:
>
> postgres@sbox /usr/local/pgsql $ /usr/local/pgsql/bin/psql test
> psql (9.2.4)
> Type "help" for help.
>
> test=# create sequence s;
> CREATE SEQUENCE
> test=# begin;
> BEGIN
> test=# select nextval('s');
> nextval
> ---------
> 1
> (1 row)
>
>
> Now let's crash the cluster:
>
> postgres@sbox /usr/local/pgsql $ pgrep -lf writer
> 13638 postgres: writer process
> 13639 postgres: wal writer process
> postgres@sbox /usr/local/pgsql $ kill -9 13638
> postgres@sbox /usr/local/pgsql $ tail logfile
> HINT: In a moment you should be able to reconnect to the database and
> repeat your command.
> LOG: all server processes terminated; reinitializing
> LOG: database system was interrupted; last known up at 2013-04-12 14:28:26
> EEST
> LOG: database system was not properly shut down; automatic recovery in
> progress
> LOG: redo starts at 0/177C9E0
> LOG: record with zero length at 0/1791888
> LOG: redo done at 0/1791858
> LOG: last completed transaction was at log time 2013-04-12
> 14:29:48.562356+03
> LOG: database system is ready to accept connections
> LOG: autovacuum launcher started
> postgres@sbox /usr/local/pgsql $
Thats caused by the fact that you didn't do anything that forces a WAL
flush since you didn't do any inserts or such. If you would do any
DML in the nextval() calling transaction this shouldn't happen (unless
you use synchronous_commit=off).
Now, there's a legitimate argument to be made that returning the
sequence value to the user kinda persists it. On the other hand, at
least in the first example you haven't even committed the transaction so
there's nothing that could flush the transaction unless we we would
*always* flush nextval() immediately if needs to get new values which
doesn't seem reasonable.
I think a reasonable compromise would be that nextval_internal()
acquires a real xid (by calling GetTopTransactionId()). In that case the
commit would force a WAL flush but there are no forced wal flushes ones
inside the transaction. And it would support async commits.
Greetings,
Andres Freund
--
Andres Freund http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Training & Services
Andres Freund <andres@2ndquadrant.com> writes:
> Thats caused by the fact that you didn't do anything that forces a WAL
> flush since you didn't do any inserts or such. If you would do any
> DML in the nextval() calling transaction this shouldn't happen (unless
> you use synchronous_commit=off).
> Now, there's a legitimate argument to be made that returning the
> sequence value to the user kinda persists it. On the other hand, at
> least in the first example you haven't even committed the transaction so
> there's nothing that could flush the transaction unless we we would
> *always* flush nextval() immediately if needs to get new values which
> doesn't seem reasonable.
I believe we've gone around on this before and decided to leave it
as-is. The thinking is that any realistic use-case would involve
storing the nextval result into some table somewhere, so that additional
WAL and a commit record would be generated.
regards, tom lane
On 2013-04-12 10:47:52 -0400, Tom Lane wrote: > Andres Freund <andres@2ndquadrant.com> writes: > > Thats caused by the fact that you didn't do anything that forces a WAL > > flush since you didn't do any inserts or such. If you would do any > > DML in the nextval() calling transaction this shouldn't happen (unless > > you use synchronous_commit=off). > > Now, there's a legitimate argument to be made that returning the > > sequence value to the user kinda persists it. On the other hand, at > > least in the first example you haven't even committed the transaction so > > there's nothing that could flush the transaction unless we we would > > *always* flush nextval() immediately if needs to get new values which > > doesn't seem reasonable. > > I believe we've gone around on this before and decided to leave it > as-is. The thinking is that any realistic use-case would involve > storing the nextval result into some table somewhere, so that additional > WAL and a commit record would be generated. Hm. I couldn't find anything about that discussions after searching some minutes. I am not really sure if I can follow that argument, its not uncommon to use the database sequences to prepare data thats then inserted lateron. In a separate transaction and possibly even in a separate connection. In the latter case you wouldn't even notice the database has restarted. I don't think flushing the WAL immediately in nextval_internal is a realistic thing to do, but making it generate an xid if its doing WAL logging sounds like a compromise with acceptable overhead. In the normal usage where you use to directly insert it won't have any additional overhead since the xid will have to be generated anyway and if you use it in a separate transaction/connection you want the flush at commit. Sure, if somebody loops around SELECT nextval(...); without using a transaction that will increase the overhead, but that doesn't sound like a terribly good idea anyway. On a tangent: I'd still really like to have nextval(..., how_many_values) or such... Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services
On 12.04.2013 17:04, Andres Freund wrote: > On the other hand, at > least in the first example you haven't even committed the transaction so > there's nothing that could flush the transaction unless we we would > *always* flush nextval() immediately if needs to get new values which > doesn't seem reasonable. Yes, i know that i haven't commited anything and also i agree that flushing always is not reasonable. I'm not sure that i understand all the details in sequence.c, but there seems to be some sort of cache used for sequences, so instead of flushing always maybe flush should only happen if next batch of values are written to cache. Regards, Tarvi Pillessaar
On 2013-04-12 20:02:07 +0300, Tarvi Pillessaar wrote: > On 12.04.2013 17:04, Andres Freund wrote: > >On the other hand, at > >least in the first example you haven't even committed the transaction so > >there's nothing that could flush the transaction unless we we would > >*always* flush nextval() immediately if needs to get new values which > >doesn't seem reasonable. > Yes, i know that i haven't commited anything and also i agree that flushing > always is not reasonable. > I'm not sure that i understand all the details in sequence.c, but there > seems to be some sort of cache used for sequences, so instead of flushing > always maybe flush should only happen if next batch of values are written to > cache. Flushing everytime the cache is used up will have a far too high overhead. Consider bulk loading new data into a table. If we would flush wal every 32 new rows that would be disastrous from a performance perspective. Greetings, Andres Freund -- Andres Freund http://www.2ndQuadrant.com/ PostgreSQL Development, 24x7 Support, Training & Services