From ca67917dcd8065b5a676bd943d79fe5cd0eb412e Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Mon, 18 Jul 2022 13:57:31 +0100 Subject: [PATCH 1/3] Add spans for perf metrics and a conversion script for Jaeger support --- scripts/spans-to-jaeger.js | 157 +++++++++++++++++++++++ src/Lifecycle.ts | 4 +- src/MatrixClientPeg.ts | 3 + src/components/structures/MatrixChat.tsx | 4 +- 4 files changed, 166 insertions(+), 2 deletions(-) create mode 100644 scripts/spans-to-jaeger.js diff --git a/scripts/spans-to-jaeger.js b/scripts/spans-to-jaeger.js new file mode 100644 index 00000000000..bb55dd547ae --- /dev/null +++ b/scripts/spans-to-jaeger.js @@ -0,0 +1,157 @@ +// convert SPAN lines into something Jaeger can parse. +// Usage: node convert-spans-to-jaeger.js console-output.log > trace.json +// +// Where console-output.log has lines line: +// SPAN START 1658139854077 MatrixClientPeg_start {"line":"at MatrixClientPegClass.start (webpack-internal:///160:180:65)"} +// SPAN START 1658139854451 pre_sync_loop {"line":"at SyncApi.sync (webpack-internal:///201:578:48)"} +// SPAN START 1658139854451 pre_sync_loop|push_rules {"line":"at getPushRules (webpack-internal:///201:598:52)"} +// SPAN END 1658139854453 MatrixClientPeg_start {"line":"at MatrixClientPegClass.start (webpack-internal:///160:185:65)"} + +"use-strict"; + +const fs = require('fs'); + +const traceId = "trace"+new Date().getTime(); +const procId = "client"; +const spanIdToEntries = {}; +const outputJson = { + traceID: traceId, + spans: [], + processes: { + client: { + serviceName: procId, + tags: [ + /* + { + "key": "ip", + "type": "string", + "value": "192.168.1.102" + } */ + ] + } + } +}; + +/* +{ + "traceID": "665b3cc06e48f122", + "spanID": "616bc4df9f135fcd", + "flags": 1, + "operationName": "HTTP GET: /customer", + "references": [{ + "refType": "CHILD_OF", + "traceID": "665b3cc06e48f122", + "spanID": "665b3cc06e48f122" + }], + "startTime": 1555385360015391, + "duration": 179848, + "tags": [], + "logs": [], + "processID": "client" + } + */ + +let spanId = 0; +const generateSpanId = () => { + spanId++; + return "" + spanId; +} +let openSpans = {}; +const addSpan = (startSpan, endSpan) => { + const startTime = new Date(Number(startSpan.timestamp)) * 1000; + const endTime = new Date(Number(endSpan.timestamp)) * 1000; + const tags = Object.keys(startSpan.keysJson).map((k) => { + return { + key: k, + type: typeof startSpan.keysJson[k], + value: startSpan.keysJson[k], + }; + }); + // foo|bar|baz => baz is child of bar who is child of foo + const references = []; + const levels = startSpan.spanName.split("|"); + let opName = startSpan.spanName; + if (levels.length > 1) { + // we only want the last span segment (baz only refs bar, not bar and foo). + const parentSpanName = levels.slice(0, levels.length-1).join("|"); + let parentSpanId; + // find the span so we can grab the ID + const openSpanIds = Object.keys(openSpans); + for (let i = openSpanIds.length-1; i >= 0; i--) { + const sid = openSpanIds[i]; + const s = openSpans[sid]; + if (s.spanName === parentSpanName) { + parentSpanId = sid; + break; + } + } + if (parentSpanId) { + references.push({ + refType: "CHILD_OF", + traceID: traceId, + spanID: parentSpanId, + }); + opName = levels[levels.length-1]; + } else { + console.error("failed to find parent for span " + startSpan.spanName + " parent: " + parentSpanName + " data: " + JSON.stringify(startSpan)); + } + } + outputJson.spans.push({ + traceID: traceId, + spanID: startSpan.spanId, + flags: 1, + operationName: opName, + startTime: startTime, + duration: endTime - startTime, + tags: tags, + logs: [], + references: references, + processID: procId, + }); +}; + +const filename = process.argv[2]; +const contents = fs.readFileSync(filename, 'utf-8'); +let startTimestamp = 0; +contents.split(/\r?\n/).forEach(line => { + const segments = line.split(" "); + // SPAN START id desc + // SPAN END id desc + if (segments[0] !== "SPAN") { + return; + } + const timestamp = segments[2]; + if (startTimestamp === 0) { + startTimestamp = timestamp; + } + const spanName = segments[3]; + const keysJson = JSON.parse(segments.slice(4).join(" ")); + const entries = spanIdToEntries[spanName] || []; + switch (segments[1]) { + case "START": { + const spanId = generateSpanId(); + const span = {spanName, timestamp, keysJson, spanId}; + entries.push(span); + spanIdToEntries[spanName] = entries; + openSpans[spanId] = span; + break; + } + case "END": { + const startSpan = entries.pop(); + if (!startSpan) { + console.error("got SPAN END without matching SPAN START; ignoring. " + line); + return; + } + const spanId = startSpan.spanId; + addSpan(startSpan, {spanName, timestamp, keysJson}); + delete openSpans[spanId]; + break; + } + default: + console.error("unknown span: " + line); + } +}); + +console.log(JSON.stringify({ + data: [outputJson] +}, undefined, 2)); diff --git a/src/Lifecycle.ts b/src/Lifecycle.ts index 915bc85dd72..48fd4faab0a 100644 --- a/src/Lifecycle.ts +++ b/src/Lifecycle.ts @@ -21,7 +21,7 @@ import { createClient } from 'matrix-js-sdk/src/matrix'; import { InvalidStoreError } from "matrix-js-sdk/src/errors"; import { MatrixClient } from "matrix-js-sdk/src/client"; import { decryptAES, encryptAES, IEncryptedPayload } from "matrix-js-sdk/src/crypto/aes"; -import { QueryDict } from 'matrix-js-sdk/src/utils'; +import { QueryDict, span } from 'matrix-js-sdk/src/utils'; import { logger } from "matrix-js-sdk/src/logger"; import { IMatrixClientCreds, MatrixClientPeg } from './MatrixClientPeg'; @@ -791,6 +791,7 @@ export function isLoggingOut(): boolean { */ async function startMatrixClient(startSyncing = true): Promise { logger.log(`Lifecycle: Starting MatrixClient`); + span("Lifecycle_start"); // dispatch this before starting the matrix client: it's used // to add listeners for the 'sync' event so otherwise we'd have @@ -849,6 +850,7 @@ async function startMatrixClient(startSyncing = true): Promise { if (isSoftLogout()) { softLogout(); } + span("Lifecycle_start", true); } /* diff --git a/src/MatrixClientPeg.ts b/src/MatrixClientPeg.ts index e8296afc521..703129b2200 100644 --- a/src/MatrixClientPeg.ts +++ b/src/MatrixClientPeg.ts @@ -229,11 +229,14 @@ class MatrixClientPegClass implements IMatrixClientPeg { } public async start(): Promise { + utils.span("MatrixClientPeg_start"); const opts = await this.assign(); logger.log(`MatrixClientPeg: really starting MatrixClient`); + await this.get().startClient(opts); logger.log(`MatrixClientPeg: MatrixClient started`); + utils.span("MatrixClientPeg_start", true); } public getCredentials(): IMatrixClientCreds { diff --git a/src/components/structures/MatrixChat.tsx b/src/components/structures/MatrixChat.tsx index eb979c5798d..4a8b6917514 100644 --- a/src/components/structures/MatrixChat.tsx +++ b/src/components/structures/MatrixChat.tsx @@ -25,6 +25,7 @@ import { } from 'matrix-js-sdk/src/matrix'; import { ISyncStateData, SyncState } from 'matrix-js-sdk/src/sync'; import { MatrixError } from 'matrix-js-sdk/src/http-api'; +import { span } from 'matrix-js-sdk/src/utils'; import { InvalidStoreError } from "matrix-js-sdk/src/errors"; import { MatrixEvent } from "matrix-js-sdk/src/models/event"; import { defer, IDeferred, QueryDict } from "matrix-js-sdk/src/utils"; @@ -252,7 +253,7 @@ export default class MatrixChat extends React.PureComponent { this.loggedInView = createRef(); SdkConfig.put(this.props.config); - + span("MatrixChat_firstSync"); // Used by _viewRoom before getting state from sync this.firstSyncComplete = false; this.firstSyncPromise = defer(); @@ -1426,6 +1427,7 @@ export default class MatrixChat extends React.PureComponent { this.firstSyncComplete = true; this.firstSyncPromise.resolve(); + span("MatrixChat_firstSync", true); if (Notifier.shouldShowPrompt() && !MatrixClientPeg.userRegisteredWithinLastHours(24)) { showNotificationsToast(false); From a8fbddfc8895370a350fda198d6b7290830b77d9 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Tue, 19 Jul 2022 14:00:21 +0100 Subject: [PATCH 2/3] Kick netlify --- scripts/spans-to-jaeger.js | 1 + 1 file changed, 1 insertion(+) diff --git a/scripts/spans-to-jaeger.js b/scripts/spans-to-jaeger.js index bb55dd547ae..0e48655728c 100644 --- a/scripts/spans-to-jaeger.js +++ b/scripts/spans-to-jaeger.js @@ -116,6 +116,7 @@ let startTimestamp = 0; contents.split(/\r?\n/).forEach(line => { const segments = line.split(" "); // SPAN START id desc + // SPAN END id desc if (segments[0] !== "SPAN") { return; From 602188931c4e5a5ec4e3f2e00fc34a2a5f6c98e8 Mon Sep 17 00:00:00 2001 From: Kegan Dougal Date: Tue, 19 Jul 2022 17:25:13 +0100 Subject: [PATCH 3/3] Poke netlify --- scripts/spans-to-jaeger.js | 1 - 1 file changed, 1 deletion(-) diff --git a/scripts/spans-to-jaeger.js b/scripts/spans-to-jaeger.js index 0e48655728c..bb55dd547ae 100644 --- a/scripts/spans-to-jaeger.js +++ b/scripts/spans-to-jaeger.js @@ -116,7 +116,6 @@ let startTimestamp = 0; contents.split(/\r?\n/).forEach(line => { const segments = line.split(" "); // SPAN START id desc - // SPAN END id desc if (segments[0] !== "SPAN") { return;