View Issue Details

IDProjectCategoryView StatusLast Update
0006452Talerexchangepublic2020-08-13 16:31
ReporterFlorian Dold Assigned ToFlorian Dold  
PrioritynormalSeveritymajorReproducibilityrandom
Status resolvedResolutionfixed 
Product Versiongit (master) 
Target Version0.8Fixed in Version0.8 
Summary0006452: exchange livelocks with only small number of concurrent requests
DescriptionSee the attached logs, specifically async scope IDs

DVGVWZGJMQSMTKBZ2PM0AS0ZHR

and

QVBSQHWV58JKX98G9DS6966KCG.

During 150 milliseconds (!), pretty much the only thing that happens is these two transactions trampling on each other's feet!
TagsNo tags attached.

Activities

Florian Dold

2020-07-31 19:36

manager  

Christian Grothoff

2020-08-02 23:31

manager   ~0016543

I still think this is because the exchange's database is so tiny, that page-level locks are too coarse. Disabling parallelism in Postgres seems to fix it pretty well for now, and might be a good answer as parallelism right now won't help anyway -- and once it would, the database will be large enough for the page-level locks to not conflict.

Florian Dold

2020-08-06 12:33

manager   ~0016562

Can be reproduced easily now:

cd wallet-core.git
./bootstrap && ./configure --prefix=$HOME/local && make install
cd packages/taler-integrationtests/
./testrunner 'test-payment-multiple'

Christian Grothoff

2020-08-07 15:56

manager   ~0016570

Last edited: 2020-08-10 07:04

View 2 revisions

Findings:
- Bug is not 100% reproducible on every run on my system. But happens 'often'.
- Postgres does NOT show any database accesses without an index in the exchange => not the cause.
- Postgres documentation for serializable urges clients to limit concurrency. Reducing thread pool size to 2-4 (from 32) seems to make the problem largely disappear
- Deploying pgpool2 to 'merge' connections from the exchange to Postgres causes all kinds of other havoc (=> abandoned).
- Playing with various postgres configuration settings seems to have no impact

What to do:
- limit #threads for now (workaround)
- investigate if the issue truly persists for 'large' databases where page-level locks should be less of an issue
- medium term: consider reducing #DB connections to less than one per thread (i.e. introduce DB connection pool
  into the exchange logic, protect with semaphore, grab, run, release to pool, etc.)
- long term: investigate what happens if we shard the database

Christian Grothoff

2020-08-10 07:03

manager   ~0016579

Last edited: 2020-08-10 07:38

View 2 revisions

So here are some interesting first results.

I am running

$ TALER_TEST_REPEAT=10000 ./scenario rerun-payment-multiple

and analyzing the logs. First:

$ for n in 23 00 01 02 03 04 05 06; do cat /tmp/taler-integrationtest-Hy7qum/exchange-httpd-testexchange-1-stderr.log | grep " $n:..:..-" | grep "Trying to withdraw" | wc -l; done
50678
50988
51012
50291
50465
51096
50782
51523

This query shows: we have a relatively stable number of # withdraw operations/hour. The key point we need from this is that the number is NOT somehow dropping over time.

Now, let's look at the number of serialization failures per hour in the logs, excluding (!) the query "reserve_update":

$ for n in 23 00 01 02 03 04 05 06; do cat /tmp/taler-integrationtest-Hy7qum/exchange-httpd-testexchange-1-stderr.log | grep serializ | grep " $n:..:..-" | grep Query | grep -v reserve_update | wc -l; done
458
299
242
190
174
166
134
119

So here there is a very clear drop. As hoped, with a growing database, serialization failures go down! Great.

Now what about that 'reserve_update' query?

$ for n in 23 00 01 02 03 04 05; do cat /tmp/taler-integrationtest-Hy7qum/exchange-httpd-testexchange-1-stderr.log | grep serializ | grep " $n:..:..-" | grep Query | grep reserve_update | wc -l; done
10656
10936
10928
10608
10863
11110
10952

so here I don't see a drop, it might even be going up. (Why could it go up? Well, maybe the # transactions isn't perfectly stable (see first query), and we actually do get a slight increase here because we do more work per hour, say because the other transactions have fewer serialization failures.)

Big question: why is this query not behaving as hoped? I see three possibilities:
1) Are we re-using the reserve_pub? So the DB is not growing the size of this table?
2) Do we have a missing index problem, so the DB does not benefit from conflict reduction from the growth?
3) Something else we don't understand yet.

Anyway, the other queries make me very hopeful that this entire issue can be solved by:
1) running with low concurrency initially
2) increasing concurrency as the system scales and the DB has naturally fewer serialization conflicts.

Christian Grothoff

2020-08-10 07:18

manager   ~0016580

