From: Christoph Ziegenberg <ziegenberg@web.de>
To: Merlin Moncure <mmoncure@gmail.com>
To: Christoph Ziegenberg <ziegenberg@web.de>
Cc: Jeff Janes <jeff.janes@gmail.com>
Cc: pgsql-bugs <pgsql-bugs@lists.postgresql.org>
Subject: Re: BUG #15967: Sequence generation using NEXTVAL() fails on 64bit systems
Date: Wed, 21 Aug 2019 07:11:16 +0200
Message-ID: <1591F404-9363-4333-AC6C-0C85795DEC2F@web.de> (raw)
In-Reply-To: <CAHyXU0wdRTs68VzvHxu7sKEfpQm8uOxtk5JLMcsHQeBf2ow3=Q@mail.gmail.com>
References: <15967-ae7fd939200f4547@postgresql.org>
<CAMkU=1w7BtrvqghRdeJ1WGeeiP5UKhMYLAXxBuKR7JaSfuYsew@mail.gmail.com>
<CAHyXU0wSQftmVD3R+GEUe8vgz=Vf8o_CSVvu0DtHwqCKvHJ2BQ@mail.gmail.com>
<6F9C0D52-A45B-4D2E-A558-F15170301C0A@web.de>
<CAHyXU0wdRTs68VzvHxu7sKEfpQm8uOxtk5JLMcsHQeBf2ow3=Q@mail.gmail.com>
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
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-bugs@postgresql.org
Cc: ziegenberg@web.de, mmoncure@gmail.com, jeff.janes@gmail.com, pgsql-bugs@lists.postgresql.org
Subject: Re: BUG #15967: Sequence generation using NEXTVAL() fails on 64bit systems
In-Reply-To: <1591F404-9363-4333-AC6C-0C85795DEC2F@web.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