Build a performance counters system so I can start optimizing things

Complete a circular buffer so we don't log too much data, config
settings for turning it on and off (default off, becuase performance)
and for changing the size of the buffer, an excmd for dumping the raw
json so you can pore over it, and for when you just want to
sanity-check yourself instead of groveling over your data for six days
with a deep learning toolkit and three hundred CPUs of compute, an
excmd for pretty-printing your stats in a nice histogram.

I didn't think far enough ahead and only implemented the easy way to
instrument a function, which is with a decorator. I'm getting _really_
angry at typescript not being able to handle decorators on free
functions. bah. I'll figure out a good way to wrap free
functions. Maybe just go the stupid route and make you change
`export async function foo(args)` to `export foo = measured(async
function(args) ...`. But that would break excmd parsing, so... :/

I think that I already want to do a refactor to break excmd.ts into a
bunch of one-line wrappers referencing implementations spread
throughout a bunch of libraries. This would go nicely with that.

Other things I did while I was here:
* Fix the ugliness we had with (window as any).tri by monkey-patching
  the tri property into the window object in tridactyl.d.ts

src/background.ts

@@ -18,7 +18,8 @@ import * as native from "./native_background"
 import state from "./state"
 import * as webext from "./lib/webext"
 import { AutoContain } from "./lib/autocontainers"
