Re: Potential G2-item cycles under serializable isolation

On 6/4/20 8:20 PM, Peter Geoghegan wrote:
> Can you explain the anomaly with reference to the actual SQL queries
> executed in the log? Is the information that I've provided sufficient?

Elle automatically explains these anomalies, so it might be easier to interpret 
with the visualization and/or interpretation of the anomaly--you'll find those 
in store/latest/elle/. Looking at the data structure representation of the 
anomaly, here's what I see in jepsen-failure-2.txt. I'm looking at the first 
(and only) anomaly in :workload/:anomalies/:G2-item.

{:cycle
      [{:type :ok,
        :f :txn,
        :value
        [[:r 100 nil] [:append 101 1] [:r 101 [1]] [:r 96 [1 2]]],
        :time 750303448,
        :process 23,
        :index 727}
       {:type :ok,
        :f :txn,
        :value [[:append 100 1] [:r 99 nil] [:r 101 nil] [:append 4 4]],
        :time 751922048,
        :process 5,
        :index 729}
       {:type :ok,
        :f :txn,
        :value
        [[:r 100 nil] [:append 101 1] [:r 101 [1]] [:r 96 [1 2]]],
        :time 750303448,
        :process 23,
        :index 727}],
      :steps
      ({:type :rw,
        :key 100,
        :value :elle.list-append/init,
        :value' 1,
        :a-mop-index 0,
        :b-mop-index 0}
       {:type :rw,
        :key 101,
        :value :elle.list-append/init,
        :value' 1,
        :a-mop-index 2,
        :b-mop-index 1}),
      :type :G2-item}

We have a cycle involving two transactions (:cycle)--the first transaction is 
shown at the end as well to make it easier to see that it closes the loop. Let's 
call them T1 (:index 727) and T2 (index :729). The first step (:steps) is an 
anti-dependency: T1 read key 100 and observed the initial state ([:r 100 nil]), 
but T2 appended 1 to 100, so we know T1 < T2. The second step is also an 
anti-dependency: T2 read key 101 and observed the initial state ([:r 101 nil]). 
Both of these transactions completed successfully (:type :ok), which means we 
have two committed transactions, both of which failed to observe the other's 
writes. These can't be serializable, because if we choose T1 < T2, T2 fails to 
observe a write that T1 performed, and if we choose T2 < T1, T1 fails to observe 
a write that T2 performed. You'll probably see something similar to this 
explanation in store/latest/elle/G2-item.txt, and a corresponding diagram in 
store/latest/elle/G2-item/0.svg.

Elle infers, from the presence of G2-item, that this history cannot satisfy 
repeatable read (:not #{:repeatable-read}). By extension, it knows (:also-not) 
that it can't be serializable, strict serializable, or strong session 
serializable either.

Now, to the SQL. T1 was performed by process 23, and T2 by process 5--you've 
helpfully restricted the postgres logs to just those two processes, so you're 
one step ahead of me. I searched for $1 = '100' to find the read of key 100 from 
process 23:

1591312493.044 171762 0 BEGIN 5ed9806c.29ef2 jepsen process 23 LOG:  execute 
<unnamed>: BEGIN
1591312493.044 171762 0 SELECT 5ed9806c.29ef2 jepsen process 23 DETAIL:  
parameters: $1 = '100'
1591312493.044 171762 0 SELECT 5ed9806c.29ef2 jepsen process 23 LOG:  execute 
<unnamed>: select (val) from txn2 where sk = $1

So, process 23 begins a transaction and reads key 100 from table txn2, using the 
secondary key `sk`. This is new, BTW--earlier versions of the test did every 
operation by primary key; I've been making the test harder over time. That read 
returns no rows: [:r 100 nil].

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. :)

1591312493.044 171762 0 SET 5ed9806c.29ef2 jepsen process 23 LOG:  execute 
<unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
1591312493.044 171762 0 SHOW 5ed9806c.29ef2 jepsen process 23 LOG:  execute 
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL

Next (in this sorted log, but not in reality), process 23 appends 1 to key 101, 
in table txn0:

1591312493.045 171762 0 INSERT 5ed9806c.29ef2 jepsen process 23 DETAIL:  
parameters: $1 = '101', $2 = '101', $3 = '1'
1591312493.045 171762 0 INSERT 5ed9806c.29ef2 jepsen process 23 LOG:  execute 
<unnamed>: insert into txn0 (id, sk, val) values ($1, $2, $3)

There should have been an update first, but it got sorted later in this file. 
Here's the update--this must have happened first, failed, and caused process 23 
to back off to an insert.

