Trace summary script

analyze-trace.ts

import { assert } from "console";

if (process.argv.length !== 3) {
    const path = require("path");
    console.error(`Usage: ${path.basename(process.argv[0])} ${path.basename(process.argv[1])} trace_path`);
    process.exit(1);
}

const inPath = process.argv[2];
const minDuration = 1E5;
const minPercentage = 0.25;

const Parser = require("jsonparse");
const fs = require("fs");

const p = new Parser();

interface Event {
    ph: string;
    ts: string;
    dur?: string;
    name: string;
    cat: string;
    args?: any;
}

interface EventSpan {
    event?: Event;
    start: number;
    end: number;
    children: EventSpan[];
}

let minTime = Infinity;
let maxTime = 0;
const unclosedStack: Event[] = []; // Sorted in increasing order of start time (even when below timestamp resolution)
const spans: EventSpan[] = []; // Sorted in increasing order of end time, then increasing order of start time (even when below timestamp resolution)
p.onValue = function (value: any) {
    if (this.stack.length !== 1) return;
    assert(this.mode === Parser.C.ARRAY, `Unexpected mode ${this.mode}`);
    this.value = [];

    // Metadata objects are uninteresting
    if (value.ph === "M") return;

    // TODO (acasey): instant events
    if (value.ph === "i" || value.ph === "I") return;

    const event = value as Event;

    if (event.ph === "B") {
        unclosedStack.push(event);
        return;
    }

    let span: EventSpan;
    if (event.ph === "E") {
        const beginEvent = unclosedStack.pop()!;
        span = { event: beginEvent, start: +beginEvent.ts, end: +event.ts, children: [] };
    }
    else if (event.ph === "X") {
        const start = +event.ts;
        const duration = +event.dur!;
        span = { event, start, end: start + duration, children: [] }
    }
    else {
        assert(false, `Unknown event phase ${event.ph}`);
        return;
    }

    minTime = Math.min(minTime, span.start);
    maxTime = Math.max(maxTime, span.end);

    if ((span.end - span.start) >= minDuration) {
        spans.push(span);
    }
}

const readStream = fs.createReadStream(inPath);
readStream.on("data", chunk => p.write(chunk));
readStream.on("end", () => {
    if (unclosedStack.length) {
        console.log("Trace ended unexpectedly");

        while (unclosedStack.length) {
            const event = unclosedStack.pop()!;
            console.log(`> ${event.name}: ${JSON.stringify(event.args)}`);
            spans.push({ event, start: +event.ts, end: maxTime, children: [] });
        }

        console.log();
    }

    spans.sort((a, b) => a.start - b.start);

    const root = { start: minTime, end: maxTime, children: [] };
    const stack: EventSpan[] = [ root ];

    for (const span of spans) {
        let i = stack.length - 1;
        for (; i > 0; i--) { // No need to check root at stack[0]
            const curr = stack[i];
            if (curr.end > span.start) {
                // Pop down to parent
                stack.length = i + 1;
                break;
            }
        }

        const parent = stack[i];
        if ((span.end - span.start) >= minPercentage * (parent.end - parent.start)) {
            parent.children.push(span);
            stack.push(span);
        }
    }

    printHotStacks(root);
});

// TODO (acasey): nicer ascii art
function printHotStacks(root: EventSpan) {
    console.log("Hot Spots");
    console.log();
    const stack: [number, EventSpan][] = [ [0, root] ];
    while (stack.length) {
        const [depth, curr] = stack.pop()!;
        let childDepth = depth;
        if (curr.event) {
            const eventStr = eventToString(curr.event);
            if (eventStr) {
                console.log(`${"|-".repeat(depth)}${eventStr} (${Math.round((curr.end - curr.start) / 1000)}ms)`);
                childDepth++;
            }
        }

        // Sort fast to slow because we'll pop in reverse order (i.e. slow to fast)
        const sorted = curr.children.sort((a, b) => (a.end - a.start) - (b.end - b.start));
        for (const child of sorted) {
            stack.push([childDepth, child]);
        }
    }
}

function eventToString(event: Event): string | undefined {
    switch (event.name) {
        case "findSourceFile":
            return `Load file ${event.args!.fileName}`;
        case "checkSourceFile":
            return `Check file ${event.args!.path}`;
        case "emit":
            return `Emit`;
        default:
            if (event.cat === "check" && event.args && event.args.pos && event.args.end) {
                return `${unmangleCamelCase(event.name)} with range [${event.args.pos},${event.args.end})`;
            }
            return undefined;
    }
}

function unmangleCamelCase(name: string) {
    let result = "";
    for (const char of [...<any>name]) {
        if (!result.length) {
            result += char.toLocaleUpperCase();
            continue;
        }

        const lower = char.toLocaleLowerCase();
        if (char !== lower) {
            result += " ";
        }

        result += lower;
    }
    return result;
}