On 9/16/19 1:46 PM, Jeff Ross wrote:
Hi all,
I've been debugging an intermittent foreign key insert error on our
single database / multi-tenant server. To help isolate traffic by
tenant, I've switched to using csvlog and for the duration and have set
log_min_duration_statement to 0 to get *everything*. Fortunately, daily
80G csvlogs compress nicely.
For lack of a readable way to paste in the 12 lines of relevant csvlog
into an e-mail, I've uploaded a very small 3K csv file to my web server at
https://openvistas.net/hansens_error.csv
The bare bones of the issue involve inserting a row into a table named
load_det, then getting the serial sequence of that table, getting the
last_value of that sequence and then inserting into another table named
cargo_det using that retrieved last_value as the foreign key that ties
this row to the load_det table. The vast majority of these succeed
without issue but not all.
The csvlog snip shows what I believe are 2 simultaneous but separate
sessions and the session that attempts to insert into the cargo_det
table is not the same session that inserted into the load_det table.
That's what my hunch is but what is unclear to me is if those separate
sessions are also in separate transactions.
To me it looks like the INSERT into load_det and into cargo_det are
occurring in the same transaction(934281062). The part that would
concern me is that:
select last_value from load_det_id_seq
occurs in different transactions and sessions. From here:
https://www.postgresql.org/docs/11/sql-createsequence.html
"Also, last_value will reflect the latest value reserved by any session,
whether or not it has yet been returned by nextval."
Especially as the error is coming from a different
transaction(934281063) and session then the INSERTs. I'm guessing that
there is cross talk on the sequence number fetch and application to
cargo_det.
csvlog has a couple of columns that I'm unclear about:
session_start_time, virtual_transaction_id. Is session_start_time the
time inside a transaction block, as in beginning with a begin but before
a commit or rollback? Or is it maybe just how long this pgbouncer
session has been connected? virtual_transaction_id is defined in the
docs as backendID/localXID--do separate backendIDs also represent
separate transactions? Is there a better way to determine separate
transactions within csvlog?
Also, the app code that does this is legacy perl using DBD::Pg but the
original code was written for Informix. We've been in the process of
moving off informix for a while now and should be done within the month.
I intend to re-work this to use returning id (available in postgres
since 8.2!) instead of the serial sequence / last_value hack but not
quite there yet.
Thanks,
Jeff Ross
--
Adrian Klaver
adrian.klaver@xxxxxxxxxxx
