Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

wip: etcd fixes and performance improvements #5392

Closed
wants to merge 8 commits into from

Conversation

bhandras
Copy link
Collaborator

@bhandras bhandras commented Jun 16, 2021

Edit:
- rebased on #5516 (1st commit)
- rebased on #5515 (2nd commit)
- rebased on #5514 (3rd commit)
- rebased on #5513 (4-5-6th commits)

The results below are somewhat outdated since now all data is in the remote db.

Description:
This PR adds a few performance improvements to LND's etcd kvdb wrapper and fixes a few of the most important hotspots.
The performance improvements is pretty dramatic and could possibly be further improved. Some of the changes require migration which is not part of the PR until ACKed.

Test 1: make itest etcd=1 icase=async_payments_benchmark

master

=== RUN   TestLightningNetworkDaemon/36-of-79/btcd/async_payments_benchmark
    test_harness.go:120: 	Benchmark info: Elapsed time:  5.851402397s
    test_harness.go:120: 	Benchmark info: TPS:  82.54431454716445

bhandras:etcd_improvements

=== RUN   TestLightningNetworkDaemon/36-of-79/btcd/async_payments_benchmark
    test_harness.go:120: 	Benchmark info: Elapsed time:  3.357472064s
    test_harness.go:120: 	Benchmark info: TPS:  143.85823345453753

For reference the same tests with bbolt:
master

=== RUN   TestLightningNetworkDaemon/36-of-79/btcd/async_payments_benchmark
    test_harness.go:120: 	Benchmark info: Elapsed time:  3.255560917s
    test_harness.go:120: 	Benchmark info: TPS:  148.3615304133472

bhandras:etcd_improvements

 === RUN   TestLightningNetworkDaemon/36-of-79/btcd/async_payments_benchmark
    test_harness.go:120: 	Benchmark info: Elapsed time:  2.841959831s
    test_harness.go:120: 	Benchmark info: TPS:  169.95314104423736

Test 2:
Bottlepay benchmark (bottlepay/lightning-benchmark#6) lnd-etcd-notls with etcd 3.5. (machine is a Hetzner AX41-nvme dedicated server):

loadtest_1    | 2021-06-25T20:28:24.266Z	INFO	Speed	{"tps": 64.53423786816828, "count": 2000, "avg_latency_sec": 1.551165605579}
loadtest_1    | 2021-06-25T20:28:39.926Z	INFO	Speed	{"tps": 63.8589896810007, "count": 3000, "avg_latency_sec": 1.563214304955}
loadtest_1    | 2021-06-25T20:28:55.677Z	INFO	Speed	{"tps": 63.48883943608307, "count": 4000, "avg_latency_sec": 1.5691106821979999}
loadtest_1    | 2021-06-25T20:29:11.351Z	INFO	Speed	{"tps": 63.799733551016345, "count": 5000, "avg_latency_sec": 1.575523050719}
loadtest_1    | 2021-06-25T20:29:33.243Z	INFO	Speed	{"tps": 45.6792330787301, "count": 6000, "avg_latency_sec": 2.125946590737}
loadtest_1    | 2021-06-25T20:30:00.740Z	INFO	Speed	{"tps": 36.36786498886787, "count": 7000, "avg_latency_sec": 2.7182521204489998}
loadtest_1    | 2021-06-25T20:30:37.995Z	INFO	Speed	{"tps": 26.841979764258515, "count": 8000, "avg_latency_sec": 3.712007323702}
loadtest_1    | 2021-06-25T20:31:15.672Z	INFO	Speed	{"tps": 26.541241455872445, "count": 9000, "avg_latency_sec": 3.7649197021939997}
loadtest_1    | 2021-06-25T20:31:53.198Z	INFO	Speed	{"tps": 26.648147887337295, "count": 10000, "avg_latency_sec": 3.760037243958}
loadtest_1    | 2021-06-25T20:32:30.899Z	INFO	Speed	{"tps": 26.52495979994532, "count": 11000, "avg_latency_sec": 3.762526293845}
loadtest_1    | 2021-06-25T20:33:08.355Z	INFO	Speed	{"tps": 26.697739686752644, "count": 12000, "avg_latency_sec": 3.743134903228}
loadtest_1    | 2021-06-25T20:33:46.253Z	INFO	Speed	{"tps": 26.387032710041233, "count": 13000, "avg_latency_sec": 3.778454786527}
loadtest_1    | 2021-06-25T20:34:22.728Z	INFO	Speed	{"tps": 27.41602735140185, "count": 14000, "avg_latency_sec": 3.648309565185}
loadtest_1    | 2021-06-25T20:34:59.736Z	INFO	Speed	{"tps": 27.020954368414703, "count": 15000, "avg_latency_sec": 3.7169224409929997}
loadtest_1    | 2021-06-25T20:35:36.832Z	INFO	Speed	{"tps": 26.95708458772625, "count": 16000, "avg_latency_sec": 3.718038788403}
loadtest_1    | 2021-06-25T20:36:14.057Z	INFO	Speed	{"tps": 26.863801955015347, "count": 17000, "avg_latency_sec": 3.7005437773809997}
loadtest_1    | 2021-06-25T20:36:50.769Z	INFO	Speed	{"tps": 27.23912651754751, "count": 18000, "avg_latency_sec": 3.702418314502}
loadtest_1    | 2021-06-25T20:37:27.028Z	INFO	Speed	{"tps": 27.579645991685165, "count": 19000, "avg_latency_sec": 3.62833937356}
loadtest_1    | 2021-06-25T20:38:03.640Z	INFO	Speed	{"tps": 27.31288613225411, "count": 20000, "avg_latency_sec": 3.640910035547}
loadtest_1    | 2021-06-25T20:38:38.998Z	INFO	Speed	{"tps": 28.28272378039225, "count": 21000, "avg_latency_sec": 3.549461816367}
loadtest_1    | 2021-06-25T20:39:15.517Z	INFO	Speed	{"tps": 27.38268223134218, "count": 22000, "avg_latency_sec": 3.622988230753}
loadtest_1    | 2021-06-25T20:39:51.170Z	INFO	Speed	{"tps": 28.04850209294464, "count": 23000, "avg_latency_sec": 3.616076497207}
loadtest_1    | 2021-06-25T20:40:14.835Z	INFO	Speed	{"tps": 42.25609409199764, "count": 24000, "avg_latency_sec": 2.3856274190680002}
loadtest_1    | 2021-06-25T20:40:41.624Z	INFO	Speed	{"tps": 37.328661146707326, "count": 25000, "avg_latency_sec": 2.631493367686}
loadtest_1    | 2021-06-25T20:41:16.835Z	INFO	Speed	{"tps": 28.40056707352067, "count": 26000, "avg_latency_sec": 3.518374261111}
loadtest_1    | 2021-06-25T20:41:51.929Z	INFO	Speed	{"tps": 28.495038611114413, "count": 27000, "avg_latency_sec": 3.449567716871}
loadtest_1    | 2021-06-25T20:42:25.699Z	INFO	Speed	{"tps": 29.612065864047747, "count": 28000, "avg_latency_sec": 3.412843902324}
loadtest_1    | 2021-06-25T20:42:59.842Z	INFO	Speed	{"tps": 29.288941299676388, "count": 29000, "avg_latency_sec": 3.440998649995}
loadtest_1    | 2021-06-25T20:43:30.855Z	INFO	Speed	{"tps": 32.24437955314579, "count": 30000, "avg_latency_sec": 3.1074791252639997}
loadtest_1    | 2021-06-25T20:44:01.289Z	INFO	Speed	{"tps": 32.85841298524933, "count": 31000, "avg_latency_sec": 3.048717978335}
loadtest_1    | 2021-06-25T20:44:26.317Z	INFO	Speed	{"tps": 39.95553007358418, "count": 32000, "avg_latency_sec": 2.535706471033}
loadtest_1    | 2021-06-25T20:44:55.086Z	INFO	Speed	{"tps": 34.75919827405728, "count": 33000, "avg_latency_sec": 2.901374373912}
loadtest_1    | 2021-06-25T20:45:20.299Z	INFO	Speed	{"tps": 39.662256248877995, "count": 34000, "avg_latency_sec": 2.402428623677}
loadtest_1    | 2021-06-25T20:45:47.715Z	INFO	Speed	{"tps": 36.475168809779504, "count": 35000, "avg_latency_sec": 2.6934887744009997}
loadtest_1    | 2021-06-25T20:46:13.449Z	INFO	Speed	{"tps": 38.860213406542506, "count": 36000, "avg_latency_sec": 2.732327640684}
loadtest_1    | 2021-06-25T20:46:40.743Z	INFO	Speed	{"tps": 36.63767627400598, "count": 37000, "avg_latency_sec": 2.71133185894}
loadtest_1    | 2021-06-25T20:47:14.283Z	INFO	Speed	{"tps": 29.815589101065907, "count": 38000, "avg_latency_sec": 3.251210235977}
loadtest_1    | 2021-06-25T20:47:50.904Z	INFO	Speed	{"tps": 27.306501429238995, "count": 39000, "avg_latency_sec": 3.5618042077629997}
loadtest_1    | 2021-06-25T20:48:20.768Z	INFO	Speed	{"tps": 33.48506530134645, "count": 40000, "avg_latency_sec": 3.178217333703}
loadtest_1    | 2021-06-25T20:48:53.882Z	INFO	Speed	{"tps": 30.198867511743984, "count": 41000, "avg_latency_sec": 3.261326943087}
loadtest_1    | 2021-06-25T20:49:30.377Z	INFO	Speed	{"tps": 27.4009239644335, "count": 42000, "avg_latency_sec": 3.6618183438000003}
loadtest_1    | 2021-06-25T20:50:07.803Z	INFO	Speed	{"tps": 26.71946799992048, "count": 43000, "avg_latency_sec": 3.788799161978}
loadtest_1    | 2021-06-25T20:50:40.953Z	INFO	Speed	{"tps": 30.166464100137283, "count": 44000, "avg_latency_sec": 3.261829291491}
loadtest_1    | 2021-06-25T20:51:18.100Z	INFO	Speed	{"tps": 26.920071596310144, "count": 45000, "avg_latency_sec": 3.6476010820380003}
loadtest_1    | 2021-06-25T20:51:57.696Z	INFO	Speed	{"tps": 25.2552097384627, "count": 46000, "avg_latency_sec": 3.989441471565}
loadtest_1    | 2021-06-25T20:52:31.398Z	INFO	Speed	{"tps": 29.672012604051638, "count": 47000, "avg_latency_sec": 3.4311492841969997}
loadtest_1    | 2021-06-25T20:53:09.045Z	INFO	Speed	{"tps": 26.562714943040568, "count": 48000, "avg_latency_sec": 3.708941020582}
loadtest_1    | 2021-06-25T20:53:41.258Z	INFO	Speed	{"tps": 31.04299467250739, "count": 49000, "avg_latency_sec": 3.223344582401}
loadtest_1    | 2021-06-25T20:54:16.625Z	INFO	Speed	{"tps": 28.275201341899614, "count": 50000, "avg_latency_sec": 3.4959532821379997}

It's possible that there's still some amount of degradation over time. After better caching and prefetches at hotspots the main culprit seemed to be the payment sequence and the misson control store. In my tests temporally removing those components completely eliminated all degradation (fluctuations still remained).

@bhandras bhandras force-pushed the etcd_improvements branch 2 times, most recently from 876a0e3 to 720598c Compare June 24, 2021 20:19
@bhandras bhandras force-pushed the etcd_improvements branch 2 times, most recently from 7b042eb to 9e1a678 Compare June 25, 2021 13:05
@bhandras bhandras requested a review from Roasbeef June 25, 2021 21:15
@bhandras
Copy link
Collaborator Author

An idea to fix the mission control store could be to completely eliminate the use of the cursor, but instead extend the kvdb interface with a DeleteRange(prefix, limit) function. The current fix (last commit) is just a quick hack.

@bhandras bhandras requested a review from guggero July 5, 2021 12:41
Copy link
Collaborator

@guggero guggero left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great work on this, looks like you were able to identify and address quite a number of bottlenecks.
I can't say I fully understand the whole code around STM just yet, so take my review with a grain of salt. But the changes look good as far as I can tell.

}

err = htlcBucket.Put(htlcAttemptInfoKey, htlcInfoBytes)
err = htlcsBucket.Put(append(htlcAttemptInfoKey, htlcIDBytes...), htlcInfoBytes)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

We need to be careful when using append() with global variables as sometimes that can modify their value. See https://trstringer.com/golang-append/

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Great work on this, looks like you were able to identify and address quite a number of bottlenecks.
I can't say I fully understand the whole code around STM just yet, so take my review with a grain of salt. But the changes look good as far as I can tell.

Thanks for the review @guggero !! :)

@@ -449,23 +442,22 @@ func (p *PaymentControl) updateHtlcKey(paymentHash lntypes.Hash,
return fmt.Errorf("htlcs bucket not found")
}

