Delayed/Failure to read your writes, lost writes are common

[nurturenature]

Hi,

This issue is a follow-on to #1245.
It's another example of how electrification changes the behavior of SQLite3 in unexpected ways.
Delayed/Failure to read your writes is common.

Please see #1245 for basic test architecture and runtime information:

• 5 client nodes
• total of 10 tps
• for 30s
• all transactions are successful

Here's an example:

;; in the results

:cyclic-versions ({:sources #{:monotonic-reads-vg},
                   :sccs    (#{[8 1] [8 3]})})

Looking at the transaction history for interactions with [8 1] and [8 3] we find a series of transactions for process 1:

• append 1
• append 3
• read 1 <- didn't read its own write of 3
• and in a later transaction
  • read 1 and 3
  • append 10
  • read 1, 3, and 10

1	:ok	:txn	[... [:append 8 1] ...]
1	:ok	:txn	[... [:append 8 3] ...]
1	:ok	:txn	[... [:r 8 [1]] ...]
1	:ok	:txn	[[:r 8 [1 3]] [:append 8 10] [:r 8 [1 3 10]] ...]

Or more formally:

G-single-item-process #1
Let:
  T1 = {:index 25, :type :ok, :process 1, :f :txn, :value [[:append 5 1] [:r 8 [1]] [:append 7 6] [:r 7 [2 6]]], :node "n2"}
  T2 = {:index 15, :type :ok, :process 1, :f :txn, :value [[:append 7 4] [:r 6 nil] [:append 8 3] [:append 7 5]], :node "n2"}

Then:
  - T1 < T2, because T1 read version [8 1] which <hb the version [8 3] that T2 wrote.
  - However, T2 < T1, because process 1 executed T2 before T1: a contradiction!

---

A GitHub action, ElectricSQL: Read-Your-Writes, https://github.com/nurturenature/jepsen-causal-consistency/actions/, has been created to reproduce the results.

In the results, :G-single-item-process and :cyclic-versions are the anomalies most likely to be failures to read your writes.

The causal directory will have a directory for each process and any G-single-item-process explanations and graphs.

There are diverse ways this anomaly presents itself.
And in general, it can take detective work and going through the history by hand.
If you have any ideas for post-analysis tools and how to present the information in understandable/actionable ways they would be appreciated.

Thanks.

[linear]

VAX-1835 Failure to read your writes is common

[nurturenature]

Hi,

To help interpret cycles and anomalies, an HTML table is now created showing all transactions interacting with any of the [k v] in the cycle.
In addition, a full transaction history for each key in the cycle is generated.

---

Here's an example that shows data loss:

{:cyclic-versions ({:sources #{:writes-follow-reads-vg
                               :read-prefix-vg
                               :monotonic-reads-vg
                               :monotonic-writes-vg
                               :init-nil-vg},
                    :sccs (#{[10 126] [10 127] [10 128]}
                           ;; plus 9 more different cycles
                          )})}

Looking at the transactions that interacted with the cyclic versions:

• node n1 appends 126, 127, and 128 to 10
• there are no later writes of 10 in the history
• all 5 nodes only ever read 126
  • and these are final reads, e.g. after database quiescence

#{[10 126] [10 127] [10 128]}
Index	Node	Mops
503	n1	[:append 10 126] [:append 10 127] [:append 10 128]
687	n3	[:r 10 [2 7 8 16 17 24 32 35 40 42 43 44 47 51 52 59 63 64 67 75 78 79 84 85 89 90 95 96 97 100 109 110 111 115 120 121 126]]
695	n1	[:r 10 [2 7 8 16 17 24 32 35 40 42 43 44 47 51 52 59 63 64 67 75 78 79 84 85 89 90 95 96 97 100 109 110 111 115 120 121 126]]
697	n5	[:r 10 [2 7 8 16 17 24 32 35 40 42 43 44 47 51 52 59 63 64 67 75 78 79 84 85 89 90 95 96 97 100 109 110 111 115 120 121 126]]
702	n2	[:r 10 [2 7 8 16 17 24 32 35 40 42 43 44 47 51 52 59 63 64 67 75 78 79 84 85 89 90 95 96 97 100 109 110 111 115 120 121 126]]
706	n4	[:r 10 [2 7 8 16 17 24 32 35 40 42 43 44 47 51 52 59 63 64 67 75 78 79 84 85 89 90 95 96 97 100 109 110 111 115 120 121 126]]
Sources: #{:init-nil-vg :monotonic-reads-vg :monotonic-writes-vg :read-prefix-vg :writes-follow-reads-vg}

---

Here's an example where node n4 writes multiple values with different keys, and then only reads one update from each key:

• append 74 and 75 to 8, and append 24 and 25 to 10
• only read 74 from 8, and only read 24 from 10

---

The lost writes occur in multiple different patterns and are common.

The same test using an un-electrified SQLite3 db shows no anomalies

[nurturenature]

In an attempt to shrink the test environment down to the simplest form that shows anomalous behavior:

• tried testing with single operation transactions, e.g. single upsert or read

  • still issues
  • see discussion below

• tried testing with single operation transactions using the generated client API

  const result = await electric.db.lww.upsert(req.body)
  const result = await electric.db.lww.findUnique(req.body)

  • still issues
  • see discussion below

Here's an example using the generated client API:

• n5 writes 61
• n4 writes 64
• n5 observes its own write of 61
• n5 observes n4's write of 64
• n5 observes n4's write of 64
• n5 does the time warp and reads back in time to its write of 61

#{[11 61] [11 64]}
Index	Node	Mops
3775	n5	[:append 11 61]
3785	n4	[:append 11 64]
3787	n5	[:r 11 [61]]
3798	n5	[:r 11 [64]]
3811	n5	[:r 11 [64]]
3823	n5	[:r 11 [61]]
Sources: #{:monotonic-reads-vg}

---

Observations:

• switching from the db adapter API to the generated client API

  • significantly constrains what it's possible to do and test
  • single value writes vs append
  • single upsert at a time
  • no mixed reads, writes

• and even though the system as a whole is more resilient with single operation transactions

  • can run at higher rates for longer periods of time
    • with lower rate of anomalies
    • before becoming divergent, losing strong convergence
    • triggering GenServer restarts on the sync service

• and there's classes of anomalies that are not findable using the electric API

  • e.g. can't have intermediate reads if can only write one [k v] at a time

• anomalies are still found

  • clients cycle monotonic read values, going back and forth in time
  • clients only read some, but not all of another process's writes, e.g. not monotonic writes

• and the generated client API and db adapter API results are similar in nature when using single operation transactions

Although not conclusive, it does seem to indicate, and is consistent with the idea that electrification of a SQLite3 table changes its behavior in fundamental ways regardless of the API used for access.

IOW, it's likely the full complement of anomalies are always present and using a constrained API only affects the nature and frequency of their occurrence?

[thruflo]

Thanks for such a detailed report. Cc @balegas