cache decrypted content based on record buffer #349

staltz · 2022-06-08T13:54:48Z

This is a just-FYI PR. I ran unit tests (e.g. test/private.js) and confirmed that the cache causes the decryption to be skipped if it has been already done.

In the big picture though, unfortunately it doesn't seem like caching does any difference to performance. In fact in some cases it seems like performance got worse. I don't understand why. :(

I'm leaving this PR here in case I made a dumb mistake somewhere and there would still be hope for this optimization technique.

Numbers below

Perf test	Before	After
add a bunch of messages	530ms	530ms
box1	1132ms	1125ms
unbox first run	105ms	115ms
unbox second run	91ms	89ms
private box1 no decrypt, box	1117ms	1021ms
query first run	35ms	30ms
query second run	20ms	23ms
private box2, box	603ms	552ms
unbox duration first run	314ms	313ms
unbox duration second run	315ms	319ms
migrate (alone)	3928ms	18515ms
migrate (+db2)	5991ms	6550ms
migrate continuation (+db2)	742ms	1097ms
migrate (+db1)	10297ms	16482ms
migrate (+db1 +db2)	27527ms	5842ms
Memory usage without indexes	713.67 MB = 36.50 MB + etc	759.07 MB = 31.53 MB + etc
initial indexing	496ms	699ms
initial indexing maxcup 86%	5910ms	5200ms
initial indexing compat	623ms	1285ms
Two indexes updating concurrently	727ms	910ms
key one initial	50ms	352ms
key two	2ms	3ms
key one again	1ms	1ms
reboot and key one again	61ms	352ms
latest root posts	509ms	612ms
latest posts	12ms	8ms
votes one initial	468ms	537ms
votes again	1ms	1ms
hasRoot	279ms	384ms
hasRoot again	0ms	1ms
author one posts	270ms	280ms
author two posts	17ms	18ms
dedicated author one posts	258ms	327ms
dedicated author one posts again	0ms	1ms
maxium RAM used	813.08 MB = 52.54 MB + etc	786.40 MB = 52.74 MB + etc
Indexes folder size	9.97 MB	9.97 MB

indexes/private.js

arj03 · 2022-06-08T14:17:46Z

Well, all indexes in db2 share the same stream on index update. So you'll only try to decrypt something once and give that to all indexes. It's true that jitdb has it's own stream, so there could be something here. This was one of the big differences compared to flume and db1 where each flume index was completely separate.

staltz · 2022-06-08T14:27:19Z

Well, that's the unsolved mystery: why do I get 4 calls to tryDecryptContent() for the same record? I don't know why, but I assumed that it's because of 3 leveldb indexes and 1 for jitdb. I checked, and at runtime there were 3 leveldb indexes.

If you want to try it yourself, put a console.log in tryDecryptContent that logs the recBuffer as hex, and then run the test test/private.js and you'll see 4 console.logs for 1 record.

arj03 · 2022-06-08T14:30:10Z

strange, I'll have a look

arj03 · 2022-06-08T14:41:24Z

It's actually jitdb that is doing the extra calls:

Trace: trying to decrypt Ex70yEq5H4M6Mnv1kmz6
    at tryDecryptContent (/home/arj/dev/ssb-db2/indexes/private.js:150:13)
    at Object.decrypt (/home/arj/dev/ssb-db2/indexes/private.js:207:23)
    at Object.o.write (/home/arj/dev/ssb-db2/log.js:98:57)
    at Stream._writeToSink (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/stream.js:79:33)
    at Stream._handleBlock (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/stream.js:109:12)
    at Stream._resumeCallback (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/stream.js:145:27)
    at Object.getBlock (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:201:7)
    at Stream._resume (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/stream.js:136:12)
    at Stream._next (/home/arj/dev/ssb-db2/node_modules/looper/index.js:11:9)
    at Stream.resume (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/stream.js:164:8)

Trace: trying to decrypt Ex70yEq5H4M6Mnv1kmz6
    at tryDecryptContent (/home/arj/dev/ssb-db2/indexes/private.js:150:13)
    at Object.decrypt (/home/arj/dev/ssb-db2/indexes/private.js:207:23)
    at /home/arj/dev/ssb-db2/log.js:69:31
    at gotBlock (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:223:7)
    at getBlock (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:201:7)
    at get (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:219:5)
    at waitForLogLoaded (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:516:12)
    at Object.log.get (/home/arj/dev/ssb-db2/log.js:65:5)
    at getRecord (/home/arj/dev/ssb-db2/node_modules/jitdb/index.js:1217:9)
    at filterRecord (/home/arj/dev/ssb-db2/node_modules/jitdb/index.js:1272:5)

Trace: trying to decrypt Ex70yEq5H4M6Mnv1kmz6
    at tryDecryptContent (/home/arj/dev/ssb-db2/indexes/private.js:150:13)
    at Object.decrypt (/home/arj/dev/ssb-db2/indexes/private.js:207:23)
    at /home/arj/dev/ssb-db2/log.js:69:31
    at gotBlock (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:223:7)
    at getBlock (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:201:7)
    at get (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:219:5)
    at waitForLogLoaded (/home/arj/dev/ssb-db2/node_modules/async-append-only-log/index.js:516:12)
    at Object.log.get (/home/arj/dev/ssb-db2/log.js:65:5)
    at getRecord (/home/arj/dev/ssb-db2/node_modules/jitdb/index.js:1217:9)
    at filterRecord (/home/arj/dev/ssb-db2/node_modules/jitdb/index.js:1272:5)

The last 2 calls are !streaming, because they are log.get calls.

arj03 · 2022-06-08T14:46:15Z

Ah right, I was instrumenting this and it does publish and then 2 queries for that author, so 3 decrypts is the correct number.

staltz · 2022-06-08T14:52:04Z

Have you tried test/private.js?

arj03 · 2022-06-08T15:02:01Z

Ahh :) It's because we are posting the same message 4 times. So by the time you get to publishAs classic, then { type: 'post', text: 'super secret', recps: [keys.id] } will be in the db encrypted 4 times ;)

