Re: BUG #15967: Sequence generation using NEXTVAL() fails on 64bit systems

From: Christoph Ziegenberg <ziegenberg(at)web(dot)de>
To: Merlin Moncure <mmoncure(at)gmail(dot)com>,Christoph Ziegenberg <ziegenberg(at)web(dot)de>
Cc: Jeff Janes <jeff(dot)janes(at)gmail(dot)com>,pgsql-bugs <pgsql-bugs(at)lists(dot)postgresql(dot)org>
Subject: Re: BUG #15967: Sequence generation using NEXTVAL() fails on 64bit systems
Date: 2019-08-21 05:11:16
Message-ID: 1591F404-9363-4333-AC6C-0C85795DEC2F@web.de
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-bugs

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(at)gmail(dot)com>:
>On Tue, Aug 20, 2019 at 9:56 AM Christoph Ziegenberg
><ziegenberg(at)web(dot)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

In response to

Responses

Browse pgsql-bugs by date

  From Date Subject
Next Message Petar Masev 2019-08-21 06:25:48 RE: Postgres 11.5.1 failed installation
Previous Message Alvaro Herrera 2019-08-21 02:40:05 Re: BUG #15964: vacuumdb.c:187:10: error: use of undeclared identifier 'FD_SETSIZE'