1591312493.045 171762 0 SAVEPOINT 5ed9806c.29ef2 jepsen process 23 LOG:  execute 
<unnamed>: savepoint upsert
1591312493.045 171762 0 UPDATE 5ed9806c.29ef2 jepsen process 23 DETAIL:  
parameters: $1 = '1', $2 = '101'
1591312493.045 171762 0 UPDATE 5ed9806c.29ef2 jepsen process 23 LOG:  execute 
<unnamed>: update txn0 set val = CONCAT(val, ',', $1) where id = $2

Next, process 5 begins its transaction:

1591312493.046 171734 0 BEGIN 5ed9806c.29ed6 jepsen process 5 LOG:  execute 
<unnamed>: BEGIN
1591312493.046 171734 0 SET 5ed9806c.29ed6 jepsen process 5 LOG: execute 
<unnamed>: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL SERIALIZABLE
1591312493.046 171734 0 SHOW 5ed9806c.29ed6 jepsen process 5 LOG: execute 
<unnamed>: SHOW TRANSACTION ISOLATION LEVEL

... and tries to append 1 to key 100 by primary key `id`:

1591312493.046 171734 0 UPDATE 5ed9806c.29ed6 jepsen process 5 DETAIL:  
parameters: $1 = '1', $2 = '100'
1591312493.046 171734 0 UPDATE 5ed9806c.29ed6 jepsen process 5 LOG:  execute 
<unnamed>: update txn2 set val = CONCAT(val, ',', $1) where id = $2

Process 23 goes on to release its upsert savepoint, and perform reads of key 101 
and 96, observing [1] and [1 2] respectively, before committing. Again, 
out-of-order log due to sorting.

1591312493.046 171762 1197960 COMMIT 5ed9806c.29ef2 jepsen process 23 LOG:  
execute <unnamed>: COMMIT
1591312493.046 171762 1197960 RELEASE 5ed9806c.29ef2 jepsen process 23 LOG:  
execute <unnamed>: release savepoint upsert
1591312493.046 171762 1197960 SELECT 5ed9806c.29ef2 jepsen process 23 DETAIL:  
parameters: $1 = '101'
1591312493.046 171762 1197960 SELECT 5ed9806c.29ef2 jepsen process 23 DETAIL:  
parameters: $1 = '96'
1591312493.046 171762 1197960 SELECT 5ed9806c.29ef2 jepsen process 23 LOG:  
execute <unnamed>: select (val) from txn0 where id = $1
1591312493.046 171762 1197960 SELECT 5ed9806c.29ef2 jepsen process 23 LOG:  
execute <unnamed>: select (val) from txn0 where sk = $1

Process 5's update affects zero rows, so it similarly backs off to an insert 
statement:

1591312493.047 171734 0 INSERT 5ed9806c.29ed6 jepsen process 5 DETAIL:  
parameters: $1 = '100', $2 = '100', $3 = '1'
1591312493.047 171734 0 INSERT 5ed9806c.29ed6 jepsen process 5 LOG:  execute 
<unnamed>: insert into txn2 (id, sk, val) values ($1, $2, $3)
1591312493.047 171734 0 SAVEPOINT 5ed9806c.29ed6 jepsen process 5 LOG:  execute 
<unnamed>: savepoint upsert
1591312493.047 171734 1197963 RELEASE 5ed9806c.29ed6 jepsen process 5 LOG:  
execute <unnamed>: release savepoint upsert

... followed by reads of 99 and 101.

1591312493.047 171734 1197963 SELECT 5ed9806c.29ed6 jepsen process 5 DETAIL:  
parameters: $1 = '101'
1591312493.047 171734 1197963 SELECT 5ed9806c.29ed6 jepsen process 5 DETAIL:  
parameters: $1 = '99'
1591312493.047 171734 1197963 SELECT 5ed9806c.29ed6 jepsen process 5 LOG:  
execute <unnamed>: select (val) from txn0 where sk = $1
1591312493.047 171734 1197963 SELECT 5ed9806c.29ed6 jepsen process 5 LOG:  
execute <unnamed>: select (val) from txn2 where id = $1

We know the read of 101 observed no rows, which makes sense because process 5
(T2)'s transaction began during process 23's transaction, *before* the commit. 
What *doesn't* make sense is...

1591312493.048 171734 1197963 COMMIT 5ed9806c.29ed6 jepsen process 5 LOG:  
execute <unnamed>: COMMIT

Process 5 manages to *commit* despite the anti-dependency cycle! That's legal 
under SI, but not under serializability.

Phew! I know it's a lot. Does this help?

--Kyle