staltz · 2022-06-08T15:17:12Z

How so? If I run only the first test in that file, it has just 1 publish(), and yet:

# publish encrypted message
ok 1 no err
ok 2 should be strictly equal
decryptAndReconstruct a527186b6579a003
decryptAndReconstruct a527186b6579a003
decryptAndReconstruct a527186b6579a003
decryptAndReconstruct a527186b6579a003
ok 3 should be strictly equal

arj03 · 2022-06-08T18:44:29Z

This seems to be a bug in AAOL related to multiple streams and a half-empty database. I'm going to reproduce this in AAOL and fix it there.

staltz · 2022-06-08T18:54:19Z

That sounds like a good hypothesis! It does feel to me like there are non-shared streams going on.

arj03 · 2022-06-08T21:03:49Z

mystery solved solved. The 4 calls to decrypt were:

updateIndex
extra not needed updateIndex (fixed with Fix restart update indexes #350)
getHelper calling jitdb, and jitdb having to update indexes
log.get doing the decrypt

ssb-db2/log.js

Line 69 in f976aac

cb(null, privateIndex.decrypt(record, false).value)

staltz · 2022-06-09T14:49:19Z

Thanks for figuring this out! Indeed, that's the truth. I think we can close this PR, there's nothing else here we can make use of.

cache decrypted content based on record buffer

77d96e6

staltz requested a review from arj03 June 8, 2022 13:55

staltz commented Jun 8, 2022

View reviewed changes

indexes/private.js Outdated Show resolved Hide resolved

cache only decrypted content

a585c55

staltz mentioned this pull request Jun 8, 2022

use a record cache ssbc/async-append-only-log#73

Closed

arj03 mentioned this pull request Jun 8, 2022

Fix restart update indexes #350

Closed

staltz closed this Jun 9, 2022

staltz deleted the record-cache branch June 9, 2022 14:49

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

cache decrypted content based on record buffer #349

cache decrypted content based on record buffer #349

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022

arj03 commented Jun 8, 2022

arj03 commented Jun 8, 2022 •

edited

Loading

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022

staltz commented Jun 8, 2022 •

edited

Loading

arj03 commented Jun 8, 2022

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022 •

edited

Loading

staltz commented Jun 9, 2022

cache decrypted content based on record buffer #349

cache decrypted content based on record buffer #349

Conversation

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022

arj03 commented Jun 8, 2022

arj03 commented Jun 8, 2022 • edited Loading

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022

staltz commented Jun 8, 2022 • edited Loading

arj03 commented Jun 8, 2022

staltz commented Jun 8, 2022

arj03 commented Jun 8, 2022 • edited Loading

staltz commented Jun 9, 2022

arj03 commented Jun 8, 2022 •

edited

Loading

staltz commented Jun 8, 2022 •

edited

Loading

arj03 commented Jun 8, 2022 •

edited

Loading