matrix/matrix-js-sdk
1
0
Fork 0
mirror of https://github.com/matrix-org/matrix-js-sdk.git synced 2025-11-23 17:02:25 +03:00
Code Activity

Add some perfomance logs (#3965)

Browse Source 
* Add some perfomance logs

* missing return
This commit is contained in:
Valere
2023-12-18 15:35:45 +01:00
committed by GitHub
parent 2c13e133b7
commit a80e90b42d
6 changed files with 70 additions and 24 deletions
Download Patch File Download Diff File Expand all files Collapse all files

8
src/rust-crypto/OutgoingRequestProcessor.ts
View File

@@ -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`);
}
}

4
src/rust-crypto/OutgoingRequestsManager.ts
View File

@@ -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 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.

14
src/rust-crypto/RoomEncryptor.ts
View File

@@ -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,9 +99,11 @@ export class RoomEncryptor {
(member.membership == "invite" && this.room.shouldEncryptForInvitedMembers())
) {
// make sure we are tracking the deviceList for this user
logDuration(this.prefixedLogger, "updateTrackedUsers", async () => {
this.olmMachine.updateTrackedUsers([new UserId(member.userId)]).catch((e) => {
this.prefixedLogger.error("Unable to update tracked users", e);
});
});
}
// TODO: handle leaves (including our own)
@@ -116,7 +119,10 @@ export class RoomEncryptor {
*/
public async prepareForEncryption(globalBlacklistUnverifiedDevices: boolean): Promise<void> {
const logger = new LogSpan(this.prefixedLogger, "prepareForEncryption");
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 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 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;
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);
}
}
});
}
/**

10
src/rust-crypto/backup.ts
View File

@@ -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);
}

8
src/rust-crypto/rust-crypto.ts
View File

@@ -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(
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);

18
src/utils.ts
View File

@@ -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}.
*/