Обсуждение: BUG #15967: Sequence generation using NEXTVAL() fails on 64bit systems

On Tue, Aug 20, 2019 at 9:14 AM Jeff Janes <jeff.janes@gmail.com> wrote:


 I did many tests:


 Can you include the code which implements those tests?

 I can't reproduce with something like this:

+1 this.  This would be a very embarrassing and serious problem should
it be proven to be valid.   We would however need to rule out issues
in the test code itself.  The best possible approach in terms of
verification would be a .sql only test with reproduction via pgbench
-f (IMO).

merlin

I did many tests:

 

Can you include the code which implements those tests? 

I can't reproduce with something like this:

perl -e 'use DBI; fork; fork; fork; my $dbh=DBI->connect("dbi:Pg:host=/tmp"); for (1..1e6) {my $seq = $dbh->selectrow_array("select nextval('\''foo_seq'\'')"); $dbh->do("insert into foo values (?)",undef,$seq);}'

Cheers,

Jeff

On Tue, Aug 20, 2019 at 9:56 AM Christoph Ziegenberg <ziegenberg@web.de> wrote:
New info:
We could also reproduce it with Postgres 10.10 32bit on Windows Server 2016 and 9.6.8 64bit on Ubuntu (18.x). So also the 32bit version is affected, as well as 9.x versions.

Ok, that makes sense; if we don't have arch specific reproduction I'd
say that lowers the likelihood of having a serious problem within
postgres itself (just a hunch).

Current test state:
We (2 of my colleagues and me) are currently trying to create an independent test, but at the moment it only occurrs within the specific application.

This of course is key.  Most people reading this list are going to be
suspicious of your application rather than postgres internals causing
the issue.  Having said that, let's see if we can isolate the problem.

Of course we search for an error in the application first, checked the connection settings, tracked all statements... there is nothing special, only a handful of SELECTS and UPDATES, then the sequence generation and the (sometimes failing) INSERT, and another INSERT (no sequence generate here) and UPDATE following. In all cases we tested with the Postgres default configuration.

