Add spans for perf metrics and a conversion script for Jaeger support

scripts/spans-to-jaeger.js

@@ -0,0 +1,158 @@
+// 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));

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<void> {
     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<void> {
     if (isSoftLogout()) {
         softLogout();
     }
+    span("Lifecycle_start", true);
 }
 
 /*

src/MatrixClientPeg.ts

@@ -229,11 +229,14 @@ class MatrixClientPegClass implements IMatrixClientPeg {
     }
 
     public async start(): Promise<any> {
+        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 {

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<IProps, IState> {
         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<IProps, IState> {
 
             this.firstSyncComplete = true;
             this.firstSyncPromise.resolve();
+            span("MatrixChat_firstSync", true);
 
             if (Notifier.shouldShowPrompt() && !MatrixClientPeg.userRegisteredWithinLastHours(24)) {
                 showNotificationsToast(false);