Add some perfomance logs (#3965)

* Add some perfomance logs

* missing return

src/rust-crypto/OutgoingRequestProcessor.ts

@@ -28,7 +28,7 @@ import {
 
 import { logger } from "../logger";
 import { IHttpOpts, MatrixHttpApi, Method } from "../http-api";
-import { QueryDict } from "../utils";
+import { logDuration, QueryDict } from "../utils";
 import { IAuthDict, UIAuthCallback } from "../interactive-auth";
 import { UIAResponse } from "../@types/uia";
 import { ToDeviceMessageId } from "../@types/event";
@@ -109,7 +109,9 @@ export class OutgoingRequestProcessor {
 
         if (msg.id) {
             try {
-                await this.olmMachine.markRequestAsSent(msg.id, msg.type, resp);
+                await logDuration(logger, `Mark Request as sent ${msg.type}`, async () => {
+                    await this.olmMachine.markRequestAsSent(msg.id!, msg.type, resp);
+                });
             } catch (e) {
                 // Ignore errors which are caused by the olmMachine having been freed. The exact error message depends
                 // on whether we are using a release or develop build of rust-sdk-crypto-wasm.
@@ -122,6 +124,8 @@ export class OutgoingRequestProcessor {
                     throw e;
                 }
             }
+        } else {
+            logger.trace(`Outgoing request type:${msg.type} does not have an ID`);
         }
     }
 

src/rust-crypto/OutgoingRequestsManager.ts

@@ -18,7 +18,7 @@ import { OlmMachine } from "@matrix-org/matrix-sdk-crypto-wasm";
 
 import { OutgoingRequest, OutgoingRequestProcessor } from "./OutgoingRequestProcessor";
 import { Logger } from "../logger";
-import { defer, IDeferred } from "../utils";
+import { defer, IDeferred, logDuration } from "../utils";
 
 /**
  * OutgoingRequestsManager: responsible for processing outgoing requests from the OlmMachine.
@@ -130,7 +130,9 @@ export class OutgoingRequestsManager {
         for (const request of outgoingRequests) {
             if (this.stopped) return;
             try {
-                await this.outgoingRequestProcessor.makeOutgoingRequest(request);
+                await logDuration(this.logger, `Make outgoing request ${request.type}`, async () => {
+                    await this.outgoingRequestProcessor.makeOutgoingRequest(request);
+                });
             } catch (e) {
                 // as part of the loop we silently ignore errors, but log them.
                 // The rust sdk will retry the request later as it won't have been marked as sent.

src/rust-crypto/RoomEncryptor.ts

@@ -33,6 +33,7 @@ import { KeyClaimManager } from "./KeyClaimManager";
 import { RoomMember } from "../models/room-member";
 import { HistoryVisibility } from "../@types/partials";
 import { OutgoingRequestsManager } from "./OutgoingRequestsManager";
+import { logDuration } from "../utils";
 
 /**
  * RoomEncryptor: responsible for encrypting messages to a given room
@@ -98,8 +99,10 @@ export class RoomEncryptor {
             (member.membership == "invite" && this.room.shouldEncryptForInvitedMembers())
         ) {
             // make sure we are tracking the deviceList for this user
-            this.olmMachine.updateTrackedUsers([new UserId(member.userId)]).catch((e) => {
-                this.prefixedLogger.error("Unable to update tracked users", e);
+            logDuration(this.prefixedLogger, "updateTrackedUsers", async () => {
+                this.olmMachine.updateTrackedUsers([new UserId(member.userId)]).catch((e) => {
+                    this.prefixedLogger.error("Unable to update tracked users", e);
+                });
             });
         }
 
@@ -116,7 +119,10 @@ export class RoomEncryptor {
      */
     public async prepareForEncryption(globalBlacklistUnverifiedDevices: boolean): Promise<void> {
         const logger = new LogSpan(this.prefixedLogger, "prepareForEncryption");
-        await this.ensureEncryptionSession(logger, globalBlacklistUnverifiedDevices);
+
+        await logDuration(this.prefixedLogger, "prepareForEncryption", async () => {
+            await this.ensureEncryptionSession(logger, globalBlacklistUnverifiedDevices);
+        });
     }
 
     /**
@@ -159,7 +165,10 @@ export class RoomEncryptor {
             // at the end of the sync, but we can't wait for that).
             // XXX future improvement process only KeysQueryRequests for the users that have never been queried.
             logger.debug(`Processing outgoing requests`);
-            await this.outgoingRequestManager.doProcessOutgoingRequests();
+
+            await logDuration(this.prefixedLogger, "doProcessOutgoingRequests", async () => {
+                await this.outgoingRequestManager.doProcessOutgoingRequests();
+            });
         } else {
             // If members are already loaded it's less critical to await on key queries.
             // We might still want to trigger a processOutgoingRequests here.
@@ -177,7 +186,10 @@ export class RoomEncryptor {
         );
 
         const userList = members.map((u) => new UserId(u.userId));
-        await this.keyClaimManager.ensureSessionsForUsers(logger, userList);
+
+        await logDuration(this.prefixedLogger, "ensureSessionsForUsers", async () => {
+            await this.keyClaimManager.ensureSessionsForUsers(logger, userList);
+        });
 
         const rustEncryptionSettings = new EncryptionSettings();
         rustEncryptionSettings.historyVisibility = toRustHistoryVisibility(this.room.getHistoryVisibility());
@@ -201,12 +213,14 @@ export class RoomEncryptor {
         rustEncryptionSettings.onlyAllowTrustedDevices =
             this.room.getBlacklistUnverifiedDevices() ?? globalBlacklistUnverifiedDevices;
 
-        const shareMessages: ToDeviceRequest[] = await this.shareRoomKey(userList, rustEncryptionSettings);
-        if (shareMessages) {
-            for (const m of shareMessages) {
-                await this.outgoingRequestManager.outgoingRequestProcessor.makeOutgoingRequest(m);
+        await logDuration(this.prefixedLogger, "shareRoomKey", async () => {
+            const shareMessages: ToDeviceRequest[] = await this.shareRoomKey(userList, rustEncryptionSettings);
+            if (shareMessages) {
+                for (const m of shareMessages) {
+                    await this.outgoingRequestManager.outgoingRequestProcessor.makeOutgoingRequest(m);
+                }
             }
-        }
+        });
     }
 
     /**

src/rust-crypto/backup.ts

@@ -29,7 +29,7 @@ import { logger } from "../logger";
 import { ClientPrefix, IHttpOpts, MatrixError, MatrixHttpApi, Method } from "../http-api";
 import { CryptoEvent, IMegolmSessionData } from "../crypto";
 import { TypedEventEmitter } from "../models/typed-event-emitter";
-import { encodeUri, immediate } from "../utils";
+import { encodeUri, immediate, logDuration } from "../utils";
 import { OutgoingRequestProcessor } from "./OutgoingRequestProcessor";
 import { sleep } from "../utils";
 import { BackupDecryptor } from "../common-crypto/CryptoBackend";
@@ -328,7 +328,13 @@ export class RustBackupManager extends TypedEventEmitter<RustBackupCryptoEvents,
                 // Get a batch of room keys to upload
                 let request: RustSdkCryptoJs.KeysBackupRequest | null = null;
                 try {
-                    request = await this.olmMachine.backupRoomKeys();
+                    request = await logDuration(
+                        logger,
+                        "BackupRoomKeys: Get keys to backup from rust crypto-sdk",
+                        async () => {
+                            return await this.olmMachine.backupRoomKeys();
+                        },
+                    );
                 } catch (err) {
                     logger.error("Backup: Failed to get keys to backup from rust crypto-sdk", err);
                 }

src/rust-crypto/rust-crypto.ts

@@ -24,12 +24,12 @@ import { IContent, MatrixEvent, MatrixEventEvent } from "../models/event";
 import { Room } from "../models/room";
 import { RoomMember } from "../models/room-member";
 import { BackupDecryptor, CryptoBackend, OnSyncCompletedData } from "../common-crypto/CryptoBackend";
-import { Logger } from "../logger";
+import { logger, Logger } from "../logger";
 import { IHttpOpts, MatrixHttpApi, Method } from "../http-api";
 import { RoomEncryptor } from "./RoomEncryptor";
 import { OutgoingRequestProcessor } from "./OutgoingRequestProcessor";
 import { KeyClaimManager } from "./KeyClaimManager";
-import { MapWithDefault } from "../utils";
+import { logDuration, MapWithDefault } from "../utils";
 import {
     BackupTrustInfo,
     BootstrapCrossSigningOpts,
@@ -1225,12 +1225,14 @@ export class RustCrypto extends TypedEventEmitter<RustCryptoEvents, RustCryptoEv
         unusedFallbackKeys?: Set<string>;
         devices?: RustSdkCryptoJs.DeviceLists;
     }): Promise<IToDeviceEvent[]> {
-        const result = await this.olmMachine.receiveSyncChanges(
-            events ? JSON.stringify(events) : "[]",
-            devices,
-            oneTimeKeysCounts,
-            unusedFallbackKeys,
-        );
+        const result = await logDuration(logger, "receiveSyncChanges", async () => {
+            return await this.olmMachine.receiveSyncChanges(
+                events ? JSON.stringify(events) : "[]",
+                devices,
+                oneTimeKeysCounts,
+                unusedFallbackKeys,
+            );
+        });
 
         // receiveSyncChanges returns a JSON-encoded list of decrypted to-device messages.
         return JSON.parse(result);

src/utils.ts

@@ -25,6 +25,7 @@ import { Optional } from "matrix-events-sdk";
 import { IEvent, MatrixEvent } from "./models/event";
 import { M_TIMESTAMP } from "./@types/location";
 import { ReceiptType } from "./@types/read_receipts";
+import { Logger } from "./logger";
 
 const interns = new Map<string, string>();
 
@@ -387,6 +388,23 @@ export function sleep<T>(ms: number, value?: T): Promise<T> {
     });
 }
 
+/**
+ * Utility to log the duration of a promise.
+ *
+ * @param logger - The logger to log to.
+ * @param name - The name of the operation.
+ * @param block - The block to execute.
+ */
+export async function logDuration<T>(logger: Logger, name: string, block: () => Promise<T>): Promise<T> {
+    const start = Date.now();
+    try {
+        return await block();
+    } finally {
+        const end = Date.now();
+        logger.debug(`[Perf]: ${name} took ${end - start}ms`);
+    }
+}
+
 /**
  * Promise/async version of {@link setImmediate}.
  */