We could see that wrapping the selection of NEXTVAL() in a transaction (which shouldn't have any effect?) reduced the problem in one case, but it was still possible to reproduce the error with an increased number of requests.

Being in a transaction makes shouldn't make any difference with
regards to behavior.

At the moment we don't have a real idea how to proceed. Next step planned is to simulate all of the aforementioned requests done by the application, because they seem to influence the behavior.

Isolating in a separate test would be proof.  Sans that, we need to be
suspicious of your test environment.  Hm, how about this: perhaps we
can tease the problem out with logging. One possible trick is to do
this:
CREATE OR REPLACE FUNCTION log_nextval(_Sequence TEXT, s OUT) RETURNS BIGINT AS
$$
BEGIN
  s := nextval(_Sequence);
  RAISE WARNING 'Got value % from %', s, _Sequence;
  RETURN s;
END;
$$ LANGUAGE PLGSQL;

Then, as an experiment, you can move all your nextval() generation to
this function (note: there will be significant performance  hit) and
attempt to reproduce the problem in your application.  If when you
did, we could then interrogate the database log to see if the same
value >1 times, this would be a smoking gun.  If you did not see the
value returned >1 times, maybe turn on full statement logging (also a
big performance hit) and see where your application might be  jacking
things up.

Background:
The application is written in PHP (different versions used in the tests, 7.2 - 7.4 I guess), runs on Apache/IIS (FastCGI) and uses the PDO extension for the communication with Postgres.

merlin

Good idea with the replacement of the nextval function. This confirms, that the problem is not an application or PHP problem.

Here an extract from the logs, showing the error:

---

2019-08-21 06:57:38.812 CEST [5824] WARNUNG:  Got value 2799 from public.e2_ws_log_login_seq
2019-08-21 06:57:38.812 CEST [5824] ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval(text) Zeile 6 bei RAISE
2019-08-21 06:57:38.872 CEST [16236] WARNUNG:  Got value 2800 from public.e2_ws_log_login_seq
2019-08-21 06:57:38.872 CEST [16236] ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval(text) Zeile 6 bei RAISE
2019-08-21 06:57:38.873 CEST [1436] WARNUNG:  Got value 2801 from public.e2_ws_log_login_seq
2019-08-21 06:57:38.873 CEST [1436] ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval(text) Zeile 6 bei RAISE
2019-08-21 06:57:38.910 CEST [12480] WARNUNG:  Got value 2801 from public.e2_ws_log_login_seq
2019-08-21 06:57:38.910 CEST [12480] ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval(text) Zeile 6 bei RAISE
2019-08-21 06:57:38.915 CEST [12480] FEHLER:  doppelter Schlüsselwert verletzt Unique-Constraint »p_e2_ws_log_login«
2019-08-21 06:57:38.915 CEST [12480] DETAIL:  Schlüssel »(log_login_id)=(2801)« existiert bereits.
2019-08-21 06:57:38.915 CEST [12480] ANWEISUNG:  INSERT INTO e2_ws_log_login (log_login_id, client_id, log_action, log_datetime, log_ip_address, log_data) VALUES ($1, $2, $3, $4, $5, $6)
2019-08-21 06:57:39.031 CEST [10672] WARNUNG:  Got value 2802 from public.e2_ws_log_login_seq
2019-08-21 06:57:39.031 CEST [10672] ZUSAMMENHANG:  PL/pgSQL-Funktion log_nextval(text) Zeile 6 bei RAISE

---

BTW: I had to change the function a little bit:

CREATE OR REPLACE FUNCTION log_nextval(_Sequence TEXT) RETURNS BIGINT AS
$$
DECLARE
    s BIGINT;
BEGIN
  s := nextval(_Sequence);
  RAISE WARNING 'Got value % from %', s, _Sequence;
  RETURN s;
END;
$$ LANGUAGE 'plpgsql';


Christoph

Am 20. August 2019 18:06:42 MESZ schrieb Merlin Moncure <mmoncure@gmail.com>:

On Tue, Aug 20, 2019 at 9:56 AM Christoph Ziegenberg <ziegenberg@web.de> wrote:
New info:
We could also reproduce it with Postgres 10.10 32bit on Windows Server 2016 and 9.6.8 64bit on Ubuntu (18.x). So also the 32bit version is affected, as well as 9.x versions.

Ok, that makes sense; if we don't have arch specific reproduction I'd
say that lowers the likelihood of having a serious problem within
postgres itself (just a hunch).

Current test state:
We (2 of my colleagues and me) are currently trying to create an independent test, but at the moment it only occurrs within the specific application.

This of course is key.  Most people reading this list are going to be
suspicious of your application rather than postgres internals causing
the issue.  Having said that, let's see if we can isolate the problem.

Of course we search for an error in the application first, checked the connection settings, tracked all statements... there is nothing special, only a handful of SELECTS and UPDATES, then the sequence generation and the (sometimes failing) INSERT, and another INSERT (no sequence generate here) and UPDATE following. In all cases we tested with the Postgres default configuration.

We could see that wrapping the selection of NEXTVAL() in a transaction (which shouldn't have any effect?) reduced the problem in one case, but it was still possible to reproduce the error with an increased number of requests.

Being in a transaction makes shouldn't make any difference with
regards to behavior.

At the moment we don't have a real idea how to proceed. Next step planned is to simulate all of the aforementioned requests done by the application, because they seem to influence the behavior.

Isolating in a separate test would be proof.  Sans that, we need to be
suspicious of your test environment.  Hm, how about this: perhaps we
can tease the problem out with logging. One possible trick is to do
this:
CREATE OR REPLACE FUNCTION log_nextval(_Sequence TEXT, s OUT) RETURNS BIGINT AS
$$
BEGIN
  s := nextval(_Sequence);
  RAISE WARNING 'Got value % from %', s, _Sequence;
  RETURN s;
END;
$$ LANGUAGE PLGSQL;

Then, as an experiment, you can move all your nextval() generation to
this function (note: there will be significant performance  hit) and
attempt to reproduce the problem in your application.  If when you
did, we could then interrogate the database log to see if the same
value >1 times, this would be a smoking gun.  If you did not see the
value returned >1 times, maybe turn on full statement logging (also a
big performance hit) and see where your application might be  jacking
things up.

Background:
The application is written in PHP (different versions used in the tests, 7.2 - 7.4 I guess), runs on Apache/IIS (FastCGI) and uses the PDO extension for the communication with Postgres.

merlin