On Fri, Jun 5, 2020 at 6:03 AM Kyle Kingsbury <aphyr@jepsen.io> wrote:
> Process 23, at least in this log, goes on to set the session to SERIALIZABLE.
> This is a bit weird, because that statement should be executed by JDBC when we
> started the transaction, right? Makes me wonder if maybe the log lines are out
> of order? Now that I look... these are suspiciously alphabetically ordered. If
> you sorted the file, that might explain it. :)
I messed that up massively -- sorry. Attached is a revised version of
the same thing, which fixes the accidental sorting. Just the relevant
area, with the proper order.
Note also that this is the log_line_prefix used: log_line_prefix='%n
%p %x %i %c %a '
Why is it that process 5 updates the txn1 table at the end, having
done insert/update stuff to the txn2 table earlier on in the same xact
(or what appears to be the same xact)? Note that that update is the
only statement from the entire sequence that affects txn1 (all other
statements affect either txn0 or txn2). It's as if the homebrew upsert
changed its mind about which table it's supposed to affect. I cannot
speak Clojure, so I have to ask. Maybe this just demonstrates that an
approach based on reading the logs like this just isn't workable. I
think that this original order might still be slightly off, due to the
vagaries of stdio with concurrent writes to the log file -- not sure
how much that, though.
I suspect that I should try a high fidelity way of capturing the
original execution order. I'm thinking of something like
test_decoding, which will show us a representation in LSN order, which
is precisely what we want:
https://www.postgresql.org/docs/devel/test-decoding.html
--
Peter Geoghegan