EDR takes minutes to send messages after importing offline key backup.

[ara4n]

Steps to reproduce

1. I successfully imported my offline keybackup (420K keys) into EDR, yay - probably means Importing a large (300MB) megolm backup into EDR fails element-desktop#1394 is fixed.
2. Message sending now takes ~5 minutes in E2EE rooms. Rageshakes can also take ~5m to send. There isn't anything consuming CPU.
3. Disabling keybackup (by running await mxMatrixClientPeg.get().getCrypto().backupManager.disableKeyBackup() at the JS console) fixes it.

There's a chance that the slow send isn't related to me having importing the offline keybackup, but by having connected to the online backup. However, EWR is fine after connecting to online backup.

As a final symptom: i'm seeing a lot of E2EE traffic coming in from online backup (with grey shields) rather than direct.

This may be related to #26375

Outcome

What did you expect?

Fast send

What happened instead?

Agonisingly slow send.

Operating system

No response

Application version

Element Nightly version: 2023121601 Crypto version: Rust SDK 0.6.0 (438880a), Vodozemac 0.5.0

How did you install the app?

No response

Homeserver

No response

Will you send logs?

Yes

[ara4n]

might be related to #26488

[BillCarsonFr]

Analysis of the problem:

What happens is that when group sessions are mark as backep_up the sdk start a readwrite transaction on inbound_group_sessions2.

If now a new message is sent from a room that needs a new session, it will create an outbound session and the inbound that it wants to store.

=> Calls save changes that will also want to start a readwrite transaction on inbound_group_sessions2

So the sending of the message is locked until the mark as backed-up as complete.
But save_change also take the save_changes_lock => Thus blocking any other save change that could occur (lock the syncs for example)

Now that save_changes_lock is taken, it will also block sendings in other rooms even if the inbound_group_sessions2 is not needed. It will lock the updates of the olm sessions used to encrypt for example.

The fact that mark_inbound_group_sessions_as_backed_up is a very slow transaction easily creates this lock.
The question is why it is so slow.

Can be reproduced with any call that readwrite on inbound_group_sessions2

For example, type this in the console:
mxMatrixClientPeg.get().getCrypto().backupManager.disableKeyBackup()

This will also be slow and locks the inbound group session store.
Now on a room:

• Type /discardsession
• Send a message

=> The sending will be super slow (depending on your number of keys)
=> Message sending on other rooms will be blocked too

[BillCarsonFr]

update:

The fact that mark_inbound_group_sessions_as_backed_up is a very slow transaction easily creates this lock.
The question is why it is so slow.

After a closer look it's not mark_inbound_group_sessions_as_backed_up that is very slow, it's the enclosing call BackupMachine#mark_request_as_sent due to the fact that for tracing purpose we count the backed-up keys. On a test setup, the total spent time is ~20s for mark_as_sent but the actual mark_inbound_group_sessions_as_backed_up is 300ms.
The count query is read only so shouldn't block, have yet to figure out what could lock for so long and create this scenario.

backupManager.disableKeyBackup() will still create it has it's a very long write transaction

[richvdh]

We don't consider this a release blocker for Element R, because once your imported keys are (eventually) backed up, performance recovers.

[BillCarsonFr]

Some more findings:

When the inbound_group_session2 database gets bigger, some operation start to be very slow. It's particularly the case with the queries that counts the number of keys. And when such a query is beeing processed, message sending will be blocked.

Can be reproduced by typing this in the console:

window.indexedDB.open("matrix-js-sdk::matrix-sdk-crypto", 8).onsuccess = (event) => {
    const db = event.target.result;
    const start = Date.now();
    const tx = db.transaction(["inbound_group_sessions2"], "readonly");
    const object_store = tx.objectStore("inbound_group_sessions2");
    const req = object_store.count()
    req.onsuccess = (event) => { 
        console.log("## Count", event.target.result);
    };
    req.onerror  = (event) => { console.info(" ## fail to count")};
    tx.oncomplete = (() => {
        const now = Date.now();
        console.info("## Perf: count took:", now - start, "ms")
    });
}

Just after starting this, you can try to send a message. It will be blocked until the count request has completed.

The count performances are particularly bad on Firefox from my testing:

Firefox:

23:07:18,566 ## Count 190003 bundle.js:262316:19
23:07:18,579 ## Perf: count took: 39182 ms

23:09:07,297 ## Count 190003 bundle.js:262316:19
23:09:07,322 ## Perf: count took: 38755 ms

The same database on Chrome:

## Count 190003
rageshake.ts:77 ## Perf: count took: 1842 ms

## Count 190003
rageshake.ts:77 ## Perf: count took: 1794 ms

So in my case as backuploop is running, a call is made after each chunk to count the remaining keys for signaling. And if you send a message it would be delayed by around ~30s on firefox.

On legacy the inbound_group_sessions are not saved in the same way in the database. And count performances are a lot better on legacy with the same database (1s instead of 38s).
On legacy inbound group sessions are stored as a json InboundGroupSessionData (~800 chars)
On rust indexeddb its a { pickled_session: Array(~3600) } (encrypted payload)

I did some experiment on the IndexedDB keys used by rust to see if it impacts count performances, but didn't see any noticable improvement. Like reducing key clustering (sessionId|roomid) instead of (roomId|sessionId) or just sessionId.

So maybe related to the size of the data?

Anyhow, for now we might want to stop counting the rows during the key loop as a temporary improvement

[ara4n]

Confirmed fixed by matrix-org/matrix-js-sdk#4015 \o/