-;(window as any).tri = Object.assign(Object.create(null), {
+import * as perf from "./perf"
+window.tri = Object.assign(window.tri || Object.create(null), {
     messaging,
     excmds,
     commandline_background,
@@ -34,6 +35,7 @@ import { AutoContain } from "./lib/autocontainers"
     webext,
     l: prom => prom.then(console.log).catch(console.error),
     contentLocation: window.location,
+    perf,
 })
 
 // {{{ tri.contentLocation
@@ -159,3 +161,31 @@ browser.webRequest.onBeforeRequest.addListener(
     ["blocking"],
 )
 // }}}
+
+// {{{ PERFORMANCE LOGGING
+
+// An object to collect all of our statistics in one place.
+const statsLogger: perf.StatsLogger = new perf.StatsLogger()
+messaging.addListener(
+    "performance_background",
+    messaging.attributeCaller(statsLogger),
+)
+
+// Listen for statistics from the background script and store them.
+const perf_observer = new PerformanceObserver(
+    (list: PerformanceObserverEntryList, observer: PerformanceObserver) => {
+        statsLogger.pushList(list.getEntries())
+    },
+)
+perf_observer.observe({ entryTypes: ["mark", "measure"], buffered: true })
+window.tri = Object.assign(window.tri || Object.create(null), {
+    // Attach the perf observer to the window object since there
+    // appears to be a bug causing performance observers to be GC'd
+    // even if they're still the target of a callback.
+    perf_observer,
+    // Also attach the statsLogger so we can access our stats from the
+    // command line
+    statsLogger,
+})
+
+// }}}

src/commandline_frame.ts

@@ -16,6 +16,7 @@ import "./number.clamp"
 import state from "./state"
 import Logger from "./logging"
 import { theme } from "./styling"
+import * as perf from "./perf"
 const logger = new Logger("cmdline")
 
 let activeCompletions: Completions.CompletionSource[] = undefined
@@ -367,3 +368,18 @@ export function getContent() {
 }
 
 Messaging.addListener("commandline_frame", Messaging.attributeCaller(SELF))
+
+// Listen for statistics from the commandline's iframe and send them
+// to the background for collection.
+const perf_observer = new PerformanceObserver(
+    (list: PerformanceObserverEntryList, observer: PerformanceObserver) => {
+        perf.sendStats(list.getEntries())
+    },
+)
+perf_observer.observe({ entryTypes: ["mark", "measure"], buffered: true })
+window.tri = Object.assign(window.tri || Object.create(null), {
+    // Attach it to the window object since there's a bug that causes
+    // performance observers to be GC'd even if they still hold a
+    // callback.
+    perf_observer,
+})

src/completions/Buffer.ts

@@ -2,6 +2,7 @@ import { enumerate } from "../itertools"
 import * as Containers from "../lib/containers"
 import * as Messaging from "../messaging"
 import * as Completions from "../completions"
+import * as Perf from "../perf"
 
 class BufferCompletionOption extends Completions.CompletionOptionHTML
     implements Completions.CompletionOptionFuse {
@@ -66,6 +67,7 @@ export class BufferCompletionSource extends Completions.CompletionSourceFuse {
         this._parent.appendChild(this.node)
     }
 
+    @Perf.measuredAsync
     private async updateOptions(exstr?: string) {
         /* console.log('updateOptions', this.optionContainer) */
         const tabs: browser.tabs.Tab[] = await Messaging.message(

src/completions/BufferAll.ts

@@ -2,6 +2,7 @@ import { browserBg } from "../lib/webext"
 import * as Containers from "../lib/containers"
 import * as Messaging from "../messaging"
 import * as Completions from "../completions"
+import * as Perf from "../perf"
 
 class BufferAllCompletionOption extends Completions.CompletionOptionHTML
     implements Completions.CompletionOptionFuse {
@@ -62,6 +63,7 @@ export class BufferAllCompletionSource extends Completions.CompletionSourceFuse
         return response
     }
 
+    @Perf.measuredAsync
     private async updateOptions(exstr?: string) {
         const tabsPromise = Messaging.message(
             "commandline_background",

src/config.ts

@@ -587,6 +587,7 @@ class default_config {
         state: "warning",
         excmd: "error",
         styling: "warning",
+        performance: "warning",
     }
     noiframeon: string[] = []
 
@@ -668,6 +669,32 @@ class default_config {
      * JavaScript RegExp used to recognize words in im_* functions (e.g. im_transpose_words). Should match any character belonging to a word.
      */
     wordpattern = "[^\\s]+"
+
+    /**
+     * Activate tridactyl's performance counters. These have a
+     * measurable performance impact, since every sample is a few
+     * hundred bytes and we sample tridactyl densely, but they're good
+     * when you're trying to optimize things.
+     */
+    perfcounters: "true" | "false" = "false"
+
+    /**
+     * How many samples to store from the perf counters.
+     *
+     * Each performance entry is two numbers (16 bytes), an entryType
+     * of either "mark" or "measure" (js strings are utf-16 ad we have
+     * two marks for each measure, so amortize to about 10 bytes per
+     * entry), and a string name that for Tridactyl object will be
+     * about 40 (utf-16) characters (80 bytes), plus object overhead
+     * roughly proportional to the string-length of the name of the
+     * constructor (in this case something like 30 bytes), for a total
+     * of what we'll call 128 bytes for ease of math.
+     *
+     * We want to store, by default, about 1MB of performance
+     * statistics, so somewhere around 10k samples.
+     *
+     */
+    perfsamples: number = 10_000
 }
 
 /** @hidden */

src/content.ts

@@ -49,6 +49,7 @@ import Mark from "mark.js"
 import * as keyseq from "./keyseq"
 import * as native from "./native_background"
 import * as styling from "./styling"
+import * as perf from "./perf"
 ;(window as any).tri = Object.assign(Object.create(null), {
     browserBg: webext.browserBg,
     commandline_content,
@@ -69,6 +70,7 @@ import * as styling from "./styling"
     native,
     styling,
     contentLocation: window.location,
+    perf,
 })
 
 logger.info("Loaded commandline content?", commandline_content)
@@ -236,3 +238,18 @@ config.getAsync("leavegithubalone").then(v => {
         })
     }
 })
+
+// Listen for statistics from each content script and send them to the
+// background for collection.
+const perf_observer = new PerformanceObserver(
+    (list: PerformanceObserverEntryList, observer: PerformanceObserver) => {
+        perf.sendStats(list.getEntries())
+    },
+)
+perf_observer.observe({ entryTypes: ["mark", "measure"], buffered: true })
+;(window as any).tri = Object.assign(window.tri, {
+    // Attach it to the window object since there's a bug that causes
+    // performance observers to be GC'd even if they still hold a
+    // callback.
+    perf_observer,
+})

src/excmds.ts

@@ -106,6 +106,7 @@ import Mark from "mark.js"
 import * as CSS from "css"
 import * as Metadata from "./.metadata.generated"
 import { fitsType, typeToString } from "./metadata"
+import * as Perf from "./perf"
 
 //#content_helper
 // {
@@ -3854,6 +3855,72 @@ export async function ttscontrol(action: string) {
 
 //}}}
 
+// {{{ PERFORMANCE LOGGING
+
+/**
+ * Build a set of FilterConfigs from a list of human-input filter
+ * specs.
+ *
+ * @hidden
+ */
+//#background_helper
+export function buildFilterConfigs(filters: string[]): Perf.StatsFilterConfig[] {
+    return filters.map(
+        (filter: string): Perf.StatsFilterConfig => {
+            if (filter.endsWith("/")) {
+                return { filter: "ownerName", ownerName: filter.slice(0, -1) }
+            } else if (filter === ":start") {
+                return { filter: "eventType", eventType: "start" }
+            } else if (filter === ":end") {
+                return { filter: "eventType", eventType: "end" }
+            } else if (filter === ":measure") {
+                return { filter: "eventType", eventType: "measure" }
+            } else {
+                return { filter: "functionName", functionName: name }
+            }
+        },
+    )
+}
+
+/**
+ * Dump the raw json for our performance counters. Filters with
+ * trailing slashes are class names, :start | :end | :measure specify
+ * what type of sample to pass through, and all others are function
+ * names. All filters must match for a sample to be dumped.
+ *
+ * Tridactyl does not collect performance information by default. To
+ * get this data you'll have to set the configuration option
+ * `perfcounters` to `"true"`. You may also want to examine the value
+ * of `perfsamples`.
+ */
+//#background
+export async function dumpcounters(...filters: string[]) {
+    let filterconfigs = buildFilterConfigs(filters)
+    const entries = window.tri.statsLogger.getEntries(...filterconfigs)
+    console.log(filterconfigs)
+    open("data:application/json;charset=UTF-8," + JSON.stringify(entries))
+}
+
+/**
+ * Pretty-print a histogram of execution durations for you. Arguments
+ * are as above, with the addition that this automatically filters to
+ * counter samples of type :measure.
+ *
+ * Note that this will display its output by opening a data: url with
+ * text in the place of your current tab.
+ */
+//#background
+export async function perfhistogram(...filters: string[]) {
+    let filterconfigs = buildFilterConfigs(filters)
+    filterconfigs.push({ filter: "eventType", eventType: "measure" })
+    const entries = window.tri.statsLogger.getEntries(...filterconfigs)
+    const histogram = Perf.renderStatsHistogram(entries)
+    console.log(histogram)
+    open("data:text/plain;charset=UTF-8;base64," + btoa(histogram))
+}
+
+// }}}
+
 // unsupported on android
 /**
  * Add or remove a bookmark.

src/math.ts

@@ -1,3 +1,70 @@
 export function log(x, base) {
     return Math.log(x) / Math.log(base)
 }
+
+// Copied from Numeric Javascript under the MIT license
+// https://github.com/sloisel/numeric/blob/656fa1254be540f428710738ca9c1539625777f1/src/numeric.js#L922
+export function linspace(a: number, b: number, n?: number) {
+    if (typeof n === "undefined") n = Math.max(Math.round(b - a) + 1, 1)
+    if (n < 2) {
+        return n === 1 ? [a] : []
+    }
+    var i,
+        ret = Array(n)
+    n--
+    for (i = n; i >= 0; i--) {
+        ret[i] = (i * b + (n - i) * a) / n
+    }
+    return ret
+}
+
+export function buckets(values: number[], numBuckets: number): number[] {
+    const min = values.reduce((a, b) => Math.min(a, b))
+    const max = values.reduce((a, b) => Math.max(a, b))
+    return linspace(min, max, numBuckets)
+}
+
+export function bucketize(
+    values: number[],
+    buckets: number[],
+): Map<number, number> {
+    // Init result storage
+    const result: Map<number, number> = new Map<number, number>()
+    for (const bucketval of buckets) {
+        result.set(bucketval, 0)
+    }
+
+    // We place a value in a bucket by going through the buckets from
+    // smallest to largest, finding the smallest bucket that's larger
+    // than or equal to than the value. This will have the following
+    // results:
+    //
+    // * A value that's larger than all bucket values will not be
+    //   placed at all.
+    // * A value with exactly the value of the largest bucket will be
+    //   placed in the largest bucket.
+    // * A value with exactly the value of the smallest bucket will be
+    //   placed in the smallest bucket.
+    // * A value that's smaller than all bucket values will be placed
+    //   in the smallest bucket.
+    //
+    // If we build our buckets as linspace(min(values), max(values)),
+    // then this means that the largest bucket is guaranteed to have
+    // exactly one element in it.
+    const placeValue = (val: number) => {
+        for (const bucketval of buckets) {
+            if (bucketval >= val) {
+                result.set(bucketval, result.get(bucketval) + 1)
+                return
+            }
+        }
+    }
+
+    // Bucketize every value.
+    for (const val of values) {
+        placeValue(val)
+    }
+
+    // Return just the counts in each bucket
+    return result
+}

src/messaging.ts

@@ -11,6 +11,7 @@ export type NonTabMessageType =
     | "controller_background"
     | "browser_proxy_background"
     | "download_background"
+    | "performance_background"
 export type MessageType = TabMessageType | NonTabMessageType
 
 export interface Message {

src/perf.ts

@@ -0,0 +1,279 @@
+/** Library used for measuring performance. */
+
+import * as messaging from "./messaging"
+import * as config from "./config"
+import * as math from "./math"
+import * as itertools from "./itertools"
+import * as logging from "./logging"
+
+const logger = new logging.Logger("performance")
+
+export const TRI_PERFORMANCE_NAME_PREFIX: string = "tri"
+
+function performanceEnabled(): boolean {
+    return performance.mark !== undefined
+}
+
+interface MetricNameInfo {
+    ownerName: string
+    functionName: string
+    uniqueSuffix: string
+}
+
+const extractRegExp = new RegExp(
+    `^${TRI_PERFORMANCE_NAME_PREFIX}` +
+        // owner name
+        `/([^/]+)` +
+        // function name
+        `/([^:]+)` +
+        // unique suffix
+        `:([^:]+)`,
+    // No need to handle :start/:end
+    // because we can get that from the
+    // sample itself.
+)
+function extractMetricName(counterName: string): MetricNameInfo {
+    const matchresult = counterName.match(extractRegExp)
+    if (!matchresult) return
+    const [_, ownerName, functionName, uniqueSuffix, startOrEnd] = matchresult
+
+    return {
+        ownerName,
+        functionName,
+        uniqueSuffix,
+    }
+}
+
+export class MetricName {
+    public readonly fullName: string
+    public readonly startName: string
+    public readonly endName: string
+
+    constructor(ownerName: string, functionName: string) {
+        const counterName = ownerName
+        const uniqueSuffix = Math.floor(
+            Math.random() * Math.floor(1e6),
+        ).toString()
+
+        this.fullName = `${TRI_PERFORMANCE_NAME_PREFIX}/${ownerName}/${functionName}:${uniqueSuffix}`
+        this.startName = `${this.fullName}:start`
+        this.endName = `${this.fullName}:end`
+    }
+}
+
+export class Marker {
+    constructor(
+        ownerName: string,
+        functionName: string,
+        private readonly active: boolean = config.get("perfcounters") == "true",
+        private readonly metricName: MetricName = new MetricName(
+            ownerName,
+            functionName,
+        ),
+    ) {}
+
+    public start() {
+        if (!this.active) return
+        performance.mark(this.metricName.startName)
+    }
+
+    public end() {
+        if (!this.active) return
+        performance.mark(this.metricName.endName)
+        performance.measure(
+            this.metricName.fullName,
+            this.metricName.startName,
+            this.metricName.endName,
+        )
+    }
+}
+
+/**
+ * Decorator for performance measuring. If performance is enabled,
+ * wraps the function call with performance marks and a measure that
+ * can be used for profiling.
+ */
+export function measured(
+    cls: any,
+    propertyKey: string,
+    descriptor: PropertyDescriptor,
+): PropertyDescriptor | void {
+    // do nothing if performance isn't available
+    if (!performanceEnabled()) return
+
+    const originalMethod = descriptor.value
+    descriptor.value = function(this, ...args) {
+        const marker = new Marker(cls.constructor.name, propertyKey)
+        marker.start()
+        const result = originalMethod.apply(this, args)
+        marker.end()
+        return result
+    }
+    return descriptor
+}
+
+/**
+ * Like the @measured decorator, but properly handles async functions
+ * by chaining a resolution onto the promise that marks completion
+ * when the function resolves its promise.
+ */
+export function measuredAsync(
+    cls: any,
+    propertyKey: string,
+    descriptor: PropertyDescriptor,
+): PropertyDescriptor | void {
+    // do nothing if performance isn't available
+    if (!performanceEnabled()) return
+
+    const originalMethod = descriptor.value
+    descriptor.value = async function(this, ...args) {
+        const marker = new Marker(cls.constructor.name, propertyKey)
+        marker.start()
+        const result = await originalMethod.apply(this, args)
+        marker.end()
+        return result
+    }
+    return descriptor
+}
+
+export type StatsFilterConfig =
+    | { filter: "functionName"; functionName: string }
+    | { filter: "ownerName"; ownerName: string }
+    | { filter: "eventType"; eventType: "start" | "end" | "measure" }
+
+class StatsFilter {
+    constructor(private readonly config: StatsFilterConfig) {}
+
+    matches(entry: PerformanceEntry): boolean {
+        const metricNameInfo = extractMetricName(entry.name)
+        if (
+            this.config.filter === "functionName" &&
+            this.config.functionName !== metricNameInfo.functionName
+        ) {
+            return false
+        }
+        if (
+            this.config.filter === "ownerName" &&
+            this.config.ownerName !== metricNameInfo.ownerName
+        ) {
+            return false
+        }
+        if (
+            this.config.filter === "eventType" &&
+            this.config.eventType !== entry.entryType
+        ) {
+            return false
+        }
+        return true
+    }
+}
+
+// export function makeObserver() {
+//     const perf_observer = new PerformanceObserver((list, observer) => {
+//         console.log("commandline_frame performance: %O", list.getEntries())
+//         console.log("commandline_frame take records: %O", observer.takeRecords())
+//     })
+//     perf_observer.observe({entryTypes: ['mark', 'measure'], buffered: true})
+//     // Attach it to the window object since there's a bug that causes
+//     // performance observers to be GC'd even if they're attached.
+//     ;(window as any).tri = Object.assign(Object.create(null), {
+//         perf_observer,
+//     })
+// }
+
+export function sendStats(list: PerformanceEntryList) {
+    messaging.message("performance_background", "receiveStatsJson", [
+        JSON.stringify(list),
+    ])
+}
+
+export class StatsLogger {
+    // TODO: Consider mapping each name to a symbol and storing the
+    // mapped symbol instead of the name so we're storing more like 50
+    // bytes per sample instead of 130 @_@
+    public buffer: PerformanceEntry[] = []
+    private idx: number = 0
+
+    constructor() {}
+
+    private incrementIdx() {
+        // Changing the buffer length while this is running will
+        // probably result in weirdness, but that shouldn't be a major
+        // issue - it's not like we need these to be in order or
+        // otherwise coherent, we're just trying to store a big pile
+        // of recent-ish samples.
+        this.idx = (this.idx + 1) % config.get("perfsamples")
+    }
+
+    public receiveStatsJson(entriesJson: string) {
+        this.pushList(JSON.parse(entriesJson) as PerformanceEntry[])
+    }
+
+    public pushList(entries: PerformanceEntry[]) {
+        for (const entry of entries) {
+            this.pushEntry(entry)
+        }
+    }
+
+    public pushEntry(entry: PerformanceEntry) {
+        // Drop samples that aren't for tridactyl, since performance
+        // events are global and there are some badly-behaved
+        // libraries spamming them all over our own data.
+        if (!entry.name.startsWith(TRI_PERFORMANCE_NAME_PREFIX)) return
+
+        // We depend on arrays auto-vivifying when elements past the
+        // end are set to make this easy.
+        this.buffer[this.idx] = entry
+        this.incrementIdx()
+    }
+
+    /**
+     * Returns only entries that match _all_ of the given filter
+     * configs.
+     */
+    public getEntries(...filterConfigs: StatsFilterConfig[]) {
+        // Explicit stream fusion, wheeeee.
+        //
+        // Well, sort of. We're not fusing all the way up to the regex
+        // match, so that's a ton of duplicated work. Not that it
+        // matters, since this should only ever be invoked when a
+        // developer asks for data.
+        const filters: StatsFilter[] = filterConfigs.map(
+            fc => new StatsFilter(fc),
+        )
+        const filterFun: (input: PerformanceEntry) => boolean = e =>
+            filters.every(f => f.matches(e))
+        return this.buffer.filter(filterFun)
+    }
+}
+
+export function renderStatsHistogram(
+    samples: PerformanceEntry[],
+    buckets: number = 15,
+    width: number = 80,
+): string {
+    const durs: number[] = samples.map(sample => sample.duration)
+
+    const min = durs.reduce((a, b) => Math.min(a, b))
+    const max = durs.reduce((a, b) => Math.max(a, b))
+
+    const bucketvals: number[] = math.linspace(min, max, buckets)
+
+    const bucketed: Map<number, number> = math.bucketize(durs, bucketvals)
+    const maxcount: number = Array.from(bucketed.values()).reduce(
+        (a, b) => Math.max(a, b),
+        0,
+    )
+
+    const labelwidth = 20
+    const barwidth = width - labelwidth
+    const tobarwidth = n => (barwidth * n) / maxcount
+
+    const result = []
+    for (const [bucketval, bucketcount] of bucketed.entries()) {
+        const bar = "#".repeat(tobarwidth(bucketcount))
+        const label = bucketval.toString().padEnd(labelwidth)
+        result.push(label + bar)
+    }
+    return result.join("\n")
+}

src/tridactyl.d.ts

@@ -16,6 +16,12 @@ interface Window {
     eval(str: string): any
 }
 
+// Record that we've added a property with convenience objects to the
+// window object:
+interface Window {
+    tri: any
+}
+
 // Again, firefox-specific
 interface UIEvent {
     pageX: number

tsconfig.json

@@ -8,7 +8,8 @@
     "target": "ES2017",
     "lib": ["ES2017","dom", "dom.iterable"],
     "typeRoots": ["node_modules/@types", "node_modules/web-ext-types/"],
-    "alwaysStrict": true
+    "alwaysStrict": true,
+    "experimentalDecorators": true,
   },
   "include": [
     "./src/**/*"