htlcBucket := htlcsBucket.NestedReadWriteBucket(htlcIDBytes)
if htlcBucket == nil {
if htlcsBucket.Get(append(htlcAttemptInfoKey, htlcIDBytes...)) == nil {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think this change would actually be bad for bbolt's performance. This would mean all HTLCs would be in the same top-level bucket. This makes write operations very memory intensive with bbolt when there are many entries as it needs to copy its whole btree when adding new leaves.
But I can definitely see why this would help etcd. Not sure what other options we have. Thought if this is a performance bottleneck then it's definitely worth brainstorming a bit more.
Or perhaps even decide that etcd performance has precedence here if the performance hit in bbolt is not too dramatic.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The variable names may be a bit misleading, but the htlcs are in the payment's own bucket (where the key is the payment hash). Before it was the same but there were three sub buckets per htlc attempt.

@@ -67,31 +67,31 @@ var (

// paymentSequenceKey is a key used in the payment's sub-bucket to
// store the sequence number of the payment.
paymentSequenceKey = []byte("payment-sequence-key")
paymentSequenceKey = []byte("s") // "payment-sequence-key"
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I like the idea of shortening the keys. Though perhaps we should always use two characters of which at least one is not in the hex alphabet to make it a bit more clear when just looking at the keys?
For example:

ci -> payment-creation-info
ai -> htlc-attempt-info
si -> htlc-settle-info
fi -> htlc-fail-info
pf -> payment-fail-info

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, maybe two char names are better for readability. I wonder how much we'd spare by shortening our keys, since I think bbolt also serializes the key and is not dictionary based. Maybe I'm wrong though.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't all this a breaking change? Also IIRC, for etcd we hashed these keys down anyway.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, it is breaking change, but there's some huge gains even in etcd. With the etcd driver we currently hash the bucket path and then append the key and the postfix of whether this is a bucket or value key.

So something like this: hash(hash(parent + b) + child + b) + key + b/v. The last part is where these longs names that I renamed would be. For each payment times each HTLC.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Another thing is that if we flatten the payment's htlc bucket that is also a change that needs migration, so we could be at least efficient breaking our schema :)

About flattening: to decide whether or not a payment is settled, we now iterate the htlc bucket (mutliple times during payment lifecycle actually) and then for each HTLC we also get the attempt, settle and fail info keys.

Which means without flattenting and assuming the above hashed structure we'd need num(htlcs) * (3 + 1) roundtrips to the DB per payment every time we need to calculate the payment status. The plus 1 comes from getting into the attempt bucket for the HTLC where the key is a global counter, so we have no way to know which ones to prefetch (keys are guaranteed to be monotonic but not sequential).


// Set a new upper bound in the DB every 1000 payments to avoid
// conflicts on the sequence when using etcd.
if p.currPaymentSeq == p.storedPaymentSeq {
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cool, I see how this should speed things up considerably! Worst case here is that we just "waste" 1k sequences if we restart lnd directly after setting a new upper bound. But that probably shouldn't matter too much if we have gaps in the payment sequences.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yep, wasting an interval is not a huge issue, since we only require these ids to be monotonic. With etcd there was a huge contention on this sequence key causing all payment transactions queueing up, and retried in the STM. This was one of our major bottlenecks.

This comment was marked as resolved.

return kvdb.Update(b.db, func(tx kvdb.RwTx) error {
b.queueMx.Lock()
defer b.queueMx.Unlock()
b.queue.PushBack(rp)
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, so the "results" are never actually read from the store, only on startup? Pathfinding always uses its internal memory representation?

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Exactly. Also I was thinking maybe the whole design of the mission control store is wrong since we use the keys for ordering to be able to delete old ones. Was thinking about a circular list based design where we can deterministically overwrite old entries, so no deletion would be needed but didn't really expand on the idea yet.

@yyforyongyu yyforyongyu self-requested a review July 8, 2021 03:13
@joostjager
Copy link
Contributor

I ran this branch (commit 12e2fc025d8d100df9238fa7dd2a0ced32ecbddc) again on the benchmark rig. Still seeing performance going down:

loadtest_1    | 2021-07-08T14:07:19.311Z        INFO    Speed   {"tps": 75.14193036238315, "count": 10000, "avg_latency_sec": 1.305311964003}
loadtest_1    | 2021-07-08T14:07:33.757Z        INFO    Speed   {"tps": 69.22095510665038, "count": 11000, "avg_latency_sec": 1.428266781691}
loadtest_1    | 2021-07-08T14:07:48.706Z        INFO    Speed   {"tps": 66.89598692150489, "count": 12000, "avg_latency_sec": 1.518786493139}
loadtest_1    | 2021-07-08T14:08:07.099Z        INFO    Speed   {"tps": 54.36768485892386, "count": 13000, "avg_latency_sec": 1.811761789857}
...
loadtest_1    | 2021-07-08T14:13:17.195Z        INFO    Speed   {"tps": 33.471198411439225, "count": 26000, "avg_latency_sec": 3.036198552882}
loadtest_1    | 2021-07-08T14:13:48.885Z        INFO    Speed   {"tps": 31.55597571425602, "count": 27000, "avg_latency_sec": 3.10192132433}
loadtest_1    | 2021-07-08T14:14:23.377Z        INFO    Speed   {"tps": 28.992107302965735, "count": 28000, "avg_latency_sec": 3.520457434735}
loadtest_1    | 2021-07-08T14:17:22.060Z        INFO    Speed   {"tps": 25.572979865416883, "count": 33000, "avg_latency_sec": 3.9895093127959997}
...
loadtest_1    | 2021-07-08T14:29:02.549Z        INFO    Speed   {"tps": 19.782371680872405, "count": 48000, "avg_latency_sec": 5.0474531862909995}
loadtest_1    | 2021-07-08T14:29:58.412Z        INFO    Speed   {"tps": 17.90082123591677, "count": 49000, "avg_latency_sec": 5.68911388522}
loadtest_1    | 2021-07-08T14:30:54.896Z        INFO    Speed   {"tps": 17.704329283512795, "count": 50000, "avg_latency_sec": 5.639053898379999}
loadtest_1    | 2021-07-08T14:31:53.200Z        INFO    Speed   {"tps": 17.15164829144177, "count": 51000, "avg_latency_sec": 5.727623284748}
...
loadtest_1    | 2021-07-08T15:00:16.638Z        INFO    Speed   {"tps": 10.80652597372745, "count": 74000, "avg_latency_sec": 8.320684109424}
loadtest_1    | 2021-07-08T15:01:42.287Z        INFO    Speed   {"tps": 11.675464192683888, "count": 75000, "avg_latency_sec": 9.581611573754}
loadtest_1    | 2021-07-08T15:03:19.586Z        INFO    Speed   {"tps": 10.277611002407355, "count": 76000, "avg_latency_sec": 8.670611182626}
loadtest_1    | 2021-07-08T15:04:44.056Z        INFO    Speed   {"tps": 11.838525160308704, "count": 77000, "avg_latency_sec": 9.304994055154001}

The benchmark eventually crashes. Some of the errors in the log:

[ERR] HSWC: Unhandled error while reforwarding htlc settle/fail over htlcswitch: circuit has already been closed

[ERR] CRTR: Failed to update mission control store: etcd error: stm.Commit() failed - etcdserver: request timed out

[WRN] HSWC: ChannelLink(508:8:0): unable to remove fwd pkgs: etcd error: stm.Commit() failed - etcdserver: too many operations in txn request

@bhandras
Copy link
Collaborator Author

bhandras commented Jul 9, 2021

You need to compact and defrag since with that many payments we'll keep a lot of history in etcd. Or you need to set autocompact and defrag.

@bhandras
Copy link
Collaborator Author

bhandras commented Jul 9, 2021

Also interesting that I'm not able to reproduce the same degradation as you (ptal included results above). What version of etcd did you use? Is this the same gcloud instance?

@joostjager
Copy link
Contributor

You need to compact and defrag since with that many payments we'll keep a lot of history in etcd. Or you need to set autocompact and defrag.

How to configure this exactly?

Also interesting that I'm not able to reproduce the same degradation as you (ptal included results above). What version of etcd did you use? Is this the same gcloud instance?

I use the code that you supplied to me earlier: https://github.com/bottlepay/lightning-benchmark/compare/etcd-improvements-test. Running on the same gcloud instance.

Maybe you can give me a patch on top of that so that I am surely running the right config?

@bhandras
Copy link
Collaborator Author

bhandras commented Jul 9, 2021

Okay did some more tests, and it seems like after 50K payments on my setup degradation was also apparent. Fortunately the cause was simple to pinpoint and it seems like that my simplistic fix to the MC store design was not sufficient. Deleting high number of entries in a foreach cursor is still bad for performance if we do it every 1 sec. For a simple test I simply commented out those parts and perf degradation is completely non-existent which is good news.

loadtest_1    | 2021-07-09T14:36:27.204Z        INFO    Speed   {"tps": 56.8322312171879, "count": 1000, "avg_latency_sec": 1.510404255081}
loadtest_1    | 2021-07-09T14:36:41.878Z        INFO    Speed   {"tps": 68.14732454926559, "count": 2000, "avg_latency_sec": 1.4709459886360001}
loadtest_1    | 2021-07-09T14:36:56.603Z        INFO    Speed   {"tps": 67.90966165765118, "count": 3000, "avg_latency_sec": 1.4720018952}
loadtest_1    | 2021-07-09T14:37:11.102Z        INFO    Speed   {"tps": 68.97425208358104, "count": 4000, "avg_latency_sec": 1.454173778003}
loadtest_1    | 2021-07-09T14:37:26.010Z        INFO    Speed   {"tps": 67.07677528259822, "count": 5000, "avg_latency_sec": 1.4799585934619999}
loadtest_1    | 2021-07-09T14:37:47.091Z        INFO    Speed   {"tps": 47.43704377851562, "count": 6000, "avg_latency_sec": 2.058000632636}
loadtest_1    | 2021-07-09T14:38:13.953Z        INFO    Speed   {"tps": 37.22636690463699, "count": 7000, "avg_latency_sec": 2.6768441527220004}
loadtest_1    | 2021-07-09T14:38:48.487Z        INFO    Speed   {"tps": 28.95692457368628, "count": 8000, "avg_latency_sec": 3.4080974476319996}
loadtest_1    | 2021-07-09T14:39:25.536Z        INFO    Speed   {"tps": 26.991542162070484, "count": 9000, "avg_latency_sec": 3.7019443135319996}
loadtest_1    | 2021-07-09T14:40:01.967Z        INFO    Speed   {"tps": 27.44944916338745, "count": 10000, "avg_latency_sec": 3.6381045619370003}
loadtest_1    | 2021-07-09T14:40:38.100Z        INFO    Speed   {"tps": 27.675732155663596, "count": 11000, "avg_latency_sec": 3.625010383987}
loadtest_1    | 2021-07-09T14:41:16.796Z        INFO    Speed   {"tps": 25.842075346581566, "count": 12000, "avg_latency_sec": 3.813668048038}
loadtest_1    | 2021-07-09T14:41:53.710Z        INFO    Speed   {"tps": 27.090406388024306, "count": 13000, "avg_latency_sec": 3.750481998338}
loadtest_1    | 2021-07-09T14:42:30.935Z        INFO    Speed   {"tps": 26.86380393165279, "count": 14000, "avg_latency_sec": 3.703922130572}
loadtest_1    | 2021-07-09T14:43:07.808Z        INFO    Speed   {"tps": 27.119885263493533, "count": 15000, "avg_latency_sec": 3.681439732187}
loadtest_1    | 2021-07-09T14:43:44.576Z        INFO    Speed   {"tps": 27.1978614626148, "count": 16000, "avg_latency_sec": 3.68806679857}
loadtest_1    | 2021-07-09T14:44:21.490Z        INFO    Speed   {"tps": 27.089915588084718, "count": 17000, "avg_latency_sec": 3.706126139701}
loadtest_1    | 2021-07-09T14:44:58.563Z        INFO    Speed   {"tps": 26.973993900866866, "count": 18000, "avg_latency_sec": 3.69935389619}
loadtest_1    | 2021-07-09T14:45:25.595Z        INFO    Speed   {"tps": 36.99339633430881, "count": 19000, "avg_latency_sec": 2.78379317528}
loadtest_1    | 2021-07-09T14:45:46.422Z        INFO    Speed   {"tps": 48.014894887224884, "count": 20000, "avg_latency_sec": 2.073309152787}
loadtest_1    | 2021-07-09T14:46:19.034Z        INFO    Speed   {"tps": 30.662830300881122, "count": 21000, "avg_latency_sec": 3.145812301186}
loadtest_1    | 2021-07-09T14:46:55.370Z        INFO    Speed   {"tps": 27.52142140375666, "count": 22000, "avg_latency_sec": 3.6785312195040003}
loadtest_1    | 2021-07-09T14:47:29.329Z        INFO    Speed   {"tps": 29.447380183686985, "count": 23000, "avg_latency_sec": 3.416612081644}
loadtest_1    | 2021-07-09T14:48:02.745Z        INFO    Speed   {"tps": 29.92553730419127, "count": 24000, "avg_latency_sec": 3.309727280387}
loadtest_1    | 2021-07-09T14:48:38.744Z        INFO    Speed   {"tps": 27.77870838457106, "count": 25000, "avg_latency_sec": 3.6388655333820004}
loadtest_1    | 2021-07-09T14:49:15.296Z        INFO    Speed   {"tps": 27.3581661815518, "count": 26000, "avg_latency_sec": 3.4900510959120004}
loadtest_1    | 2021-07-09T14:49:45.007Z        INFO    Speed   {"tps": 33.658262034003, "count": 27000, "avg_latency_sec": 3.146124310527}
loadtest_1    | 2021-07-09T14:50:15.531Z        INFO    Speed   {"tps": 32.76085331610834, "count": 28000, "avg_latency_sec": 3.1310029879970003}
loadtest_1    | 2021-07-09T14:50:30.308Z        INFO    Speed   {"tps": 67.67241737749555, "count": 29000, "avg_latency_sec": 1.4784958989930002}
loadtest_1    | 2021-07-09T14:50:45.261Z        INFO    Speed   {"tps": 66.87661993426619, "count": 30000, "avg_latency_sec": 1.4917168933709999}
loadtest_1    | 2021-07-09T14:51:00.131Z        INFO    Speed   {"tps": 67.24874813656115, "count": 31000, "avg_latency_sec": 1.48539007233}
loadtest_1    | 2021-07-09T14:51:28.535Z        INFO    Speed   {"tps": 35.20659754716335, "count": 32000, "avg_latency_sec": 2.750167609867}
loadtest_1    | 2021-07-09T14:52:05.343Z        INFO    Speed   {"tps": 27.167780860438796, "count": 33000, "avg_latency_sec": 3.668727569459}
loadtest_1    | 2021-07-09T14:52:25.367Z        INFO    Speed   {"tps": 49.941136078405954, "count": 34000, "avg_latency_sec": 2.106124077303}
loadtest_1    | 2021-07-09T14:52:43.622Z        INFO    Speed   {"tps": 54.78072846847489, "count": 35000, "avg_latency_sec": 1.7978524383530001}
loadtest_1    | 2021-07-09T14:53:11.916Z        INFO    Speed   {"tps": 35.34246964610236, "count": 36000, "avg_latency_sec": 2.6991269820480004}
loadtest_1    | 2021-07-09T14:53:32.565Z        INFO    Speed   {"tps": 48.42883483743189, "count": 37000, "avg_latency_sec": 2.193898456163}
loadtest_1    | 2021-07-09T14:53:58.098Z        INFO    Speed   {"tps": 39.16571249336685, "count": 38000, "avg_latency_sec": 2.519637557513}
loadtest_1    | 2021-07-09T14:54:23.368Z        INFO    Speed   {"tps": 39.572810292467345, "count": 39000, "avg_latency_sec": 2.587606398799}
loadtest_1    | 2021-07-09T14:54:47.400Z        INFO    Speed   {"tps": 41.610637282996244, "count": 40000, "avg_latency_sec": 2.296770751578}
loadtest_1    | 2021-07-09T14:55:20.604Z        INFO    Speed   {"tps": 30.116668979620822, "count": 41000, "avg_latency_sec": 3.3961283328569998}
loadtest_1    | 2021-07-09T14:55:41.161Z        INFO    Speed   {"tps": 48.64620838496876, "count": 42000, "avg_latency_sec": 2.056737804041}
loadtest_1    | 2021-07-09T14:56:10.053Z        INFO    Speed   {"tps": 34.61169757408186, "count": 43000, "avg_latency_sec": 2.6915720166740003}
loadtest_1    | 2021-07-09T14:56:28.696Z        INFO    Speed   {"tps": 53.63902956932613, "count": 44000, "avg_latency_sec": 2.0908361489089997}
loadtest_1    | 2021-07-09T14:56:43.328Z        INFO    Speed   {"tps": 68.34473973618952, "count": 45000, "avg_latency_sec": 1.467565107658}
loadtest_1    | 2021-07-09T14:57:13.684Z        INFO    Speed   {"tps": 32.94283646306309, "count": 46000, "avg_latency_sec": 2.862288094969}
loadtest_1    | 2021-07-09T14:57:40.902Z        INFO    Speed   {"tps": 36.73952042242779, "count": 47000, "avg_latency_sec": 2.820686873697}
loadtest_1    | 2021-07-09T14:58:15.205Z        INFO    Speed   {"tps": 29.15249912760957, "count": 48000, "avg_latency_sec": 3.315875566804}
loadtest_1    | 2021-07-09T14:58:30.557Z        INFO    Speed   {"tps": 65.13765979826204, "count": 49000, "avg_latency_sec": 1.727621370606}
loadtest_1    | 2021-07-09T14:58:45.401Z        INFO    Speed   {"tps": 67.36581188141804, "count": 50000, "avg_latency_sec": 1.4766942338290001}
loadtest_1    | 2021-07-09T14:59:00.018Z        INFO    Speed   {"tps": 68.41546911839554, "count": 51000, "avg_latency_sec": 1.4642323976059999}
loadtest_1    | 2021-07-09T14:59:18.698Z        INFO    Speed   {"tps": 53.532953107354054, "count": 52000, "avg_latency_sec": 1.868391810206}
loadtest_1    | 2021-07-09T14:59:33.429Z        INFO    Speed   {"tps": 67.88543340817414, "count": 53000, "avg_latency_sec": 1.4713324016659999}
loadtest_1    | 2021-07-09T14:59:48.299Z        INFO    Speed   {"tps": 67.24710065065322, "count": 54000, "avg_latency_sec": 1.490100083634}
loadtest_1    | 2021-07-09T15:00:03.000Z        INFO    Speed   {"tps": 68.02396251802445, "count": 55000, "avg_latency_sec": 1.4657559539890002}
loadtest_1    | 2021-07-09T15:00:22.376Z        INFO    Speed   {"tps": 51.61216818062438, "count": 56000, "avg_latency_sec": 1.936356693397}
loadtest_1    | 2021-07-09T15:00:37.214Z        INFO    Speed   {"tps": 67.39210037686954, "count": 57000, "avg_latency_sec": 1.485176819708}
loadtest_1    | 2021-07-09T15:00:52.089Z        INFO    Speed   {"tps": 67.2289509089752, "count": 58000, "avg_latency_sec": 1.491222528622}
loadtest_1    | 2021-07-09T15:01:11.945Z        INFO    Speed   {"tps": 50.36201337278012, "count": 59000, "avg_latency_sec": 1.884741571158}
loadtest_1    | 2021-07-09T15:01:30.330Z        INFO    Speed   {"tps": 54.39226772976426, "count": 60000, "avg_latency_sec": 1.934931997746}
loadtest_1    | 2021-07-09T15:01:45.158Z        INFO    Speed   {"tps": 67.44110263164175, "count": 61000, "avg_latency_sec": 1.484459503943}
loadtest_1    | 2021-07-09T15:01:59.959Z        INFO    Speed   {"tps": 67.56408842787623, "count": 62000, "avg_latency_sec": 1.48435852228}
loadtest_1    | 2021-07-09T15:02:19.765Z        INFO    Speed   {"tps": 50.49024003718961, "count": 63000, "avg_latency_sec": 1.976738236976}
loadtest_1    | 2021-07-09T15:02:34.637Z        INFO    Speed   {"tps": 67.23973800329522, "count": 64000, "avg_latency_sec": 1.4844005989509998}
loadtest_1    | 2021-07-09T15:02:49.426Z        INFO    Speed   {"tps": 67.61729914993263, "count": 65000, "avg_latency_sec": 1.486444892395}
loadtest_1    | 2021-07-09T15:03:04.241Z        INFO    Speed   {"tps": 67.49938370818319, "count": 66000, "avg_latency_sec": 1.47544700458}
loadtest_1    | 2021-07-09T15:03:24.340Z        INFO    Speed   {"tps": 49.754539700029476, "count": 67000, "avg_latency_sec": 2.014812962102}
loadtest_1    | 2021-07-09T15:03:39.122Z        INFO    Speed   {"tps": 67.64949877600486, "count": 68000, "avg_latency_sec": 1.473076852343}
loadtest_1    | 2021-07-09T15:03:54.165Z        INFO    Speed   {"tps": 66.4770300627705, "count": 69000, "avg_latency_sec": 1.507818120644}
loadtest_1    | 2021-07-09T15:04:14.702Z        INFO    Speed   {"tps": 48.693222253741844, "count": 70000, "avg_latency_sec": 2.010601759591}
loadtest_1    | 2021-07-09T15:04:29.606Z        INFO    Speed   {"tps": 67.09411209483555, "count": 71000, "avg_latency_sec": 1.5280125300740002}
loadtest_1    | 2021-07-09T15:04:44.323Z        INFO    Speed   {"tps": 67.95095820042448, "count": 72000, "avg_latency_sec": 1.488871244544}
loadtest_1    | 2021-07-09T15:04:59.157Z        INFO    Speed   {"tps": 67.41261643470877, "count": 73000, "avg_latency_sec": 1.4719140009390002}
loadtest_1    | 2021-07-09T15:05:20.119Z        INFO    Speed   {"tps": 47.70375322460949, "count": 74000, "avg_latency_sec": 2.087402766371}
loadtest_1    | 2021-07-09T15:05:34.901Z        INFO    Speed   {"tps": 67.65069164995218, "count": 75000, "avg_latency_sec": 1.4845876644340001}
loadtest_1    | 2021-07-09T15:05:49.702Z        INFO    Speed   {"tps": 67.5637531280614, "count": 76000, "avg_latency_sec": 1.477982891879}
loadtest_1    | 2021-07-09T15:06:11.440Z        INFO    Speed   {"tps": 46.00335926788124, "count": 77000, "avg_latency_sec": 1.552614180435}
loadtest_1    | 2021-07-09T15:06:26.528Z        INFO    Speed   {"tps": 66.27633009970191, "count": 78000, "avg_latency_sec": 2.135332090714}```

@bhandras
Copy link
Collaborator Author

bhandras commented Jul 9, 2021

There are a few tunings I did, that I think help too with the benchmark, although not sure how much yet since I had limited time today to test this.

  1. I did echo performance | tee /sys/devices/system/cpu/cpu*/cpufreq/scaling_governor to set performance mode on all cores, as recommended by the etcd tuning guide: https://etcd.io/docs/v3.5/tuning/

  2. I'll submit a patch to the bottlepay repo but just for reference I set up auto compact every 1000 revisions. This is probably too much since in a cluster we probably want to keep at least 10k revisions but just wanted to see if it has a good/bad impact:

    restart: unless-stopped
    image: 'bitnami/etcd:3.5.0'
    environment:
      - ALLOW_NONE_AUTHENTICATION=yes
      - ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_ADVERTISE_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_MAX_TXN_OPS=16384
      - ETCD_MAX_REQUEST_BYTES=104857600
      - ETCD_LOG_LEVEL=error
      - ETCD_AUTO_COMPACTION_MODE=revision
      - ETCD_AUTO_COMPACTION_RETENTION=1000

  etcd-bob:
    restart: unless-stopped
    image: 'bitnami/etcd:3.5.0'
    environment:
      - ALLOW_NONE_AUTHENTICATION=yes
      - ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_ADVERTISE_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_MAX_TXN_OPS=16384
      - ETCD_MAX_REQUEST_BYTES=104857600
      - ETCD_LOG_LEVEL=error
      - ETCD_AUTO_COMPACTION_MODE=revision
      - ETCD_AUTO_COMPACTION_RETENTION=1000
  1. I did defrag every 5 minutes. My rationale was that although it's a stop-the-world style maintenance operation, but at least we can see if it is good/bad. Defragged DB is certainly good for performance. In my tests it didn't really degrade latency.

for i in {1..100} ; do sleep 5m; docker exec -it lightning-benchmark_etcd-alice_1 etcdctl defrag ; docker exec -it lightning-benchmark_etcd-bob_1 etcdctl defrag ; done

It seemed like that on my machine Alice's etcd kept using about 25% CPU going up to 60-70% so less then one "whole core" amount. Seems like the benchmark is faster when etcd CPU usage is stable. I did notice spiking when the MC store was still in operation. For the performance fluctuation (fast when starts, avg for a while, then speeds up later) I have no explanation yet.

@bhandras
Copy link
Collaborator Author

bhandras commented Jul 9, 2021

Put up a fix (last commit) which I think is better than my original idea. The gist is that it creates the difference and stores that rather than iterating the range. More efficient in etcd.

For reference benchmark on my end:

loadtest_1    | 2021-07-09T16:56:20.545Z        INFO    Speed   {"tps": 57.214807984273705, "count": 1000, "avg_latency_sec": 1.517822319934}
loadtest_1    | 2021-07-09T16:56:35.388Z        INFO    Speed   {"tps": 67.37270873237888, "count": 2000, "avg_latency_sec": 1.4867925128700001}
loadtest_1    | 2021-07-09T16:56:50.178Z        INFO    Speed   {"tps": 67.61321441814712, "count": 3000, "avg_latency_sec": 1.474159184823}
loadtest_1    | 2021-07-09T16:57:04.924Z        INFO    Speed   {"tps": 67.81699450054774, "count": 4000, "avg_latency_sec": 1.483676774451}
loadtest_1    | 2021-07-09T16:57:19.787Z        INFO    Speed   {"tps": 67.28001414634421, "count": 5000, "avg_latency_sec": 1.4852773613899999}
loadtest_1    | 2021-07-09T16:57:40.358Z        INFO    Speed   {"tps": 48.61347392444886, "count": 6000, "avg_latency_sec": 1.983652135283}
loadtest_1    | 2021-07-09T16:58:07.618Z        INFO    Speed   {"tps": 36.68310004974411, "count": 7000, "avg_latency_sec": 2.729819407376}
loadtest_1    | 2021-07-09T16:58:42.881Z        INFO    Speed   {"tps": 28.358418286697805, "count": 8000, "avg_latency_sec": 3.467984400543}
loadtest_1    | 2021-07-09T16:59:20.377Z        INFO    Speed   {"tps": 26.670099847456598, "count": 9000, "avg_latency_sec": 3.765748023578}
loadtest_1    | 2021-07-09T16:59:58.149Z        INFO    Speed   {"tps": 26.4746081447004, "count": 10000, "avg_latency_sec": 3.768066113929}
loadtest_1    | 2021-07-09T17:00:35.033Z        INFO    Speed   {"tps": 27.11170133566881, "count": 11000, "avg_latency_sec": 3.6976030337420003}
loadtest_1    | 2021-07-09T17:01:13.392Z        INFO    Speed   {"tps": 26.069966297382372, "count": 12000, "avg_latency_sec": 3.821810951168}
loadtest_1    | 2021-07-09T17:01:51.226Z        INFO    Speed   {"tps": 26.43101448879396, "count": 13000, "avg_latency_sec": 3.781683921645}
loadtest_1    | 2021-07-09T17:02:29.334Z        INFO    Speed   {"tps": 26.24144979502466, "count": 14000, "avg_latency_sec": 3.8176928031409996}
loadtest_1    | 2021-07-09T17:03:06.894Z        INFO    Speed   {"tps": 26.62393010091198, "count": 15000, "avg_latency_sec": 3.770118084067}
loadtest_1    | 2021-07-09T17:03:44.918Z        INFO    Speed   {"tps": 26.299419027965847, "count": 16000, "avg_latency_sec": 3.7895723701299997}
loadtest_1    | 2021-07-09T17:04:22.219Z        INFO    Speed   {"tps": 26.80892754508234, "count": 17000, "avg_latency_sec": 3.7225396239390003}
loadtest_1    | 2021-07-09T17:04:59.577Z        INFO    Speed   {"tps": 26.767838481787606, "count": 18000, "avg_latency_sec": 3.758521555493}
loadtest_1    | 2021-07-09T17:05:36.592Z        INFO    Speed   {"tps": 27.01632401156311, "count": 19000, "avg_latency_sec": 3.688670354911}
loadtest_1    | 2021-07-09T17:06:16.066Z        INFO    Speed   {"tps": 25.33324029869722, "count": 20000, "avg_latency_sec": 3.95093624782}
loadtest_1    | 2021-07-09T17:06:52.762Z        INFO    Speed   {"tps": 27.25118724536897, "count": 21000, "avg_latency_sec": 3.677269312316}
loadtest_1    | 2021-07-09T17:07:29.724Z        INFO    Speed   {"tps": 27.054742458727155, "count": 22000, "avg_latency_sec": 3.683725510189}
loadtest_1    | 2021-07-09T17:08:06.118Z        INFO    Speed   {"tps": 27.47657803946801, "count": 23000, "avg_latency_sec": 3.645570174954}
loadtest_1    | 2021-07-09T17:08:43.010Z        INFO    Speed   {"tps": 27.106166035538575, "count": 24000, "avg_latency_sec": 3.686488509358}
loadtest_1    | 2021-07-09T17:09:20.328Z        INFO    Speed   {"tps": 26.797348186228128, "count": 25000, "avg_latency_sec": 3.7296514891359998}
loadtest_1    | 2021-07-09T17:09:57.174Z        INFO    Speed   {"tps": 27.139561007697473, "count": 26000, "avg_latency_sec": 3.678246207503}
loadtest_1    | 2021-07-09T17:10:33.991Z        INFO    Speed   {"tps": 27.161352247346343, "count": 27000, "avg_latency_sec": 3.6895287071030003}
loadtest_1    | 2021-07-09T17:11:14.686Z        INFO    Speed   {"tps": 24.57297709412609, "count": 28000, "avg_latency_sec": 4.054863699898}
loadtest_1    | 2021-07-09T17:11:52.011Z        INFO    Speed   {"tps": 26.792215222973013, "count": 29000, "avg_latency_sec": 3.736024224964}
loadtest_1    | 2021-07-09T17:12:29.994Z        INFO    Speed   {"tps": 26.32741380145778, "count": 30000, "avg_latency_sec": 3.801564606618}
loadtest_1    | 2021-07-09T17:13:08.007Z        INFO    Speed   {"tps": 26.30694406419562, "count": 31000, "avg_latency_sec": 3.815200508051}
loadtest_1    | 2021-07-09T17:13:45.920Z        INFO    Speed   {"tps": 26.376440428404177, "count": 32000, "avg_latency_sec": 3.7909776347719997}
loadtest_1    | 2021-07-09T17:14:24.362Z        INFO    Speed   {"tps": 26.01266195855609, "count": 33000, "avg_latency_sec": 3.826353095457}
loadtest_1    | 2021-07-09T17:15:01.904Z        INFO    Speed   {"tps": 26.637041342803094, "count": 34000, "avg_latency_sec": 3.740427433224}
loadtest_1    | 2021-07-09T17:15:19.130Z        INFO    Speed   {"tps": 58.05207001690445, "count": 35000, "avg_latency_sec": 1.8650594912829999}
loadtest_1    | 2021-07-09T17:15:38.229Z        INFO    Speed   {"tps": 52.36090072614648, "count": 36000, "avg_latency_sec": 1.875066770045}
loadtest_1    | 2021-07-09T17:16:03.142Z        INFO    Speed   {"tps": 40.13982295491762, "count": 37000, "avg_latency_sec": 2.397397540678}
loadtest_1    | 2021-07-09T17:16:19.955Z        INFO    Speed   {"tps": 59.4748894447449, "count": 38000, "avg_latency_sec": 1.812079822001}
loadtest_1    | 2021-07-09T17:16:34.958Z        INFO    Speed   {"tps": 66.6543500803394, "count": 39000, "avg_latency_sec": 1.489601211652}
loadtest_1    | 2021-07-09T17:16:52.111Z        INFO    Speed   {"tps": 58.30017814348184, "count": 40000, "avg_latency_sec": 1.655731302881}
loadtest_1    | 2021-07-09T17:17:24.519Z        INFO    Speed   {"tps": 30.856721867143236, "count": 41000, "avg_latency_sec": 3.215681150514}
loadtest_1    | 2021-07-09T17:17:57.554Z        INFO    Speed   {"tps": 30.271230041054025, "count": 42000, "avg_latency_sec": 3.287043532857}
loadtest_1    | 2021-07-09T17:18:18.256Z        INFO    Speed   {"tps": 48.30360086814979, "count": 43000, "avg_latency_sec": 2.179874668958}
loadtest_1    | 2021-07-09T17:18:36.057Z        INFO    Speed   {"tps": 56.17643480916656, "count": 44000, "avg_latency_sec": 1.75143940428}
loadtest_1    | 2021-07-09T17:19:04.891Z        INFO    Speed   {"tps": 34.68192578638676, "count": 45000, "avg_latency_sec": 2.723656937707}
loadtest_1    | 2021-07-09T17:19:21.106Z        INFO    Speed   {"tps": 61.67065913150222, "count": 46000, "avg_latency_sec": 1.808419867612}
loadtest_1    | 2021-07-09T17:19:36.283Z        INFO    Speed   {"tps": 65.89064753371399, "count": 47000, "avg_latency_sec": 1.5144639344770001}
loadtest_1    | 2021-07-09T17:19:52.463Z        INFO    Speed   {"tps": 61.8023673834387, "count": 48000, "avg_latency_sec": 1.55380806634}
loadtest_1    | 2021-07-09T17:20:14.423Z        INFO    Speed   {"tps": 45.53794763849091, "count": 49000, "avg_latency_sec": 2.25932288444}
loadtest_1    | 2021-07-09T17:20:29.687Z        INFO    Speed   {"tps": 65.51459189985881, "count": 50000, "avg_latency_sec": 1.523462139192}
loadtest_1    | 2021-07-09T17:20:51.033Z        INFO    Speed   {"tps": 46.847836346418816, "count": 51000, "avg_latency_sec": 2.054776955197}
loadtest_1    | 2021-07-09T17:21:18.507Z        INFO    Speed   {"tps": 36.398154757530335, "count": 52000, "avg_latency_sec": 2.832175087216}
loadtest_1    | 2021-07-09T17:21:33.376Z        INFO    Speed   {"tps": 67.25287543628441, "count": 53000, "avg_latency_sec": 1.481661480681}
loadtest_1    | 2021-07-09T17:21:51.779Z        INFO    Speed   {"tps": 54.339344831547464, "count": 54000, "avg_latency_sec": 1.777665367634}
loadtest_1    | 2021-07-09T17:22:16.545Z        INFO    Speed   {"tps": 40.378464047014866, "count": 55000, "avg_latency_sec": 2.5440374158459997}
loadtest_1    | 2021-07-09T17:22:31.351Z        INFO    Speed   {"tps": 67.53757629296365, "count": 56000, "avg_latency_sec": 1.487286542308}
loadtest_1    | 2021-07-09T17:22:46.324Z        INFO    Speed   {"tps": 66.78845713248481, "count": 57000, "avg_latency_sec": 1.4848566240499999}
loadtest_1    | 2021-07-09T17:23:12.224Z        INFO    Speed   {"tps": 38.610040944529885, "count": 58000, "avg_latency_sec": 2.5188222714869997}
loadtest_1    | 2021-07-09T17:23:27.008Z        INFO    Speed   {"tps": 67.64214450813188, "count": 59000, "avg_latency_sec": 1.550765491008}
loadtest_1    | 2021-07-09T17:23:41.660Z        INFO    Speed   {"tps": 68.24711926838268, "count": 60000, "avg_latency_sec": 1.473481245804}
loadtest_1    | 2021-07-09T17:23:56.521Z        INFO    Speed   {"tps": 67.29309029203118, "count": 61000, "avg_latency_sec": 1.4813183453019998}
loadtest_1    | 2021-07-09T17:24:14.183Z        INFO    Speed   {"tps": 56.61765507380195, "count": 62000, "avg_latency_sec": 1.764983243469}
loadtest_1    | 2021-07-09T17:24:29.139Z        INFO    Speed   {"tps": 66.86606127029015, "count": 63000, "avg_latency_sec": 1.495967226555}
loadtest_1    | 2021-07-09T17:24:44.101Z        INFO    Speed   {"tps": 66.83269109231334, "count": 64000, "avg_latency_sec": 1.493827864509}
loadtest_1    | 2021-07-09T17:25:02.059Z        INFO    Speed   {"tps": 55.68722832868717, "count": 65000, "avg_latency_sec": 1.56019378807}
loadtest_1    | 2021-07-09T17:25:17.066Z        INFO    Speed   {"tps": 66.63569054171758, "count": 66000, "avg_latency_sec": 1.7401769173089998}
loadtest_1    | 2021-07-09T17:25:31.988Z        INFO    Speed   {"tps": 67.01581409446084, "count": 67000, "avg_latency_sec": 1.488117375821}
loadtest_1    | 2021-07-09T17:25:46.908Z        INFO    Speed   {"tps": 67.0244840239066, "count": 68000, "avg_latency_sec": 1.4985334886400001}
loadtest_1    | 2021-07-09T17:26:06.427Z        INFO    Speed   {"tps": 51.23048465710751, "count": 69000, "avg_latency_sec": 1.855850706045}
loadtest_1    | 2021-07-09T17:26:25.328Z        INFO    Speed   {"tps": 52.908140333967914, "count": 70000, "avg_latency_sec": 1.979590633267}
loadtest_1    | 2021-07-09T17:26:40.057Z        INFO    Speed   {"tps": 67.89236735953564, "count": 71000, "avg_latency_sec": 1.481697080406}
loadtest_1    | 2021-07-09T17:26:54.904Z        INFO    Speed   {"tps": 67.35475887800133, "count": 72000, "avg_latency_sec": 1.471541395254}
loadtest_1    | 2021-07-09T17:27:13.367Z        INFO    Speed   {"tps": 54.163001614322845, "count": 73000, "avg_latency_sec": 1.8498607522719999}
loadtest_1    | 2021-07-09T17:27:28.505Z        INFO    Speed   {"tps": 66.05874439811592, "count": 74000, "avg_latency_sec": 1.516897943401}
loadtest_1    | 2021-07-09T17:27:43.591Z        INFO    Speed   {"tps": 66.2861724939194, "count": 75000, "avg_latency_sec": 1.509482844703}
loadtest_1    | 2021-07-09T17:27:58.529Z        INFO    Speed   {"tps": 66.94526045703485, "count": 76000, "avg_latency_sec": 1.494218752114}
loadtest_1    | 2021-07-09T17:28:17.333Z        INFO    Speed   {"tps": 53.18170957345403, "count": 77000, "avg_latency_sec": 1.883018441899}
loadtest_1    | 2021-07-09T17:28:32.275Z        INFO    Speed   {"tps": 66.92495370984996, "count": 78000, "avg_latency_sec": 1.488674167126}
loadtest_1    | 2021-07-09T17:28:47.132Z        INFO    Speed   {"tps": 67.30590182185425, "count": 79000, "avg_latency_sec": 1.486041144459}
loadtest_1    | 2021-07-09T17:29:05.981Z        INFO    Speed   {"tps": 53.054578401444424, "count": 80000, "avg_latency_sec": 1.883965241358}
loadtest_1    | 2021-07-09T17:29:21.018Z        INFO    Speed   {"tps": 66.50297178734313, "count": 81000, "avg_latency_sec": 1.5027542300249999}
loadtest_1    | 2021-07-09T17:29:36.187Z        INFO    Speed   {"tps": 65.9219747239524, "count": 82000, "avg_latency_sec": 1.523443653213}
loadtest_1    | 2021-07-09T17:29:51.078Z        INFO    Speed   {"tps": 67.15475240344851, "count": 83000, "avg_latency_sec": 1.4905357555949998}
loadtest_1    | 2021-07-09T17:30:09.696Z        INFO    Speed   {"tps": 53.71269381171987, "count": 84000, "avg_latency_sec": 1.8540713764069998}
loadtest_1    | 2021-07-09T17:30:24.517Z        INFO    Speed   {"tps": 67.47185535347917, "count": 85000, "avg_latency_sec": 1.482594541639}

@joostjager
Copy link
Contributor

Question about these etcd parameters:

      - ETCD_MAX_TXN_OPS=16384
      - ETCD_MAX_REQUEST_BYTES=104857600
      - ETCD_AUTO_COMPACTION_RETENTION=1000

How do you know for sure that the settings above guarantee that an error like too many operations in txn request will never happen?

// Prefetch will prefetch keys (exact match) and ranges (prefix match).
// So that subsequent fetches for those keys and keys in ranges don't
// go the the DB.
Prefetch(keys []string, ranges []string)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

To me this seems to be an interface that is pretty etcd-specific. Isn't it possible to define a more abstract interface for prefetching at the kvdb level?

kvdb/etcd/stm.go Outdated
@@ -732,6 +942,72 @@ func (s *stm) OnCommit(cb func()) {
s.onCommit = cb
}

// Prefetch will prefetch the passed keys and prefixes in one transaction.
// Keys and prefixes that we already have will be skipped.
func (s *stm) Prefetch(keys []string, prefixes []string) {
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I must say that I am a little intimidated by the STM code. It is almost as if logic that is normally part of a (battle-tested) database server is now implemented in lnd itself. Do you think it is solid enough to trust it with critical Lightning data? It feels risky, but maybe I am not familiar enough with etcd.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah since we needed to bend the usual implementation to fit our pattern/interfaces, we ended up having to write more custom logic here than originally anticipated. I also get somewhat squeamish when we need to make significant changes in this area. FWIW, if we want to rely on them, there're tools like Jepsen that can be used to find consistency violating issues in distributed databases. A run of the tool a few years ago actually found a number of issues in the etcd logic as well as some of the concurrency APIs (leasing, locking, etc).

@joostjager
Copy link
Contributor

joostjager commented Jul 9, 2021

I am also getting stable result with the changes above, even without defrag. It went up to 225k payments, but then this happened in the logs:

lnd-alice_1   | {"level":"warn","ts":"2021-07-09T20:32:15.269Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-36af7f85-212a-4c07-a0cb-d8a0282a9cea/etcd-alice:2379","attempt":0,"error":"rpc error: code = ResourceExhausted desc = etcdserver: mvcc: database space exceeded"}
lnd-alice_1   | 2021-07-09 20:32:15.269 [ERR] CRTR: Failed to update mission control store: etcd error: stm.Commit() failed - etcdserver: mvcc: database space exceeded

(repeating)

I thought that the disk is full, but that doesn't appear to be the case. Maybe this is because defrag isn't running?

Copy link
Member

@Roasbeef Roasbeef left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Very cool set of optimizations!

There's definitely a lot we can do here to improve the underlying data model of the KV interface as well as implementations of certain major data stores. I think we should be careful here though to not over invest in what may be incremental performance improvements from the PoV of external performance, and also to not force the interfaces to grow in order to accommodate some of these optimizations (like the caller needing to know what to prefetch, etc).

I'm also apprehensive to to force migrations to re-order the bucket structures for bolt, etc when lately we can avoid them mainly by just relying on TLV blobs appended to certain values.

With that said, I think a lot of what's in this PR are easy wins including: the optimization of the borked check (runs each time we need to update a commitment, may very well just be in memory), the batch allocation of sequence numbers, delayed mission control syncing (as it's non-critical really), and the improved commit queue for etcd.

kvdb/etcd/stm.go Outdated Show resolved Hide resolved
kvdb/etcd/commit_queue.go Outdated Show resolved Hide resolved
// Prefetch will prefetch keys (exact match) and ranges (prefix match).
// So that subsequent fetches for those keys and keys in ranges don't
// go the the DB.
Prefetch(keys []string, ranges []string)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, this seems to be leaking too much information about the underlying semantics of the database to the caller. Why not just hide it further underneath the existing API? Also not clear if this extended bucket is useful for anything other than the etcd optimizations implemented in this PR.

Same goes for the methods below as well, which forces a distinction between range/bucket/value keys.

kvdb/etcd/readwrite_bucket.go Outdated Show resolved Hide resolved
channeldb/channel.go Outdated Show resolved Hide resolved
@@ -67,31 +67,31 @@ var (

// paymentSequenceKey is a key used in the payment's sub-bucket to
// store the sequence number of the payment.
paymentSequenceKey = []byte("payment-sequence-key")
paymentSequenceKey = []byte("s") // "payment-sequence-key"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Isn't all this a breaking change? Also IIRC, for etcd we hashed these keys down anyway.

kvdb/etcd/readwrite_cursor.go Outdated Show resolved Hide resolved

// Set a new upper bound in the DB every 1000 payments to avoid
// conflicts on the sequence when using etcd.
if p.currPaymentSeq == p.storedPaymentSeq {

This comment was marked as resolved.

@Roasbeef
Copy link
Member

Roasbeef commented Jul 9, 2021

I thought that the disk is full, but that doesn't appear to be the case. Maybe this is because defrag isn't running?

IIRC, the version compaction is auto, but the defrag needs to happen manually? A few weeks ago we defragged the Pool database, and reclaimed gigabytes in one swoop.

How do you know for sure that the settings above guarantee that an error like too many operations in txn request will never happen?

One of those things where you kinda just need to "set it high enough to hopefully never happen"...

@joostjager
Copy link
Contributor

I ran again with defrag in the background, but got this:

lnd-alice_1   | 2021-07-09 21:01:03.946 [ERR] CRTR: Failed sending attempt 96697 for payment 4c66d4fbd719727f897481c3346fef3403f015cb0d8b83f01ab54b0a84abf40e to switch: etcd error: stm.Commit() failed - etcdserver: request timed out
lnd-alice_1   | 2021-07-09 21:01:03.946 [WRN] CRTR: Attempt 96697 for payment 4c66d4fbd719727f897481c3346fef3403f015cb0d8b83f01ab54b0a84abf40e failed: etcd error: stm.Commit() failed - etcdserver: request timed out
lnd-alice_1   | {"level":"warn","ts":"2021-07-09T21:01:03.946Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-7d6c3568-3a3e-4579-84f4-d0d3926d37b4/etcd-alice:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: request timed out"}
lnd-alice_1   | {"level":"warn","ts":"2021-07-09T21:01:03.946Z","caller":"clientv3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"endpoint://client-7d6c3568-3a3e-4579-84f4-d0d3926d37b4/etcd-alice:2379","attempt":0,"error":"rpc error: code = Unavailable desc = etcdserver: request timed out"}
lnd-alice_1   | 2021-07-09 21:01:03.946 [ERR] HSWC: unable to commit circuit in switch: etcd error: stm.Commit() failed - etcdserver: request timed out

@joostjager
Copy link
Contributor

One of those things where you kinda just need to "set it high enough to hopefully never happen"...

Doesn't sound good to me.

@Roasbeef
Copy link
Member

Roasbeef commented Jul 10, 2021

Also let's update this to etcd 3.5 so we inherit their bug fixes and performance optimizations?

@joostjager
Copy link
Contributor

I am testing on etcd 3.5.

Defrag worked for a few times (in the endless loop provided above), but then started failing:

{"level":"warn","ts":"2021-07-09T20:55:52.949Z","logger":"etcd-client","caller":"v3/retry_interceptor.go:62","msg":"retrying of unary invoker failed","target":"etcd-endpoints://0xc000236000/#initially=[127.0.0.1:2379]","attempt":0,"error":"rpc error: code = DeadlineExceeded desc = context deadline exceeded"}
Failed to defragment etcd member[127.0.0.1:2379] (context deadline exceeded)

@bhandras
Copy link
Collaborator Author

bhandras commented Aug 18, 2021

Did run some new tests using the bottlepay benchmark suite. These are interesting because since this PR has been started, we did a lot of changes and now all state is in the remote DB. Median performance is around stable 31 TPS, sometimes fluctuating upwards to a maximum of ~68TPS. Machine: AX-41V-nvme.

I did use etcd 3.5, autocompact every 1000 revisions.

 etcd-alice:
    restart: unless-stopped
    image: 'bitnami/etcd:3.5.0'
    environment:
      - ALLOW_NONE_AUTHENTICATION=yes
      - ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_ADVERTISE_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_MAX_TXN_OPS=16384
      - ETCD_MAX_REQUEST_BYTES=104857600
      - ETCD_LOG_LEVEL=error
      - ETCD_AUTO_COMPACTION_MODE=revision
      - ETCD_AUTO_COMPACTION_RETENTION=1000

  etcd-bob:
    restart: unless-stopped
    image: 'bitnami/etcd:3.5.0'
    environment:
      - ALLOW_NONE_AUTHENTICATION=yes
      - ETCD_LISTEN_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_ADVERTISE_CLIENT_URLS=http://0.0.0.0:2379
      - ETCD_MAX_TXN_OPS=16384
      - ETCD_MAX_REQUEST_BYTES=104857600
      - ETCD_LOG_LEVEL=error
      - ETCD_AUTO_COMPACTION_MODE=revision
      - ETCD_AUTO_COMPACTION_RETENTION=1000

Defragged alice every 5 minutes since we put in a lot of revisions over time:
for i in {1..100} ; do docker exec -it lightning-benchmark_etcd-alice_1 etcdctl defrag ; sleep 5m; done
It seems like sometimes after defrag performance increases slightly for some time (not always).

loadtest_1    | 2021-08-18T15:29:21.344Z        INFO    Speed   {"tps": 63.792398362775344, "count": 1000, "avg_latency_sec": 1.439278468956}
loadtest_1    | 2021-08-18T15:29:35.915Z        INFO    Speed   {"tps": 68.62923821022974, "count": 2000, "avg_latency_sec": 1.461414870087}
loadtest_1    | 2021-08-18T15:29:50.541Z        INFO    Speed   {"tps": 68.3716974868165, "count": 3000, "avg_latency_sec": 1.466783421652}
loadtest_1    | 2021-08-18T15:30:05.161Z        INFO    Speed   {"tps": 68.40180540072656, "count": 4000, "avg_latency_sec": 1.4671189251149999}
loadtest_1    | 2021-08-18T15:30:19.856Z        INFO    Speed   {"tps": 68.05042197595078, "count": 5000, "avg_latency_sec": 1.461194384414}
loadtest_1    | 2021-08-18T15:30:34.477Z        INFO    Speed   {"tps": 68.3937398780924, "count": 6000, "avg_latency_sec": 1.470667363068}
loadtest_1    | 2021-08-18T15:30:49.205Z        INFO    Speed   {"tps": 67.89937574117872, "count": 7000, "avg_latency_sec": 1.466219509992}
loadtest_1    | 2021-08-18T15:31:06.459Z        INFO    Speed   {"tps": 57.956484812090615, "count": 8000, "avg_latency_sec": 1.658493377246}
loadtest_1    | 2021-08-18T15:31:38.367Z        INFO    Speed   {"tps": 31.340226280428997, "count": 9000, "avg_latency_sec": 3.158771859813}
loadtest_1    | 2021-08-18T15:32:10.325Z        INFO    Speed   {"tps": 31.29065805728842, "count": 10000, "avg_latency_sec": 3.2006127466409997}
loadtest_1    | 2021-08-18T15:32:41.826Z        INFO    Speed   {"tps": 31.745838833119887, "count": 11000, "avg_latency_sec": 3.169674658471}
loadtest_1    | 2021-08-18T15:33:14.081Z        INFO    Speed   {"tps": 31.002987371967848, "count": 12000, "avg_latency_sec": 3.2190729327549996}
loadtest_1    | 2021-08-18T15:33:46.363Z        INFO    Speed   {"tps": 30.976715595333328, "count": 13000, "avg_latency_sec": 3.196851235741}
loadtest_1    | 2021-08-18T15:34:20.371Z        INFO    Speed   {"tps": 29.40504622448875, "count": 14000, "avg_latency_sec": 3.428409899241}
loadtest_1    | 2021-08-18T15:34:52.836Z        INFO    Speed   {"tps": 30.8025899722752, "count": 15000, "avg_latency_sec": 3.2094332083989996}
loadtest_1    | 2021-08-18T15:35:24.387Z        INFO    Speed   {"tps": 31.694858754477103, "count": 16000, "avg_latency_sec": 3.187884269769}
loadtest_1    | 2021-08-18T15:35:56.206Z        INFO    Speed   {"tps": 31.42794601935979, "count": 17000, "avg_latency_sec": 3.183606547332}
loadtest_1    | 2021-08-18T15:36:28.224Z        INFO    Speed   {"tps": 31.23255822763467, "count": 18000, "avg_latency_sec": 3.182797376361}
loadtest_1    | 2021-08-18T15:36:59.478Z        INFO    Speed   {"tps": 31.996007499277095, "count": 19000, "avg_latency_sec": 3.158462890634}
loadtest_1    | 2021-08-18T15:37:32.071Z        INFO    Speed   {"tps": 30.68136645849088, "count": 20000, "avg_latency_sec": 3.2306827971920002}
loadtest_1    | 2021-08-18T15:38:04.040Z        INFO    Speed   {"tps": 31.2803170054304, "count": 21000, "avg_latency_sec": 3.204074627037}
loadtest_1    | 2021-08-18T15:38:35.501Z        INFO    Speed   {"tps": 31.785302407440618, "count": 22000, "avg_latency_sec": 3.149968119426}
loadtest_1    | 2021-08-18T15:39:09.566Z        INFO    Speed   {"tps": 29.355538496653555, "count": 23000, "avg_latency_sec": 3.410476867435}
loadtest_1    | 2021-08-18T15:39:40.755Z        INFO    Speed   {"tps": 32.06316659180463, "count": 24000, "avg_latency_sec": 3.11681247519}
loadtest_1    | 2021-08-18T15:40:12.568Z        INFO    Speed   {"tps": 31.43358764862669, "count": 25000, "avg_latency_sec": 3.184946277521}
loadtest_1    | 2021-08-18T15:40:44.531Z        INFO    Speed   {"tps": 31.286268635268616, "count": 26000, "avg_latency_sec": 3.1954867940250002}
loadtest_1    | 2021-08-18T15:41:16.159Z        INFO    Speed   {"tps": 31.617324962370297, "count": 27000, "avg_latency_sec": 3.16748173954}
loadtest_1    | 2021-08-18T15:41:48.359Z        INFO    Speed   {"tps": 31.05610490373948, "count": 28000, "avg_latency_sec": 3.200406800626}
loadtest_1    | 2021-08-18T15:42:20.455Z        INFO    Speed   {"tps": 31.15661705729048, "count": 29000, "avg_latency_sec": 3.1997766848599998}
loadtest_1    | 2021-08-18T15:42:52.854Z        INFO    Speed   {"tps": 30.865395727431604, "count": 30000, "avg_latency_sec": 3.252128149578}
loadtest_1    | 2021-08-18T15:43:24.621Z        INFO    Speed   {"tps": 31.479178727616908, "count": 31000, "avg_latency_sec": 3.182249840175}
loadtest_1    | 2021-08-18T15:43:56.877Z        INFO    Speed   {"tps": 31.00146970307399, "count": 32000, "avg_latency_sec": 3.218041212306}
loadtest_1    | 2021-08-18T15:44:31.813Z        INFO    Speed   {"tps": 28.62413232980801, "count": 33000, "avg_latency_sec": 3.5067252252479997}
loadtest_1    | 2021-08-18T15:45:03.763Z        INFO    Speed   {"tps": 31.29854908870298, "count": 34000, "avg_latency_sec": 3.188473612755}
loadtest_1    | 2021-08-18T15:45:35.146Z        INFO    Speed   {"tps": 31.865248088987162, "count": 35000, "avg_latency_sec": 3.167641516898}
loadtest_1    | 2021-08-18T15:46:07.161Z        INFO    Speed   {"tps": 31.234980855650285, "count": 36000, "avg_latency_sec": 3.17830488612}
loadtest_1    | 2021-08-18T15:46:38.905Z        INFO    Speed   {"tps": 31.502429364213615, "count": 37000, "avg_latency_sec": 3.1713710856349997}
loadtest_1    | 2021-08-18T15:47:10.904Z        INFO    Speed   {"tps": 31.25062533575537, "count": 38000, "avg_latency_sec": 3.196196640642}
loadtest_1    | 2021-08-18T15:47:42.954Z        INFO    Speed   {"tps": 31.201942089176953, "count": 39000, "avg_latency_sec": 3.2205158883549996}
loadtest_1    | 2021-08-18T15:48:14.712Z        INFO    Speed   {"tps": 31.48745992188015, "count": 40000, "avg_latency_sec": 3.1735878530169996}
loadtest_1    | 2021-08-18T15:48:46.764Z        INFO    Speed   {"tps": 31.19929249676398, "count": 41000, "avg_latency_sec": 3.1915490199770002}
loadtest_1    | 2021-08-18T15:49:21.722Z        INFO    Speed   {"tps": 28.606339556151763, "count": 42000, "avg_latency_sec": 3.4762675375570002}
loadtest_1    | 2021-08-18T15:49:53.651Z        INFO    Speed   {"tps": 31.319390714531128, "count": 43000, "avg_latency_sec": 3.214591579853}
loadtest_1    | 2021-08-18T15:50:25.760Z        INFO    Speed   {"tps": 31.14351320136618, "count": 44000, "avg_latency_sec": 3.2099215851180003}
loadtest_1    | 2021-08-18T15:50:57.659Z        INFO    Speed   {"tps": 31.349484096230597, "count": 45000, "avg_latency_sec": 3.19556962811}
loadtest_1    | 2021-08-18T15:51:29.541Z        INFO    Speed   {"tps": 31.36595635807548, "count": 46000, "avg_latency_sec": 3.183929785167}
loadtest_1    | 2021-08-18T15:52:00.807Z        INFO    Speed   {"tps": 31.983673687619802, "count": 47000, "avg_latency_sec": 3.136523635104}
loadtest_1    | 2021-08-18T15:52:32.400Z        INFO    Speed   {"tps": 31.65245604879034, "count": 48000, "avg_latency_sec": 3.163617639821}
loadtest_1    | 2021-08-18T15:53:04.414Z        INFO    Speed   {"tps": 31.236156572713163, "count": 49000, "avg_latency_sec": 3.178541688506}
loadtest_1    | 2021-08-18T15:53:36.640Z        INFO    Speed   {"tps": 31.03095675081032, "count": 50000, "avg_latency_sec": 3.233428799929}
loadtest_1    | 2021-08-18T15:54:12.415Z        INFO    Speed   {"tps": 27.952465755142587, "count": 51000, "avg_latency_sec": 3.510325761562}
loadtest_1    | 2021-08-18T15:54:44.186Z        INFO    Speed   {"tps": 31.47585206596665, "count": 52000, "avg_latency_sec": 3.239649383982}
loadtest_1    | 2021-08-18T15:55:15.854Z        INFO    Speed   {"tps": 31.57735316613526, "count": 53000, "avg_latency_sec": 3.161894277973}
loadtest_1    | 2021-08-18T15:55:47.974Z        INFO    Speed   {"tps": 31.13351380050201, "count": 54000, "avg_latency_sec": 3.2238728643630004}
loadtest_1    | 2021-08-18T15:56:19.638Z        INFO    Speed   {"tps": 31.58101704001329, "count": 55000, "avg_latency_sec": 3.151471388364}
loadtest_1    | 2021-08-18T15:56:51.456Z        INFO    Speed   {"tps": 31.42925732308286, "count": 56000, "avg_latency_sec": 3.218999302011}
loadtest_1    | 2021-08-18T15:57:26.338Z        INFO    Speed   {"tps": 28.668162984519427, "count": 57000, "avg_latency_sec": 3.167127004313}
loadtest_1    | 2021-08-18T15:57:57.897Z        INFO    Speed   {"tps": 31.686690381943322, "count": 58000, "avg_latency_sec": 3.439858256552}
loadtest_1    | 2021-08-18T15:58:29.390Z        INFO    Speed   {"tps": 31.75306794162205, "count": 59000, "avg_latency_sec": 3.1725709033980003}
loadtest_1    | 2021-08-18T15:59:02.688Z        INFO    Speed   {"tps": 30.032203677058455, "count": 60000, "avg_latency_sec": 3.2510869138180003}
loadtest_1    | 2021-08-18T15:59:38.140Z        INFO    Speed   {"tps": 28.206852751131084, "count": 61000, "avg_latency_sec": 3.594355175735}
loadtest_1    | 2021-08-18T16:00:09.760Z        INFO    Speed   {"tps": 31.6259097597675, "count": 62000, "avg_latency_sec": 3.188217428552}
loadtest_1    | 2021-08-18T16:00:41.657Z        INFO    Speed   {"tps": 31.35101321538809, "count": 63000, "avg_latency_sec": 3.174169634893}
loadtest_1    | 2021-08-18T16:01:13.266Z        INFO    Speed   {"tps": 31.636498106712125, "count": 64000, "avg_latency_sec": 3.163671763548}
loadtest_1    | 2021-08-18T16:01:44.882Z        INFO    Speed   {"tps": 31.62969118796956, "count": 65000, "avg_latency_sec": 3.159605776726}
loadtest_1    | 2021-08-18T16:02:16.159Z        INFO    Speed   {"tps": 31.972424746409878, "count": 66000, "avg_latency_sec": 3.126620405312}
loadtest_1    | 2021-08-18T16:02:44.952Z        INFO    Speed   {"tps": 34.73049100223041, "count": 67000, "avg_latency_sec": 2.952689166176
loadtest_1    | 2021-08-18T16:03:05.168Z        INFO    Speed   {"tps": 49.46481115006414, "count": 68000, "avg_latency_sec": 2.016812307668}
loadtest_1    | 2021-08-18T16:03:25.368Z        INFO    Speed   {"tps": 49.50697644061663, "count": 69000, "avg_latency_sec": 2.029324394564}
loadtest_1    | 2021-08-18T16:03:45.742Z        INFO    Speed   {"tps": 49.08053206094344, "count": 70000, "avg_latency_sec": 2.023601342921}
loadtest_1    | 2021-08-18T16:04:14.401Z        INFO    Speed   {"tps": 34.89330806624594, "count": 71000, "avg_latency_sec": 2.762044630294}
loadtest_1    | 2021-08-18T16:04:45.070Z        INFO    Speed   {"tps": 32.606572826768215, "count": 72000, "avg_latency_sec": 3.1027094904199997}
loadtest_1    | 2021-08-18T16:05:16.858Z        INFO    Speed   {"tps": 31.45841249694066, "count": 73000, "avg_latency_sec": 3.189868136744}
loadtest_1    | 2021-08-18T16:05:48.787Z        INFO    Speed   {"tps": 31.319906186228444, "count": 74000, "avg_latency_sec": 3.1952189202529997}
loadtest_1    | 2021-08-18T16:06:20.819Z        INFO    Speed   {"tps": 31.21808213333756, "count": 75000, "avg_latency_sec": 3.193423857794}
loadtest_1    | 2021-08-18T16:06:52.675Z        INFO    Speed   {"tps": 31.39195320576828, "count": 76000, "avg_latency_sec": 3.18906480755}
loadtest_1    | 2021-08-18T16:07:24.845Z        INFO    Speed   {"tps": 31.084734929359307, "count": 77000, "avg_latency_sec": 3.1950325746029997}
loadtest_1    | 2021-08-18T16:07:53.376Z        INFO    Speed   {"tps": 35.04995337194997, "count": 78000, "avg_latency_sec": 2.945461335529}
loadtest_1    | 2021-08-18T16:08:13.819Z        INFO    Speed   {"tps": 48.91624428213282, "count": 79000, "avg_latency_sec": 2.037872371772}
loadtest_1    | 2021-08-18T16:08:34.206Z        INFO    Speed   {"tps": 49.04999932129761, "count": 80000, "avg_latency_sec": 2.034048262368}
loadtest_1    | 2021-08-18T16:08:54.195Z        INFO    Speed   {"tps": 50.02818129476006, "count": 81000, "avg_latency_sec": 2.002122193211}
loadtest_1    | 2021-08-18T16:09:28.305Z        INFO    Speed   {"tps": 29.317344772947656, "count": 82000, "avg_latency_sec": 3.359281304234}
loadtest_1    | 2021-08-18T16:09:59.082Z        INFO    Speed   {"tps": 32.49185129006592, "count": 83000, "avg_latency_sec": 3.080813960043}
loadtest_1    | 2021-08-18T16:10:29.695Z        INFO    Speed   {"tps": 32.66542408541091, "count": 84000, "avg_latency_sec": 3.052581438623}
loadtest_1    | 2021-08-18T16:11:01.575Z        INFO    Speed   {"tps": 31.3678728703202, "count": 85000, "avg_latency_sec": 3.193015480229}
loadtest_1    | 2021-08-18T16:11:33.622Z        INFO    Speed   {"tps": 31.203991453249582, "count": 86000, "avg_latency_sec": 3.19112523614}
loadtest_1    | 2021-08-18T16:12:05.332Z        INFO    Speed   {"tps": 31.536155904365017, "count": 87000, "avg_latency_sec": 3.191176559515}
loadtest_1    | 2021-08-18T16:12:41.152Z        INFO    Speed   {"tps": 27.917350836171604, "count": 88000, "avg_latency_sec": 3.542114613589}
loadtest_1    | 2021-08-18T16:13:01.207Z        INFO    Speed   {"tps": 49.864217151237526, "count": 89000, "avg_latency_sec": 2.0937528655229998}
loadtest_1    | 2021-08-18T16:13:21.367Z        INFO    Speed   {"tps": 49.60165149293865, "count": 90000, "avg_latency_sec": 2.0165356513490003}
loadtest_1    | 2021-08-18T16:13:44.526Z        INFO    Speed   {"tps": 43.180457155595136, "count": 91000, "avg_latency_sec": 2.288097703507}
loadtest_1    | 2021-08-18T16:14:15.793Z        INFO    Speed   {"tps": 31.982847128297585, "count": 92000, "avg_latency_sec": 3.062922591533}
loadtest_1    | 2021-08-18T16:14:47.077Z        INFO    Speed   {"tps": 31.965463102069673, "count": 93000, "avg_latency_sec": 3.1673397268429997}
loadtest_1    | 2021-08-18T16:15:19.190Z        INFO    Speed   {"tps": 31.13926463925921, "count": 94000, "avg_latency_sec": 3.208985291095}
loadtest_1    | 2021-08-18T16:15:50.463Z        INFO    Speed   {"tps": 31.976899172778303, "count": 95000, "avg_latency_sec": 3.1291739433570003}
loadtest_1    | 2021-08-18T16:16:22.164Z        INFO    Speed   {"tps": 31.54465055170413, "count": 96000, "avg_latency_sec": 3.151771497669}
loadtest_1    | 2021-08-18T16:16:53.898Z        INFO    Speed   {"tps": 31.512566085269015, "count": 97000, "avg_latency_sec": 3.1830585426769997}
loadtest_1    | 2021-08-18T16:17:25.963Z        INFO    Speed   {"tps": 31.186428529594163, "count": 98000, "avg_latency_sec": 3.210515827657}
loadtest_1    | 2021-08-18T16:17:56.305Z        INFO    Speed   {"tps": 32.957199412275216, "count": 99000, "avg_latency_sec": 3.1199099143540003}
loadtest_1    | 2021-08-18T16:18:11.015Z        INFO    Speed   {"tps": 67.98110597804074, "count": 100000, "avg_latency_sec": 1.4710317153880001}
loadtest_1    | 2021-08-18T16:18:25.974Z        INFO    Speed   {"tps": 66.85156472885049, "count": 101000, "avg_latency_sec": 1.496351689303}
loadtest_1    | 2021-08-18T16:18:40.622Z        INFO    Speed   {"tps": 68.2682331353444, "count": 102000, "avg_latency_sec": 1.469192855764}
loadtest_1    | 2021-08-18T16:18:57.104Z        INFO    Speed   {"tps": 60.673601941258106, "count": 103000, "avg_latency_sec": 1.612301560439}
loadtest_1    | 2021-08-18T16:19:28.019Z        INFO    Speed   {"tps": 32.34701147159956, "count": 104000, "avg_latency_sec": 3.058401692072}
loadtest_1    | 2021-08-18T16:19:56.951Z        INFO    Speed   {"tps": 34.563644196247054, "count": 105000, "avg_latency_sec": 2.8719866365030002}
loadtest_1    | 2021-08-18T16:20:29.019Z        INFO    Speed   {"tps": 31.184105242396058, "count": 106000, "avg_latency_sec": 3.189012887124}

@joostjager
Copy link
Contributor

I've also been working on a benchmark variation that includes a router node. The payments will take the A->B->C route. Perhaps it is interesting to take a look at that too to spot any bottlenecks in the forwarding logic.

https://github.com/bottlepay/lightning-benchmark/tree/etcd-updates-router

@bhandras
Copy link
Collaborator Author

bhandras commented Aug 19, 2021

I've also been working on a benchmark variation that includes a router node. The payments will take the A->B->C route. Perhaps it is interesting to take a look at that too to spot any bottlenecks in the forwarding logic.

https://github.com/bottlepay/lightning-benchmark/tree/etcd-updates-router

Got similiar performance. According to ctop the whole setup uses 2-3% sytem and 6-8% user space CPU. TPS again goes up after defrags (not always).

loadtest_1      | 2021-08-19T08:01:59.426Z      INFO    Speed   {"tps": 64.44689654201923, "count": 1000, "avg_latency_sec": 1.43518459316}
loadtest_1      | 2021-08-19T08:02:14.036Z      INFO    Speed   {"tps": 68.44457027598442, "count": 2000, "avg_latency_sec": 1.456652570091}
loadtest_1      | 2021-08-19T08:02:28.726Z      INFO    Speed   {"tps": 68.07378175146903, "count": 3000, "avg_latency_sec": 1.476677161041}
loadtest_1      | 2021-08-19T08:02:43.408Z      INFO    Speed   {"tps": 68.11233167611046, "count": 4000, "avg_latency_sec": 1.467800475251}
loadtest_1      | 2021-08-19T08:02:58.091Z      INFO    Speed   {"tps": 68.10449081060078, "count": 5000, "avg_latency_sec": 1.470063306049}
loadtest_1      | 2021-08-19T08:03:12.949Z      INFO    Speed   {"tps": 67.30523115859886, "count": 6000, "avg_latency_sec": 1.477675071559}
loadtest_1      | 2021-08-19T08:03:27.645Z      INFO    Speed   {"tps": 68.04575366236725, "count": 7000, "avg_latency_sec": 1.4792085738210001}
loadtest_1      | 2021-08-19T08:03:43.372Z      INFO    Speed   {"tps": 63.58622292375303, "count": 8000, "avg_latency_sec": 1.511410174505}
loadtest_1      | 2021-08-19T08:04:16.084Z      INFO    Speed   {"tps": 30.56971696590095, "count": 9000, "avg_latency_sec": 3.237296592682}
loadtest_1      | 2021-08-19T08:04:47.980Z      INFO    Speed   {"tps": 31.35190681793128, "count": 10000, "avg_latency_sec": 3.183784295737}
loadtest_1      | 2021-08-19T08:05:20.443Z      INFO    Speed   {"tps": 30.8036590882493, "count": 11000, "avg_latency_sec": 3.263160064394}
loadtest_1      | 2021-08-19T08:05:52.615Z      INFO    Speed   {"tps": 31.083594863693758, "count": 12000, "avg_latency_sec": 3.204784026716}
loadtest_1      | 2021-08-19T08:06:25.233Z      INFO    Speed   {"tps": 30.657749010738474, "count": 13000, "avg_latency_sec": 3.256024241574}
loadtest_1      | 2021-08-19T08:07:00.298Z      INFO    Speed   {"tps": 28.51873223408482, "count": 14000, "avg_latency_sec": 3.515915712263}
loadtest_1      | 2021-08-19T08:07:33.242Z      INFO    Speed   {"tps": 30.354163086519605, "count": 15000, "avg_latency_sec": 3.297672770761}
loadtest_1      | 2021-08-19T08:08:05.782Z      INFO    Speed   {"tps": 30.731469260783506, "count": 16000, "avg_latency_sec": 3.23238849777}
loadtest_1      | 2021-08-19T08:08:37.934Z      INFO    Speed   {"tps": 31.102686762338347, "count": 17000, "avg_latency_sec": 3.240841398873}
loadtest_1      | 2021-08-19T08:09:10.386Z      INFO    Speed   {"tps": 30.814386202059723, "count": 18000, "avg_latency_sec": 3.244554661749}
loadtest_1      | 2021-08-19T08:09:42.295Z      INFO    Speed   {"tps": 31.339105103516943, "count": 19000, "avg_latency_sec": 3.181594858492}
loadtest_1      | 2021-08-19T08:10:14.177Z      INFO    Speed   {"tps": 31.365722349598283, "count": 20000, "avg_latency_sec": 3.189913502125}
loadtest_1      | 2021-08-19T08:10:46.350Z      INFO    Speed   {"tps": 31.082293202477484, "count": 21000, "avg_latency_sec": 3.219003633104}
loadtest_1      | 2021-08-19T08:11:17.903Z      INFO    Speed   {"tps": 31.693317454449687, "count": 22000, "avg_latency_sec": 3.162662550495}
loadtest_1      | 2021-08-19T08:11:53.434Z      INFO    Speed   {"tps": 28.144543077391873, "count": 23000, "avg_latency_sec": 3.557175049761}
loadtest_1      | 2021-08-19T08:12:26.581Z      INFO    Speed   {"tps": 30.168111578527316, "count": 24000, "avg_latency_sec": 3.295021037767}
loadtest_1      | 2021-08-19T08:12:59.020Z      INFO    Speed   {"tps": 30.82696058810954, "count": 25000, "avg_latency_sec": 3.260491858003}
loadtest_1      | 2021-08-19T08:13:31.125Z      INFO    Speed   {"tps": 31.147875012499075, "count": 26000, "avg_latency_sec": 3.208562376483}
loadtest_1      | 2021-08-19T08:14:03.077Z      INFO    Speed   {"tps": 31.29696144959214, "count": 27000, "avg_latency_sec": 3.1821375308279998}
loadtest_1      | 2021-08-19T08:14:35.095Z      INFO    Speed   {"tps": 31.232840585635785, "count": 28000, "avg_latency_sec": 3.206386218698}
loadtest_1      | 2021-08-19T08:15:07.174Z      INFO    Speed   {"tps": 31.172747511055764, "count": 29000, "avg_latency_sec": 3.216965464623}
loadtest_1      | 2021-08-19T08:15:38.636Z      INFO    Speed   {"tps": 31.78501795848699, "count": 30000, "avg_latency_sec": 3.129817442151}
loadtest_1      | 2021-08-19T08:16:10.421Z      INFO    Speed   {"tps": 31.461327344231563, "count": 31000, "avg_latency_sec": 3.181516140872}
loadtest_1      | 2021-08-19T08:16:47.153Z      INFO    Speed   {"tps": 27.224258705307424, "count": 32000, "avg_latency_sec": 3.564531470691}
loadtest_1      | 2021-08-19T08:17:20.825Z      INFO    Speed   {"tps": 29.698244005566522, "count": 33000, "avg_latency_sec": 3.47808845385}
loadtest_1      | 2021-08-19T08:17:53.787Z      INFO    Speed   {"tps": 30.337848680552156, "count": 34000, "avg_latency_sec": 3.2982517620949996}
loadtest_1      | 2021-08-19T08:18:26.188Z      INFO    Speed   {"tps": 30.863369147557975, "count": 35000, "avg_latency_sec": 3.2324816945749997}
loadtest_1      | 2021-08-19T08:18:59.380Z      INFO    Speed   {"tps": 30.127498587648624, "count": 36000, "avg_latency_sec": 3.312401703367}
loadtest_1      | 2021-08-19T08:19:32.265Z      INFO    Speed   {"tps": 30.40959558693555, "count": 37000, "avg_latency_sec": 3.2997949126600004}
loadtest_1      | 2021-08-19T08:20:04.278Z      INFO    Speed   {"tps": 31.237166991846735, "count": 38000, "avg_latency_sec": 3.19947835837}
loadtest_1      | 2021-08-19T08:20:36.480Z      INFO    Speed   {"tps": 31.05448830060268, "count": 39000, "avg_latency_sec": 3.207689382046}
loadtest_1      | 2021-08-19T08:21:08.646Z      INFO    Speed   {"tps": 31.088908304015757, "count": 40000, "avg_latency_sec": 3.233908811056}
loadtest_1      | 2021-08-19T08:21:45.904Z      INFO    Speed   {"tps": 26.839577883779977, "count": 41000, "avg_latency_sec": 3.709651236176}
loadtest_1      | 2021-08-19T08:22:16.823Z      INFO    Speed   {"tps": 32.34263945935463, "count": 42000, "avg_latency_sec": 3.12201889262}
loadtest_1      | 2021-08-19T08:22:47.214Z      INFO    Speed   {"tps": 32.904203941167076, "count": 43000, "avg_latency_sec": 3.032879575982}
loadtest_1      | 2021-08-19T08:23:19.299Z      INFO    Speed   {"tps": 31.16765182342072, "count": 44000, "avg_latency_sec": 3.20819307205}
loadtest_1      | 2021-08-19T08:23:51.804Z      INFO    Speed   {"tps": 30.76485518232573, "count": 45000, "avg_latency_sec": 3.2566734203800003}
loadtest_1      | 2021-08-19T08:24:24.903Z      INFO    Speed   {"tps": 30.211810377734363, "count": 46000, "avg_latency_sec": 3.284497331352}
loadtest_1      | 2021-08-19T08:24:57.128Z      INFO    Speed   {"tps": 31.032648450338485, "count": 47000, "avg_latency_sec": 3.245511666637}
loadtest_1      | 2021-08-19T08:25:29.108Z      INFO    Speed   {"tps": 31.26945609107796, "count": 48000, "avg_latency_sec": 3.182342977832}
loadtest_1      | 2021-08-19T08:26:01.266Z      INFO    Speed   {"tps": 31.096615257231093, "count": 49000, "avg_latency_sec": 3.2127337077080003}
loadtest_1      | 2021-08-19T08:26:34.412Z      INFO    Speed   {"tps": 30.168834023236986, "count": 50000, "avg_latency_sec": 3.268533047291}
loadtest_1      | 2021-08-19T08:27:05.376Z      INFO    Speed   {"tps": 32.29588540554509, "count": 51000, "avg_latency_sec": 3.2054368891549996}
loadtest_1      | 2021-08-19T08:27:26.430Z      INFO    Speed   {"tps": 47.49703008741634, "count": 52000, "avg_latency_sec": 2.07741053518}
loadtest_1      | 2021-08-19T08:27:53.790Z      INFO    Speed   {"tps": 36.54969161719262, "count": 53000, "avg_latency_sec": 2.725785440787}
loadtest_1      | 2021-08-19T08:28:25.284Z      INFO    Speed   {"tps": 31.752003918960856, "count": 54000, "avg_latency_sec": 3.1434546127789997}
loadtest_1      | 2021-08-19T08:28:58.266Z      INFO    Speed   {"tps": 30.320443755608956, "count": 55000, "avg_latency_sec": 3.292613546533}
loadtest_1      | 2021-08-19T08:29:31.381Z      INFO    Speed   {"tps": 30.19700779973166, "count": 56000, "avg_latency_sec": 3.285623568826}
loadtest_1      | 2021-08-19T08:30:03.578Z      INFO    Speed   {"tps": 31.059628484541353, "count": 57000, "avg_latency_sec": 3.2454219993480002}
loadtest_1      | 2021-08-19T08:30:35.450Z      INFO    Speed   {"tps": 31.375398734615636, "count": 58000, "avg_latency_sec": 3.175669057868}
loadtest_1      | 2021-08-19T08:31:07.638Z      INFO    Speed   {"tps": 31.067375003914467, "count": 59000, "avg_latency_sec": 3.238258748348}
loadtest_1      | 2021-08-19T08:31:43.567Z      INFO    Speed   {"tps": 27.832536223138487, "count": 60000, "avg_latency_sec": 3.533069673185}
loadtest_1      | 2021-08-19T08:32:16.470Z      INFO    Speed   {"tps": 30.39227999894468, "count": 61000, "avg_latency_sec": 3.348436048816}
loadtest_1      | 2021-08-19T08:32:48.325Z      INFO    Speed   {"tps": 31.39288113046818, "count": 62000, "avg_latency_sec": 3.172371354751}
loadtest_1      | 2021-08-19T08:33:20.444Z      INFO    Speed   {"tps": 31.13439397300371, "count": 63000, "avg_latency_sec": 3.2070002867469998}
loadtest_1      | 2021-08-19T08:33:52.071Z      INFO    Speed   {"tps": 31.6186625036781, "count": 64000, "avg_latency_sec": 3.173462832958}
loadtest_1      | 2021-08-19T08:34:23.708Z      INFO    Speed   {"tps": 31.60778560732191, "count": 65000, "avg_latency_sec": 3.148020471776}
loadtest_1      | 2021-08-19T08:34:55.584Z      INFO    Speed   {"tps": 31.37180108634354, "count": 66000, "avg_latency_sec": 3.2011717909949997}
loadtest_1      | 2021-08-19T08:35:27.389Z      INFO    Speed   {"tps": 31.441525591342256, "count": 67000, "avg_latency_sec": 3.180156388188}
loadtest_1      | 2021-08-19T08:35:59.289Z      INFO    Speed   {"tps": 31.348329156913568, "count": 68000, "avg_latency_sec": 3.17730412257}
loadtest_1      | 2021-08-19T08:36:31.855Z      INFO    Speed   {"tps": 30.7072195141324, "count": 69000, "avg_latency_sec": 3.219648486748}
loadtest_1      | 2021-08-19T08:37:08.728Z      INFO    Speed   {"tps": 27.120171571469612, "count": 70000, "avg_latency_sec": 3.733766453745}
loadtest_1      | 2021-08-19T08:37:40.339Z      INFO    Speed   {"tps": 31.6345225626662, "count": 71000, "avg_latency_sec": 3.175357647354}
loadtest_1      | 2021-08-19T08:38:11.732Z      INFO    Speed   {"tps": 31.854446642116837, "count": 72000, "avg_latency_sec": 3.127471588533}
loadtest_1      | 2021-08-19T08:38:43.594Z      INFO    Speed   {"tps": 31.385346712521894, "count": 73000, "avg_latency_sec": 3.1767200493649996}
loadtest_1      | 2021-08-19T08:39:14.434Z      INFO    Speed   {"tps": 32.42527665131578, "count": 74000, "avg_latency_sec": 3.107128442005}
loadtest_1      | 2021-08-19T08:39:46.016Z      INFO    Speed   {"tps": 31.663494048681564, "count": 75000, "avg_latency_sec": 3.1431091629349996}
loadtest_1      | 2021-08-19T08:40:17.505Z      INFO    Speed   {"tps": 31.75710519657327, "count": 76000, "avg_latency_sec": 3.154030467333}
loadtest_1      | 2021-08-19T08:40:49.539Z      INFO    Speed   {"tps": 31.217512245230417, "count": 77000, "avg_latency_sec": 3.180844551325}
loadtest_1      | 2021-08-19T08:41:21.255Z      INFO    Speed   {"tps": 31.52925382571174, "count": 78000, "avg_latency_sec": 3.185414694515}
loadtest_1      | 2021-08-19T08:41:59.574Z      INFO    Speed   {"tps": 26.097115225736324, "count": 79000, "avg_latency_sec": 3.796034223189}
loadtest_1      | 2021-08-19T08:42:36.938Z      INFO    Speed   {"tps": 26.76347105929678, "count": 80000, "avg_latency_sec": 3.6873292890930003}
loadtest_1      | 2021-08-19T08:42:54.293Z      INFO    Speed   {"tps": 57.62155494736531, "count": 81000, "avg_latency_sec": 1.911149838557}
loadtest_1      | 2021-08-19T08:43:09.118Z      INFO    Speed   {"tps": 67.45368105587109, "count": 82000, "avg_latency_sec": 1.491346747167}
loadtest_1      | 2021-08-19T08:43:23.958Z      INFO    Speed   {"tps": 67.3878802663505, "count": 83000, "avg_latency_sec": 1.477579601656}
loadtest_1      | 2021-08-19T08:43:42.513Z      INFO    Speed   {"tps": 53.89244880408587, "count": 84000, "avg_latency_sec": 1.811829216864}
loadtest_1      | 2021-08-19T08:44:06.408Z      INFO    Speed   {"tps": 41.85024197712609, "count": 85000, "avg_latency_sec": 2.38091627001}
loadtest_1      | 2021-08-19T08:44:35.202Z      INFO    Speed   {"tps": 34.72970358040773, "count": 86000, "avg_latency_sec": 2.829033848076}
loadtest_1      | 2021-08-19T08:45:07.348Z      INFO    Speed   {"tps": 31.10767964370807, "count": 87000, "avg_latency_sec": 3.229316936019}
loadtest_1      | 2021-08-19T08:45:39.271Z      INFO    Speed   {"tps": 31.32597591531312, "count": 88000, "avg_latency_sec": 3.187433856797}
loadtest_1      | 2021-08-19T08:46:11.700Z      INFO    Speed   {"tps": 30.83654342056137, "count": 89000, "avg_latency_sec": 3.249671558332}
loadtest_1      | 2021-08-19T08:46:48.798Z      INFO    Speed   {"tps": 26.955439360550315, "count": 90000, "avg_latency_sec": 3.637964310752}
loadtest_1      | 2021-08-19T08:47:22.523Z      INFO    Speed   {"tps": 29.651856329912313, "count": 91000, "avg_latency_sec": 3.446442658358}
loadtest_1      | 2021-08-19T08:47:52.032Z      INFO    Speed   {"tps": 33.88794306041426, "count": 92000, "avg_latency_sec": 3.041547257835}
loadtest_1      | 2021-08-19T08:48:06.777Z      INFO    Speed   {"tps": 67.81835049810404, "count": 93000, "avg_latency_sec": 1.464259901294}
loadtest_1      | 2021-08-19T08:48:21.648Z      INFO    Speed   {"tps": 67.24549917043038, "count": 94000, "avg_latency_sec": 1.495508909852}
loadtest_1      | 2021-08-19T08:48:36.912Z      INFO    Speed   {"tps": 65.51604356688145, "count": 95000, "avg_latency_sec": 1.4907924752189998}
loadtest_1      | 2021-08-19T08:48:57.264Z      INFO    Speed   {"tps": 49.135181574755336, "count": 96000, "avg_latency_sec": 2.041451738502}
loadtest_1      | 2021-08-19T08:49:22.295Z      INFO    Speed   {"tps": 39.95056456415973, "count": 97000, "avg_latency_sec": 2.443743097282}
loadtest_1      | 2021-08-19T08:49:54.460Z      INFO    Speed   {"tps": 31.089175507592632, "count": 98000, "avg_latency_sec": 3.2151944719110004}
loadtest_1      | 2021-08-19T08:49:54.460Z      INFO    Speed   {"tps": 31.089175507592632, "count": 98000, "avg_latency_sec": 3.2151944719110004}
loadtest_1      | 2021-08-19T08:50:26.608Z      INFO    Speed   {"tps": 31.106210880171492, "count": 99000, "avg_latency_sec": 3.225031018509}
loadtest_1      | 2021-08-19T08:50:58.626Z      INFO    Speed   {"tps": 31.232711860462235, "count": 100000, "avg_latency_sec": 3.192317168849}
loadtest_1      | 2021-08-19T08:51:30.565Z      INFO    Speed   {"tps": 31.3098943935904, "count": 101000, "avg_latency_sec": 3.198969402752}
loadtest_1      | 2021-08-19T08:52:09.173Z      INFO    Speed   {"tps": 25.901490096301107, "count": 102000, "avg_latency_sec": 3.837315603626}
loadtest_1      | 2021-08-19T08:52:46.475Z      INFO    Speed   {"tps": 26.808203945794016, "count": 103000, "avg_latency_sec": 3.778125888779}
loadtest_1      | 2021-08-19T08:53:01.213Z      INFO    Speed   {"tps": 67.85065468336099, "count": 104000, "avg_latency_sec": 1.5365244879689999}
loadtest_1      | 2021-08-19T08:53:16.235Z      INFO    Speed   {"tps": 66.56946981310875, "count": 105000, "avg_latency_sec": 1.4952415334079998}
loadtest_1      | 2021-08-19T08:53:31.137Z      INFO    Speed   {"tps": 67.10587872294577, "count": 106000, "avg_latency_sec": 1.492498915246}
loadtest_1      | 2021-08-19T08:53:47.782Z      INFO    Speed   {"tps": 60.07724471390072, "count": 107000, "avg_latency_sec": 1.641001468832}
loadtest_1      | 2021-08-19T08:54:15.974Z      INFO    Speed   {"tps": 35.471755254698245, "count": 108000, "avg_latency_sec": 2.782255065116}
loadtest_1      | 2021-08-19T08:54:46.641Z      INFO    Speed   {"tps": 32.608504004198196, "count": 109000, "avg_latency_sec": 3.042685552978}
loadtest_1      | 2021-08-19T08:55:18.646Z      INFO    Speed   {"tps": 31.24516248626988, "count": 110000, "avg_latency_sec": 3.1804918234810002}
loadtest_1      | 2021-08-19T08:55:50.928Z      INFO    Speed   {"tps": 30.976851643828528, "count": 111000, "avg_latency_sec": 3.236466943136}
loadtest_1      | 2021-08-19T08:56:22.701Z      INFO    Speed   {"tps": 31.473405895872606, "count": 112000, "avg_latency_sec": 3.1927354865910003}
loadtest_1      | 2021-08-19T08:57:02.739Z      INFO    Speed   {"tps": 24.976210843519723, "count": 113000, "avg_latency_sec": 3.984363017642}
loadtest_1      | 2021-08-19T08:57:34.217Z      INFO    Speed   {"tps": 31.768810231066702, "count": 114000, "avg_latency_sec": 3.165811820055}
loadtest_1      | 2021-08-19T08:58:02.957Z      INFO    Speed   {"tps": 34.794210623680776, "count": 115000, "avg_latency_sec": 2.9567295226340002}
loadtest_1      | 2021-08-19T08:58:17.876Z      INFO    Speed   {"tps": 67.02990570277775, "count": 116000, "avg_latency_sec": 1.4903769785699998}
loadtest_1      | 2021-08-19T08:58:32.843Z      INFO    Speed   {"tps": 66.813010213978, "count": 117000, "avg_latency_sec": 1.4988291825989999}
loadtest_1      | 2021-08-19T08:58:47.730Z      INFO    Speed   {"tps": 67.17136906566382, "count": 118000, "avg_latency_sec": 1.481818830383}
loadtest_1      | 2021-08-19T08:59:04.672Z      INFO    Speed   {"tps": 59.0256828864041, "count": 119000, "avg_latency_sec": 1.662838297343}
loadtest_1      | 2021-08-19T08:59:30.422Z      INFO    Speed   {"tps": 38.83581776350411, "count": 120000, "avg_latency_sec": 2.539786818194}
loadtest_1      | 2021-08-19T09:00:01.657Z      INFO    Speed   {"tps": 32.0147558345438, "count": 121000, "avg_latency_sec": 3.116753527287}
loadtest_1      | 2021-08-19T09:00:34.144Z      INFO    Speed   {"tps": 30.78195815042315, "count": 122000, "avg_latency_sec": 3.2415004046919997}
loadtest_1      | 2021-08-19T09:01:06.702Z      INFO    Speed   {"tps": 30.714748205095134, "count": 123000, "avg_latency_sec": 3.247035923066}

@bhandras
Copy link
Collaborator Author

Last two commits are still wip added for some additional testing. Above benchmark results are without those two.

@joostjager
Copy link
Contributor

Not bad those results with a routing node in the path.

@guggero
Copy link
Collaborator

guggero commented Aug 26, 2021

I ran the commit 5eb805cc with lnd-etcd-notls on my beefy machine (24 threads, 128GB RAM, 560k IOPS SSD):

loadtest_1    | 2021-08-26T11:44:00.593Z        INFO    Speed   {"tps": 177.69105557123507, "count": 1000, "avg_latency_sec": 0.5063927146589999}
loadtest_1    | 2021-08-26T11:44:05.743Z        INFO    Speed   {"tps": 194.18215886445967, "count": 2000, "avg_latency_sec": 0.511979358207}
loadtest_1    | 2021-08-26T11:44:10.926Z        INFO    Speed   {"tps": 192.94100914851327, "count": 3000, "avg_latency_sec": 0.5225050415729999}
loadtest_1    | 2021-08-26T11:44:16.056Z        INFO    Speed   {"tps": 194.92154691932114, "count": 4000, "avg_latency_sec": 0.510622662479}
loadtest_1    | 2021-08-26T11:44:21.270Z        INFO    Speed   {"tps": 191.79418933173915, "count": 5000, "avg_latency_sec": 0.5213774442489999}
loadtest_1    | 2021-08-26T11:44:26.492Z        INFO    Speed   {"tps": 191.50438705076985, "count": 6000, "avg_latency_sec": 0.5203092322180001}
loadtest_1    | 2021-08-26T11:44:31.752Z        INFO    Speed   {"tps": 190.12126062714893, "count": 7000, "avg_latency_sec": 0.528913576594}
loadtest_1    | 2021-08-26T11:44:36.975Z        INFO    Speed   {"tps": 191.45004672218732, "count": 8000, "avg_latency_sec": 0.5196531202050001}
loadtest_1    | 2021-08-26T11:44:42.213Z        INFO    Speed   {"tps": 190.93738219300755, "count": 9000, "avg_latency_sec": 0.5257845323620001}
loadtest_1    | 2021-08-26T11:44:47.426Z        INFO    Speed   {"tps": 191.81810635990325, "count": 10000, "avg_latency_sec": 0.51971002483}
loadtest_1    | 2021-08-26T11:44:52.641Z        INFO    Speed   {"tps": 191.7770796849586, "count": 11000, "avg_latency_sec": 0.520899661165}
loadtest_1    | 2021-08-26T11:44:57.856Z        INFO    Speed   {"tps": 191.74051847057257, "count": 12000, "avg_latency_sec": 0.521108361638}
loadtest_1    | 2021-08-26T11:45:03.487Z        INFO    Speed   {"tps": 177.602641460785, "count": 13000, "avg_latency_sec": 0.5636313050339999}
loadtest_1    | 2021-08-26T11:45:09.017Z        INFO    Speed   {"tps": 180.84013141090298, "count": 14000, "avg_latency_sec": 0.5527473299550001}
loadtest_1    | 2021-08-26T11:45:14.455Z        INFO    Speed   {"tps": 183.88565639766904, "count": 15000, "avg_latency_sec": 0.541819768201}
loadtest_1    | 2021-08-26T11:45:19.801Z        INFO    Speed   {"tps": 187.05220352482564, "count": 16000, "avg_latency_sec": 0.536853878681}
loadtest_1    | 2021-08-26T11:45:25.305Z        INFO    Speed   {"tps": 181.675110224524, "count": 17000, "avg_latency_sec": 0.550793115806}
loadtest_1    | 2021-08-26T11:45:30.793Z        INFO    Speed   {"tps": 182.22666604948438, "count": 18000, "avg_latency_sec": 0.550503266089}
loadtest_1    | 2021-08-26T11:45:36.260Z        INFO    Speed   {"tps": 182.91662803025434, "count": 19000, "avg_latency_sec": 0.542617385101}
loadtest_1    | 2021-08-26T11:45:41.645Z        INFO    Speed   {"tps": 185.72458578755683, "count": 20000, "avg_latency_sec": 0.534755494878}
loadtest_1    | 2021-08-26T11:45:47.141Z        INFO    Speed   {"tps": 181.94055526721525, "count": 21000, "avg_latency_sec": 0.555925637882}
loadtest_1    | 2021-08-26T11:45:52.557Z        INFO    Speed   {"tps": 184.62171066409886, "count": 22000, "avg_latency_sec": 0.5417716804310001}
loadtest_1    | 2021-08-26T11:45:57.944Z        INFO    Speed   {"tps": 185.65204603559127, "count": 23000, "avg_latency_sec": 0.5359541798899999}
loadtest_1    | 2021-08-26T11:46:03.295Z        INFO    Speed   {"tps": 186.8960797655214, "count": 24000, "avg_latency_sec": 0.537326135867}
loadtest_1    | 2021-08-26T11:46:09.231Z        INFO    Speed   {"tps": 168.45072940868872, "count": 25000, "avg_latency_sec": 0.587003079675}
loadtest_1    | 2021-08-26T11:46:14.974Z        INFO    Speed   {"tps": 174.12032736881625, "count": 26000, "avg_latency_sec": 0.58204492889}
loadtest_1    | 2021-08-26T11:46:20.689Z        INFO    Speed   {"tps": 174.99357441531586, "count": 27000, "avg_latency_sec": 0.570634454633}
loadtest_1    | 2021-08-26T11:46:26.806Z        INFO    Speed   {"tps": 163.47547924643553, "count": 28000, "avg_latency_sec": 0.6000763327099999}
loadtest_1    | 2021-08-26T11:46:33.388Z        INFO    Speed   {"tps": 151.93967411853802, "count": 29000, "avg_latency_sec": 0.6632680207280001}
loadtest_1    | 2021-08-26T11:46:39.481Z        INFO    Speed   {"tps": 164.11547225744636, "count": 30000, "avg_latency_sec": 0.612509585261}
loadtest_1    | 2021-08-26T11:46:46.969Z        INFO    Speed   {"tps": 133.55683171619128, "count": 31000, "avg_latency_sec": 0.7472780735410001}
loadtest_1    | 2021-08-26T11:46:53.345Z        INFO    Speed   {"tps": 156.83595141631127, "count": 32000, "avg_latency_sec": 0.639664382341}
loadtest_1    | 2021-08-26T11:46:59.108Z        INFO    Speed   {"tps": 173.50105375995128, "count": 33000, "avg_latency_sec": 0.576976371944}
loadtest_1    | 2021-08-26T11:47:04.711Z        INFO    Speed   {"tps": 178.50260086920065, "count": 34000, "avg_latency_sec": 0.5623213143310001}
loadtest_1    | 2021-08-26T11:47:10.639Z        INFO    Speed   {"tps": 168.6959886801631, "count": 35000, "avg_latency_sec": 0.569068280454}
loadtest_1    | 2021-08-26T11:47:16.335Z        INFO    Speed   {"tps": 175.5467007673623, "count": 36000, "avg_latency_sec": 0.58823608026}
loadtest_1    | 2021-08-26T11:47:22.394Z        INFO    Speed   {"tps": 165.03764591387156, "count": 37000, "avg_latency_sec": 0.6059949069230001}
loadtest_1    | 2021-08-26T11:47:29.119Z        INFO    Speed   {"tps": 148.70257286962627, "count": 38000, "avg_latency_sec": 0.663533461612}
loadtest_1    | 2021-08-26T11:47:36.022Z        INFO    Speed   {"tps": 144.8675221524396, "count": 39000, "avg_latency_sec": 0.699269091048}
loadtest_1    | 2021-08-26T11:47:42.214Z        INFO    Speed   {"tps": 161.51804997941565, "count": 40000, "avg_latency_sec": 0.621741156486}
loadtest_1    | 2021-08-26T11:47:47.903Z        INFO    Speed   {"tps": 175.7550377632248, "count": 41000, "avg_latency_sec": 0.570878741449}
loadtest_1    | 2021-08-26T11:47:53.632Z        INFO    Speed   {"tps": 174.554247164064, "count": 42000, "avg_latency_sec": 0.574336590082}
loadtest_1    | 2021-08-26T11:47:59.490Z        INFO    Speed   {"tps": 170.72279876408734, "count": 43000, "avg_latency_sec": 0.582348032209}
loadtest_1    | 2021-08-26T11:48:05.123Z        INFO    Speed   {"tps": 177.53923788837776, "count": 44000, "avg_latency_sec": 0.5656494571990001}
loadtest_1    | 2021-08-26T11:48:11.240Z        INFO    Speed   {"tps": 163.45951321074358, "count": 45000, "avg_latency_sec": 0.599825296729}
loadtest_1    | 2021-08-26T11:48:17.049Z        INFO    Speed   {"tps": 172.17038748530186, "count": 46000, "avg_latency_sec": 0.592266063657}
loadtest_1    | 2021-08-26T11:48:22.809Z        INFO    Speed   {"tps": 173.58711534444012, "count": 47000, "avg_latency_sec": 0.575721836346}
loadtest_1    | 2021-08-26T11:48:28.649Z        INFO    Speed   {"tps": 171.26215890511324, "count": 48000, "avg_latency_sec": 0.577011178039}
loadtest_1    | 2021-08-26T11:48:34.636Z        INFO    Speed   {"tps": 167.02180585621988, "count": 49000, "avg_latency_sec": 0.603552425059}
loadtest_1    | 2021-08-26T11:48:42.188Z        INFO    Speed   {"tps": 132.41756810804526, "count": 50000, "avg_latency_sec": 0.7523301221049999}
loadtest_1    | 2021-08-26T11:48:49.042Z        INFO    Speed   {"tps": 145.88643104017189, "count": 51000, "avg_latency_sec": 0.689844793426}
loadtest_1    | 2021-08-26T11:48:55.635Z        INFO    Speed   {"tps": 151.69081366035934, "count": 52000, "avg_latency_sec": 0.664929357442}
loadtest_1    | 2021-08-26T11:49:01.724Z        INFO    Speed   {"tps": 164.2374188778483, "count": 53000, "avg_latency_sec": 0.6023062513470001}
loadtest_1    | 2021-08-26T11:49:07.330Z        INFO    Speed   {"tps": 178.3627248182953, "count": 54000, "avg_latency_sec": 0.55598219767}
loadtest_1    | 2021-08-26T11:49:13.493Z        INFO    Speed   {"tps": 162.25755601932022, "count": 55000, "avg_latency_sec": 0.622277872042}
loadtest_1    | 2021-08-26T11:49:19.611Z        INFO    Speed   {"tps": 163.4645760593126, "count": 56000, "avg_latency_sec": 0.610461668348}
loadtest_1    | 2021-08-26T11:49:25.598Z        INFO    Speed   {"tps": 167.04127830944068, "count": 57000, "avg_latency_sec": 0.61403873021}
loadtest_1    | 2021-08-26T11:49:33.100Z        INFO    Speed   {"tps": 133.29750419054395, "count": 58000, "avg_latency_sec": 0.729755753801}
loadtest_1    | 2021-08-26T11:49:39.400Z        INFO    Speed   {"tps": 158.7151604246203, "count": 59000, "avg_latency_sec": 0.6373058841549999}
loadtest_1    | 2021-08-26T11:49:45.193Z        INFO    Speed   {"tps": 172.63087744380798, "count": 60000, "avg_latency_sec": 0.576814951554}
loadtest_1    | 2021-08-26T11:49:50.937Z        INFO    Speed   {"tps": 174.0943392071013, "count": 61000, "avg_latency_sec": 0.5742669738539999}
loadtest_1    | 2021-08-26T11:49:57.190Z        INFO    Speed   {"tps": 159.94391877419162, "count": 62000, "avg_latency_sec": 0.611279934869}
loadtest_1    | 2021-08-26T11:50:03.318Z        INFO    Speed   {"tps": 163.18715375634082, "count": 63000, "avg_latency_sec": 0.624296296689}
loadtest_1    | 2021-08-26T11:50:09.452Z        INFO    Speed   {"tps": 163.0281698714175, "count": 64000, "avg_latency_sec": 0.61645000953}
loadtest_1    | 2021-08-26T11:50:15.633Z        INFO    Speed   {"tps": 161.77017327885767, "count": 65000, "avg_latency_sec": 0.618948765825}
loadtest_1    | 2021-08-26T11:50:21.588Z        INFO    Speed   {"tps": 167.93587193942338, "count": 66000, "avg_latency_sec": 0.598824191969}
loadtest_1    | 2021-08-26T11:50:27.619Z        INFO    Speed   {"tps": 165.8201223308768, "count": 67000, "avg_latency_sec": 0.596678376556}
loadtest_1    | 2021-08-26T11:50:33.640Z        INFO    Speed   {"tps": 166.06315306417997, "count": 68000, "avg_latency_sec": 0.600850391613}
loadtest_1    | 2021-08-26T11:50:39.898Z        INFO    Speed   {"tps": 159.81463892711454, "count": 69000, "avg_latency_sec": 0.6236348479130001}
loadtest_1    | 2021-08-26T11:50:45.947Z        INFO    Speed   {"tps": 165.30455935672953, "count": 70000, "avg_latency_sec": 0.609062544664}
loadtest_1    | 2021-08-26T11:50:51.864Z        INFO    Speed   {"tps": 169.01706930087568, "count": 71000, "avg_latency_sec": 0.590023148652}
loadtest_1    | 2021-08-26T11:50:57.751Z        INFO    Speed   {"tps": 169.86433802988591, "count": 72000, "avg_latency_sec": 0.5896023291870001}
loadtest_1    | 2021-08-26T11:51:03.941Z        INFO    Speed   {"tps": 161.56479025350504, "count": 73000, "avg_latency_sec": 0.606056234958}
loadtest_1    | 2021-08-26T11:51:11.322Z        INFO    Speed   {"tps": 135.48699741237354, "count": 74000, "avg_latency_sec": 0.7414013250960001}
loadtest_1    | 2021-08-26T11:51:17.404Z        INFO    Speed   {"tps": 164.4168155168543, "count": 75000, "avg_latency_sec": 0.618619275311}
loadtest_1    | 2021-08-26T11:51:23.284Z        INFO    Speed   {"tps": 170.0726607942494, "count": 76000, "avg_latency_sec": 0.590611262048}
loadtest_1    | 2021-08-26T11:51:29.138Z        INFO    Speed   {"tps": 170.80925320990977, "count": 77000, "avg_latency_sec": 0.584904135594}
loadtest_1    | 2021-08-26T11:51:34.840Z        INFO    Speed   {"tps": 175.38060603232472, "count": 78000, "avg_latency_sec": 0.569876913757}
loadtest_1    | 2021-08-26T11:51:40.934Z        INFO    Speed   {"tps": 164.0909146506822, "count": 79000, "avg_latency_sec": 0.608061197147}
loadtest_1    | 2021-08-26T11:51:47.110Z        INFO    Speed   {"tps": 161.9219304361563, "count": 80000, "avg_latency_sec": 0.6158667159819999}
loadtest_1    | 2021-08-26T11:51:53.150Z        INFO    Speed   {"tps": 165.56877169753298, "count": 81000, "avg_latency_sec": 0.6019375045609999}
loadtest_1    | 2021-08-26T11:51:59.155Z        INFO    Speed   {"tps": 166.51909930033, "count": 82000, "avg_latency_sec": 0.606324461753}
loadtest_1    | 2021-08-26T11:52:06.049Z        INFO    Speed   {"tps": 145.06483707273333, "count": 83000, "avg_latency_sec": 0.673507313144}
loadtest_1    | 2021-08-26T11:52:13.418Z        INFO    Speed   {"tps": 135.7017335908408, "count": 84000, "avg_latency_sec": 0.749037678284}
loadtest_1    | 2021-08-26T11:52:19.508Z        INFO    Speed   {"tps": 164.20450112511463, "count": 85000, "avg_latency_sec": 0.6127483137409999}
loadtest_1    | 2021-08-26T11:52:25.652Z        INFO    Speed   {"tps": 162.76213968299595, "count": 86000, "avg_latency_sec": 0.630602334962}
loadtest_1    | 2021-08-26T11:52:32.228Z        INFO    Speed   {"tps": 152.07421790713101, "count": 87000, "avg_latency_sec": 0.629304568112}
loadtest_1    | 2021-08-26T11:52:38.699Z        INFO    Speed   {"tps": 154.53328120730015, "count": 88000, "avg_latency_sec": 0.6565551978790001}
loadtest_1    | 2021-08-26T11:52:45.324Z        INFO    Speed   {"tps": 150.93818802734418, "count": 89000, "avg_latency_sec": 0.6542107006500001}
loadtest_1    | 2021-08-26T11:52:51.862Z        INFO    Speed   {"tps": 152.97115720310444, "count": 90000, "avg_latency_sec": 0.660884206777}
loadtest_1    | 2021-08-26T11:52:58.177Z        INFO    Speed   {"tps": 158.34618258371432, "count": 91000, "avg_latency_sec": 0.6345039939680001}
loadtest_1    | 2021-08-26T11:53:04.530Z        INFO    Speed   {"tps": 157.41634175262087, "count": 92000, "avg_latency_sec": 0.630586998997}
loadtest_1    | 2021-08-26T11:53:12.085Z        INFO    Speed   {"tps": 132.36046063458002, "count": 93000, "avg_latency_sec": 0.7496223399540001}
loadtest_1    | 2021-08-26T11:53:18.816Z        INFO    Speed   {"tps": 148.561042599329, "count": 94000, "avg_latency_sec": 0.683957343285}
loadtest_1    | 2021-08-26T11:53:24.780Z        INFO    Speed   {"tps": 167.67521334515433, "count": 95000, "avg_latency_sec": 0.600361614546}
loadtest_1    | 2021-08-26T11:53:30.915Z        INFO    Speed   {"tps": 163.0072331241936, "count": 96000, "avg_latency_sec": 0.603975951508}
loadtest_1    | 2021-08-26T11:53:36.955Z        INFO    Speed   {"tps": 165.5724128843324, "count": 97000, "avg_latency_sec": 0.606270065653}
loadtest_1    | 2021-08-26T11:53:43.292Z        INFO    Speed   {"tps": 157.805346110137, "count": 98000, "avg_latency_sec": 0.6371194566530001}
loadtest_1    | 2021-08-26T11:53:49.999Z        INFO    Speed   {"tps": 149.0998419915468, "count": 99000, "avg_latency_sec": 0.6718651326499999}
loadtest_1    | 2021-08-26T11:53:57.073Z        INFO    Speed   {"tps": 141.36871897359077, "count": 100000, "avg_latency_sec": 0.6975987180969999}
loadtest_1    | 2021-08-26T11:54:04.680Z        INFO    Speed   {"tps": 131.45618054519107, "count": 101000, "avg_latency_sec": 0.7515626451849999}
loadtest_1    | 2021-08-26T11:54:11.876Z        INFO    Speed   {"tps": 138.96444406943624, "count": 102000, "avg_latency_sec": 0.736854534497}
loadtest_1    | 2021-08-26T11:54:18.188Z        INFO    Speed   {"tps": 158.4147901867644, "count": 103000, "avg_latency_sec": 0.630425556509}
loadtest_1    | 2021-08-26T11:54:24.050Z        INFO    Speed   {"tps": 170.59874848614808, "count": 104000, "avg_latency_sec": 0.588124501177}
loadtest_1    | 2021-08-26T11:54:29.961Z        INFO    Speed   {"tps": 169.19812881366428, "count": 105000, "avg_latency_sec": 0.5878315566060001}
loadtest_1    | 2021-08-26T11:54:35.920Z        INFO    Speed   {"tps": 167.79697485972108, "count": 106000, "avg_latency_sec": 0.583646414138}
loadtest_1    | 2021-08-26T11:54:42.062Z        INFO    Speed   {"tps": 162.82833481920568, "count": 107000, "avg_latency_sec": 0.6215892375600001}
loadtest_1    | 2021-08-26T11:54:48.155Z        INFO    Speed   {"tps": 164.1122757250502, "count": 108000, "avg_latency_sec": 0.609761263104}
loadtest_1    | 2021-08-26T11:54:54.133Z        INFO    Speed   {"tps": 167.28052608794036, "count": 109000, "avg_latency_sec": 0.60406583823}
loadtest_1    | 2021-08-26T11:55:00.857Z        INFO    Speed   {"tps": 148.73333022547106, "count": 110000, "avg_latency_sec": 0.666465630817}

@joostjager
Copy link
Contributor

That was fast. Curious to what happens when you let it run to 1M payments which should only take around an hour on your box it seems.

Another interesting thing would be to run it with replicated etcd, which may be closer to a production setup?

@orijbot
Copy link

orijbot commented Sep 10, 2021

@Roasbeef Roasbeef removed the request for review from yyforyongyu September 16, 2021 00:50
This commits adds a new generic Cache to kvdb which is capable of
prefetching large buckets recursively while skipping arbitrary buckets
at the same time. This mechanism lets us use such cache for buckets that
don't grow indefinitely but are accessed very frequently, essentially
reducing DB operations to just the puts and deletes.
@lightninglabs-deploy
Copy link

@bhandras, remember to re-request review from reviewers for your latest update

@bhandras
Copy link
Collaborator Author

bhandras commented Dec 7, 2021

Closing this PR as most of the fixes have been merged already and the rest can be tracked separately.

@bhandras bhandras closed this Dec 7, 2021
@bhandras bhandras deleted the etcd_improvements branch September 12, 2023 15:27
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

6 participants