More findings:
(1) we're not re-using the reserve_pub, but even now there are only 0001588:0004080 reserves in the database (but 330884 known coins). So the growth there is MUCH slower, so we may still simply be way too slow.
(2) We definitively have an index, the only item the query selects upon is the PRIMARY KEY of the table.
(3) The reserve_update statement is a key action we do during every withdraw inside of "insert_withdraw_info". So this is likely _the_ transactional bottleneck and maybe a good candidate for replacing the current "SELECT + UPDATE" with a maybe more performant statement.

Christian Grothoff

2020-08-10 08:27

manager   ~0016581

Last edited: 2020-08-10 09:17

View 2 revisions

First (preliminary) data shows that merging a SELECT and an UPDATE statement for the reserve balance in 1a37d9d8..6503a9fe (creating a new 'reserve_reduce' SQL statement instead of 'reserve_update') reduces conflicts by about 3%. Again, this is preliminary data.

That said, it seems unavoidable to get conflicts (and larger DBs won't help) *IF* the wallet makes withdraw operations from the same reserve (!) in parallel (!). My guess right now is that this is what is actually going on: the wallet creates coins and runs withdrawals in parallel, and since we only have one wallet and that wallet probably only uses one reserve, we get massive serialization issues _because_ during the withdraw phase we DO really hit the same reserve from multiple threads with massively conflicting updates.

Assuming my analysis above is correct, the solution is clear: change the wallet to ensure it never withdraws in parallel from the same reserve (or equivalently, from operating in parallel on the same coin, say deposit + refresh), at least as far as the network is concerned. Sure, that'll (minimally) reduce parallelism (crypto can be parallel!), but it'll massively help the exchange.

grote

2020-08-12 19:08

reporter   ~0016592

Should the exchange not still be resilient against these kinds of requests and generally be thread-safe?

Christian Grothoff

2020-08-12 19:31

manager   ~0016593

It is, the point of the bug is that if the exchange gets two conflicting requests on two different threads, only one can/may succeed. So if a wallet hits the exchange with a dozen _conflicting_ requests, it'll get a high rate of errors back. That's not the exchange's fault, and it would be very inefficient for a wallet as it'll have to retry. So instead of retrying, the point is to simply not send requests that are totally going to conflict (same coin, same reserve) in parallel, as otherwise with high likelihood one will be aborted.

Christian Grothoff

2020-08-13 16:31

manager   ~0016597

I can confirm that with the latest wallet change, all serialization issues that remain are only for tiny databases and drop sharply as the database grows and not everything happens on a single page ;-). Declaring victory.

Issue History

Date Modified Username Field Change
2020-07-31 19:36 Florian Dold New Issue
2020-07-31 19:36 Florian Dold Status new => assigned
2020-07-31 19:36 Florian Dold Assigned To => Christian Grothoff
2020-07-31 19:36 Florian Dold File Added: logs-exchange-2020-07-31.tar.gz
2020-08-02 23:30 Christian Grothoff Target Version 0.8 =>
2020-08-02 23:30 Christian Grothoff Description Updated View Revisions
2020-08-02 23:31 Christian Grothoff Note Added: 0016543
2020-08-02 23:32 Christian Grothoff Assigned To Christian Grothoff =>
2020-08-02 23:32 Christian Grothoff Status assigned => acknowledged
2020-08-06 12:33 Florian Dold Note Added: 0016562
2020-08-07 01:51 Christian Grothoff Assigned To => Christian Grothoff
2020-08-07 01:51 Christian Grothoff Status acknowledged => assigned
2020-08-07 01:51 Christian Grothoff Product Version => git (master)
2020-08-07 01:51 Christian Grothoff Target Version => 0.8
2020-08-07 15:56 Christian Grothoff Note Added: 0016570
2020-08-10 07:03 Christian Grothoff Note Added: 0016579
2020-08-10 07:04 Christian Grothoff Note Edited: 0016570 View Revisions
2020-08-10 07:18 Christian Grothoff Note Added: 0016580
2020-08-10 07:38 Christian Grothoff Note Edited: 0016579 View Revisions
2020-08-10 08:27 Christian Grothoff Note Added: 0016581
2020-08-10 08:28 Christian Grothoff Assigned To Christian Grothoff => Florian Dold
2020-08-10 08:28 Christian Grothoff Status assigned => feedback
2020-08-10 09:17 Christian Grothoff Note Edited: 0016581 View Revisions
2020-08-12 19:08 grote Note Added: 0016592
2020-08-12 19:31 Christian Grothoff Note Added: 0016593
2020-08-13 16:31 Christian Grothoff Status feedback => resolved
2020-08-13 16:31 Christian Grothoff Resolution open => fixed
2020-08-13 16:31 Christian Grothoff Fixed in Version => 0.8
2020-08-13 16:31 Christian Grothoff Note Added: 0016597