From a80e90b42d311cfccdd12998f8fdb4c3008c045e Mon Sep 17 00:00:00 2001 From: Valere Date: Mon, 18 Dec 2023 15:35:45 +0100 Subject: [PATCH] Add some perfomance logs (#3965) * Add some perfomance logs * missing return --- src/rust-crypto/OutgoingRequestProcessor.ts | 8 +++-- src/rust-crypto/OutgoingRequestsManager.ts | 6 ++-- src/rust-crypto/RoomEncryptor.ts | 34 +++++++++++++++------ src/rust-crypto/backup.ts | 10 ++++-- src/rust-crypto/rust-crypto.ts | 18 ++++++----- src/utils.ts | 18 +++++++++++ 6 files changed, 70 insertions(+), 24 deletions(-) diff --git a/src/rust-crypto/OutgoingRequestProcessor.ts b/src/rust-crypto/OutgoingRequestProcessor.ts index 1fbd2d643..18b9d6b03 100644 --- a/src/rust-crypto/OutgoingRequestProcessor.ts +++ b/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`); } } diff --git a/src/rust-crypto/OutgoingRequestsManager.ts b/src/rust-crypto/OutgoingRequestsManager.ts index e3ca9066d..81b3001c8 100644 --- a/src/rust-crypto/OutgoingRequestsManager.ts +++ b/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. diff --git a/src/rust-crypto/RoomEncryptor.ts b/src/rust-crypto/RoomEncryptor.ts index 5a752c53f..5de1769ba 100644 --- a/src/rust-crypto/RoomEncryptor.ts +++ b/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 { 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); + } } - } + }); } /** diff --git a/src/rust-crypto/backup.ts b/src/rust-crypto/backup.ts index 1b3f88910..f12061bdd 100644 --- a/src/rust-crypto/backup.ts +++ b/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 { + return await this.olmMachine.backupRoomKeys(); + }, + ); } catch (err) { logger.error("Backup: Failed to get keys to backup from rust crypto-sdk", err); } diff --git a/src/rust-crypto/rust-crypto.ts b/src/rust-crypto/rust-crypto.ts index 833de7785..aac89657d 100644 --- a/src/rust-crypto/rust-crypto.ts +++ b/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; devices?: RustSdkCryptoJs.DeviceLists; }): Promise { - 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); diff --git a/src/utils.ts b/src/utils.ts index 1dba236c9..a40aac112 100644 --- a/src/utils.ts +++ b/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(); @@ -387,6 +388,23 @@ export function sleep(ms: number, value?: T): Promise { }); } +/** + * 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(logger: Logger, name: string, block: () => Promise): Promise { + 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}. */