View Issue Details
| ID | Project | Category | View Status | Date Submitted | Last Update |
|---|---|---|---|---|---|
| 0006452 | Taler | exchange | public | 2020-07-31 19:36 | 2021-08-24 16:23 |
| Reporter | Florian Dold | Assigned To | Florian Dold | ||
| Priority | normal | Severity | major | Reproducibility | random |
| Status | closed | Resolution | fixed | ||
| Product Version | git (master) | ||||
| Target Version | 0.8 | Fixed in Version | 0.8 | ||
| Summary | 0006452: exchange livelocks with only small number of concurrent requests | ||||
| Description | See 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! | ||||
| Tags | No tags attached. | ||||
| Attached Files | |||||
|
|
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. |
|
|
Can be reproduced easily now: cd wallet-core.git ./bootstrap && ./configure --prefix=$HOME/local && make install cd packages/taler-integrationtests/ ./testrunner 'test-payment-multiple' |
|
|
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 |
|
|
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. |
|
|
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. |
|
|
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. |
|
|
Should the exchange not still be resilient against these kinds of requests and generally be thread-safe? |
|
|
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. |
|
|
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. |
| 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 | |
| 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 | |
| 2020-08-10 07:18 | Christian Grothoff | Note Added: 0016580 | |
| 2020-08-10 07:38 | Christian Grothoff | Note Edited: 0016579 | |
| 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 | |
| 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 | |
| 2021-08-24 16:23 | Christian Grothoff | Status | resolved => closed |
