Added fine-grain timing for aspects of the bake. Improved efficiency of autobakes and moved output decoding into a worker.

src/web/App.mjs

@@ -160,11 +160,9 @@ class App {
 
         if (this.autoBake_ && !this.baking) {
             log.debug("Auto-baking");
-            this.manager.input.inputWorker.postMessage({
+            this.manager.worker.bakeInputs({
-                action: "autobake",
+                nums: [this.manager.tabs.getActiveTab("input")],
-                data: {
+                step: false
-                    activeTab: this.manager.tabs.getActiveTab("input")
-                }
             });
         } else {
             this.manager.controls.showStaleIndicator();

src/web/Manager.mjs

@@ -17,6 +17,7 @@ import SeasonalWaiter from "./waiters/SeasonalWaiter.mjs";
 import BindingsWaiter from "./waiters/BindingsWaiter.mjs";
 import BackgroundWorkerWaiter from "./waiters/BackgroundWorkerWaiter.mjs";
 import TabWaiter from "./waiters/TabWaiter.mjs";
+import TimingWaiter from "./waiters/TimingWaiter.mjs";
 
 
 /**
@@ -59,6 +60,7 @@ class Manager {
         this.statechange = new CustomEvent("statechange", {bubbles: true});
 
         // Define Waiter objects to handle various areas
+        this.timing      = new TimingWaiter(this.app, this);
         this.worker      = new WorkerWaiter(this.app, this);
         this.window      = new WindowWaiter(this.app);
         this.controls    = new ControlsWaiter(this.app, this);

src/web/utils/statusBar.mjs

@@ -18,7 +18,8 @@ class StatusBarPanel {
      */
     constructor(opts) {
         this.label = opts.label;
-        this.bakeStats = opts.bakeStats ? opts.bakeStats : null;
+        this.timing = opts.timing;
+        this.tabNumGetter = opts.tabNumGetter;
         this.eolHandler = opts.eolHandler;
         this.chrEncHandler = opts.chrEncHandler;
         this.chrEncGetter = opts.chrEncGetter;
@@ -243,18 +244,21 @@ class StatusBarPanel {
     }
 
     /**
-     * Sets the latest bake duration
+     * Sets the latest timing info
      */
-    updateBakeStats() {
+    updateTiming() {
+        if (!this.timing) return;
+
         const bakingTime = this.dom.querySelector(".baking-time-value");
         const bakingTimeInfo = this.dom.querySelector(".baking-time-info");
 
-        if (this.label === "Output" &&
+        if (this.label === "Output" && this.timing) {
-            this.bakeStats &&
-            typeof this.bakeStats.duration === "number" &&
-            this.bakeStats.duration >= 0) {
             bakingTimeInfo.style.display = "inline-block";
-            bakingTime.textContent = this.bakeStats.duration;
+            bakingTime.textContent = this.timing.overallDuration(this.tabNumGetter());
+
+            const info = this.timing.printStages(this.tabNumGetter()).replace(/\n/g, "<br>");
+            bakingTimeInfo.setAttribute("title", info);
+            bakingTimeInfo.setAttribute("data-original-title", info);
         } else {
             bakingTimeInfo.style.display = "none";
         }
@@ -335,7 +339,7 @@ class StatusBarPanel {
         ).join("");
 
         return `
-            <span class="baking-time-info" style="display: none" data-toggle="tooltip" title="Baking time">
+            <span class="baking-time-info" style="display: none" data-toggle="tooltip" data-html="true" title="Baking time">
                 <i class="material-icons">schedule</i>
                 <span class="baking-time-value"></span>ms
             </span>
@@ -429,7 +433,7 @@ function makePanel(opts) {
     return (view) => {
         sbPanel.updateEOL(view.state);
         sbPanel.updateCharEnc();
-        sbPanel.updateBakeStats();
+        sbPanel.updateTiming();
         sbPanel.updateStats(view.state.doc);
         sbPanel.updateSelection(view.state, false);
         sbPanel.monitorHTMLOutput();
@@ -440,7 +444,7 @@ function makePanel(opts) {
                 sbPanel.updateEOL(update.state);
                 sbPanel.updateCharEnc();
                 sbPanel.updateSelection(update.state, update.selectionSet);
-                sbPanel.updateBakeStats();
+                sbPanel.updateTiming();
                 sbPanel.monitorHTMLOutput();
                 if (update.geometryChanged) {
                     sbPanel.updateSizing(update.view);

src/web/waiters/InputWaiter.mjs

@@ -462,8 +462,8 @@ class InputWaiter {
             case "queueInputError":
                 this.manager.worker.queueInputError(r.data);
                 break;
-            case "bakeAllInputs":
+            case "bakeInputs":
-                this.manager.worker.bakeAllInputs(r.data);
+                this.manager.worker.bakeInputs(r.data);
                 break;
             case "displayTabSearchResults":
                 this.displayTabSearchResults(r.data);
@@ -544,12 +544,14 @@ class InputWaiter {
             }
 
             // Decode the data to a string
+            this.manager.timing.recordTime("inputEncodingStart", inputNum);
             let inputVal;
             if (this.getChrEnc() > 0) {
                 inputVal = cptable.utils.decode(this.inputChrEnc, new Uint8Array(inputData.buffer));
             } else {
                 inputVal = Utils.arrayBufferToStr(inputData.buffer);
             }
+            this.manager.timing.recordTime("inputEncodingEnd", inputNum);
 
             // Populate the input editor
             this.setInput(inputVal);
@@ -684,6 +686,8 @@ class InputWaiter {
         let stringSample = "";
 
         // If value is a string, interpret it using the specified character encoding
+        const tabNum = this.manager.tabs.getActiveTab("input");
+        this.manager.timing.recordTime("inputEncodingStart", tabNum);
         if (typeof value === "string") {
             stringSample = value.slice(0, 4096);
             if (this.getChrEnc() > 0) {
@@ -696,6 +700,7 @@ class InputWaiter {
             buffer = value;
             stringSample = Utils.arrayBufferToStr(value.slice(0, 4096));
         }
+        this.manager.timing.recordTime("inputEncodingEnd", tabNum);
 
         // Update the deep link
         const recipeStr = buffer.byteLength < 51200 ? toBase64(buffer, "A-Za-z0-9+/") : ""; // B64 alphabet with no padding

src/web/waiters/OutputWaiter.mjs

@@ -9,7 +9,6 @@ import Utils, {debounce} from "../../core/Utils.mjs";
 import Dish from "../../core/Dish.mjs";
 import FileSaver from "file-saver";
 import ZipWorker from "worker-loader?inline=no-fallback!../workers/ZipWorker.mjs";
-import cptable from "codepage";
 
 import {
     EditorView,
@@ -57,10 +56,6 @@ class OutputWaiter {
         this.manager = manager;
 
         this.outputTextEl = document.getElementById("output-text");
-        // Object to contain bake statistics - used by statusBar extension
-        this.bakeStats = {
-            duration: 0
-        };
         // Object to handle output HTML state - used by htmlWidget extension
         this.htmlOutput = {
             html: "",
@@ -106,7 +101,10 @@ class OutputWaiter {
                 // Custom extensions
                 statusBar({
                     label: "Output",
-                    bakeStats: this.bakeStats,
+                    timing: this.manager.timing,
+                    tabNumGetter: function() {
+                        return this.manager.tabs.getActiveTab("output");
+                    }.bind(this),
                     eolHandler: this.eolChange.bind(this),
                     chrEncHandler: this.chrEncChange.bind(this),
                     chrEncGetter: this.getChrEnc.bind(this),
@@ -145,7 +143,7 @@ class OutputWaiter {
      * Sets the line separator
      * @param {string} eolVal
      */
-    eolChange(eolVal) {
+    async eolChange(eolVal) {
         const currentTabNum = this.manager.tabs.getActiveTab("output");
         if (currentTabNum >= 0) {
             this.outputs[currentTabNum].eolSequence = eolVal;
@@ -159,7 +157,7 @@ class OutputWaiter {
         });
 
         // Reset the output so that lines are recalculated, preserving the old EOL values
-        this.setOutput(this.currentOutputCache, true);
+        await this.setOutput(this.currentOutputCache, true);
         // Update the URL manually since we aren't firing a statechange event
         this.app.updateURL(true);
     }
@@ -182,7 +180,7 @@ class OutputWaiter {
      * Sets the output character encoding
      * @param {number} chrEncVal
      */
-    chrEncChange(chrEncVal) {
+    async chrEncChange(chrEncVal) {
         if (typeof chrEncVal !== "number") return;
 
         const currentTabNum = this.manager.tabs.getActiveTab("output");
@@ -193,7 +191,7 @@ class OutputWaiter {
         }
 
         // Reset the output, forcing it to re-decode the data with the new character encoding
-        this.setOutput(this.currentOutputCache, true);
+        await this.setOutput(this.currentOutputCache, true);
         // Update the URL manually since we aren't firing a statechange event
         this.app.updateURL(true);
     }
@@ -227,24 +225,18 @@ class OutputWaiter {
      * @param {string|ArrayBuffer} data
      * @param {boolean} [force=false]
      */
-    setOutput(data, force=false) {
+    async setOutput(data, force=false) {
         // Don't do anything if the output hasn't changed
         if (!force && data === this.currentOutputCache) return;
         this.currentOutputCache = data;
 
         // If data is an ArrayBuffer, convert to a string in the correct character encoding
+        const tabNum = this.manager.tabs.getActiveTab("output");
+        this.manager.timing.recordTime("outputDecodingStart", tabNum);
         if (data instanceof ArrayBuffer) {
-            const encoding = this.getChrEnc();
+            data = await this.bufferToStr(data);
-            if (encoding === 0) {
-                data = Utils.arrayBufferToStr(data);
-            } else {
-                try {
-                    data = cptable.utils.decode(encoding, new Uint8Array(data));
-                } catch (err) {
-                    data = err;
-                }
-            }
         }
+        this.manager.timing.recordTime("outputDecodingEnd", tabNum);
 
         // Turn drawSelection back on
         this.outputEditorView.dispatch({
@@ -267,12 +259,12 @@ class OutputWaiter {
      * Sets the value of the current output to a rendered HTML value
      * @param {string} html
      */
-    setHTMLOutput(html) {
+    async setHTMLOutput(html) {
         this.htmlOutput.html = html;
         this.htmlOutput.changed = true;
         // This clears the text output, but also fires a View update which
         // triggers the htmlWidget to render the HTML.
-        this.setOutput("");
+        await this.setOutput("");
 
         // Turn off drawSelection
         this.outputEditorView.dispatch({
@@ -518,6 +510,7 @@ class OutputWaiter {
 
         return new Promise(async function(resolve, reject) {
             const output = this.outputs[inputNum];
+            this.manager.timing.recordTime("settingOutput", inputNum);
 
             // Update the EOL value
             this.outputEditorView.dispatch({
@@ -553,34 +546,41 @@ class OutputWaiter {
                 this.clearHTMLOutput();
 
                 if (output.error) {
-                    this.setOutput(output.error);
+                    await this.setOutput(output.error);
                 } else {
-                    this.setOutput(output.data.result);
+                    await this.setOutput(output.data.result);
                 }
             } else if (output.status === "baked" || output.status === "inactive") {
                 document.querySelector("#output-loader .loading-msg").textContent = `Loading output ${inputNum}`;
 
                 if (output.data === null) {
                     this.clearHTMLOutput();
-                    this.setOutput("");
+                    await this.setOutput("");
                     this.toggleLoader(false);
                     return;
                 }
 
-                this.bakeStats.duration = output.data.duration;
-
                 switch (output.data.type) {
                     case "html":
-                        this.setHTMLOutput(output.data.result);
+                        await this.setHTMLOutput(output.data.result);
                         break;
                     case "ArrayBuffer":
                     case "string":
                     default:
                         this.clearHTMLOutput();
-                        this.setOutput(output.data.result);
+                        await this.setOutput(output.data.result);
                         break;
                 }
                 this.toggleLoader(false);
+                this.manager.timing.recordTime("complete", inputNum);
+
+                // Trigger an update so that the status bar recalculates timings
+                this.outputEditorView.dispatch({
+                    changes: {
+                        from: 0,
+                        to: 0
+                    }
+                });
 
                 debounce(this.backgroundMagic, 50, "backgroundMagic", this, [])();
             }
@@ -630,6 +630,22 @@ class OutputWaiter {
         });
     }
 
+    /**
+     * Asks a worker to translate an ArrayBuffer into a certain character encoding
+     *
+     * @param {ArrrayBuffer} buffer
+     * @returns {string}
+     */
+    async bufferToStr(buffer) {
+        const encoding = this.getChrEnc();
+
+        return await new Promise(resolve => {
+            this.manager.worker.bufferToStr(buffer, encoding, r => {
+                resolve(r.value);
+            });
+        });
+    }
+
     /**
      * Save bombe object then remove it from the DOM so that it does not cause performance issues.
      */

src/web/waiters/TimingWaiter.mjs

@@ -0,0 +1,145 @@
+/**
+ * @author n1474335 [n1474335@gmail.com]
+ * @copyright Crown Copyright 2023
+ * @license Apache-2.0
+ */
+
+/**
+ * Waiter to handle timing of the baking process.
+ */
+class TimingWaiter {
+
+    /**
+     * TimingWaiter constructor.
+     *
+     * @param {App} app - The main view object for CyberChef.
+     * @param {Manager} manager - The CyberChef event manager.
+     */
+    constructor(app, manager) {
+        this.app = app;
+        this.manager = manager;
+
+        this.inputs = {};
+        /*
+            Inputs example:
+            "1": {
+                "inputEncodingStart": 0,
+                "inputEncodingEnd": 0,
+                "trigger": 0
+                "chefWorkerTasked": 0,
+                "bakeComplete": 0,
+                "bakeDuration": 0,
+                "settingOutput": 0,
+                "outputDecodingStart": 0,
+                "outputDecodingEnd": 0,
+                "complete": 0
+            }
+        */
+    }
+
+
+    /**
+     * Record the time for an input
+     *
+     * @param {string} event
+     * @param {number} inputNum
+     * @param {number} value
+     */
+    recordTime(event, inputNum, value=Date.now()) {
+        inputNum = inputNum.toString();
+        if (!Object.keys(this.inputs).includes(inputNum)) {
+            this.inputs[inputNum] = {};
+        }
+        log.debug(`Recording ${event} for input ${inputNum}`);
+        this.inputs[inputNum][event] = value;
+    }
+
+    /**
+     * The total time for a completed bake
+     *
+     * @param {number} inputNum
+     * @returns {number}
+     */
+    overallDuration(inputNum) {
+        const input = this.inputs[inputNum.toString()];
+
+        // If this input has not been encoded yet, we cannot calculate a time
+        if (!input ||
+            !input.trigger ||
+            !input.inputEncodingEnd ||
+            !input.inputEncodingStart)
+            return 0;
+
+        // input encoding can happen before a bake is triggered, so it is calculated separately
+        const inputEncodingTotal = input.inputEncodingEnd - input.inputEncodingStart;
+
+        let total = 0;
+        if (input.bakeComplete && input.bakeComplete > input.trigger)
+            total = input.bakeComplete - input.trigger;
+
+        if (input.settingOutput && input.settingOutput > input.trigger)
+            total = input.settingOutput - input.trigger;
+
+        if (input.outputDecodingStart && input.outputDecodingStart > input.trigger)
+            total = input.outputDecodingStart - input.trigger;
+
+        if (input.outputDecodingEnd && input.outputDecodingEnd > input.trigger)
+            total = input.outputDecodingEnd - input.trigger;
+
+        if (input.complete && input.complete > input.trigger)
+            total = input.complete - input.trigger;
+
+        return total + inputEncodingTotal;
+    }
+
+    /**
+     * Prints out the time between stages
+     *
+     * @param {number} inputNum
+     * @returns {string}
+     */
+    printStages(inputNum) {
+        const input = this.inputs[inputNum.toString()];
+        if (!input || !input.trigger) return "";
+        this.logAllTimes(inputNum);
+
+        const total = this.overallDuration(inputNum),
+            inputEncoding = input.inputEncodingEnd - input.inputEncodingStart,
+            outputDecoding = input.outputDecodingEnd - input.outputDecodingStart,
+            overhead = total - inputEncoding - outputDecoding - input.bakeDuration;
+
+        return `Input encoding: ${inputEncoding}ms
+Recipe duration: ${input.bakeDuration}ms
+Output decoding: ${outputDecoding}ms
+Threading overhead: ${overhead}ms
+Total: ${total}ms`;
+    }
+
+    /**
+     * Logs every interval
+     *
+     * @param {number} inputNum
+     */
+    logAllTimes(inputNum) {
+        const input = this.inputs[inputNum.toString()];
+        if (!input || !input.trigger) return;
+
+        try {
+            log.debug(`Trigger:             ${input.trigger}
+inputEncodingStart:  ${input.inputEncodingStart} | ${input.inputEncodingStart - input.trigger}ms since trigger
+inputEncodingEnd:    ${input.inputEncodingEnd} | ${input.inputEncodingEnd - input.inputEncodingStart}ms input encoding time
+chefWorkerTasked:    ${input.chefWorkerTasked} | ${input.chefWorkerTasked - input.trigger}ms since trigger
+bakeDuration:                      | ${input.bakeDuration}ms duration in worker
+bakeComplete:        ${input.bakeComplete} | ${input.bakeComplete - input.chefWorkerTasked}ms since worker tasked
+settingOutput:       ${input.settingOutput} | ${input.settingOutput - input.bakeComplete}ms since worker finished
+outputDecodingStart: ${input.outputDecodingStart} | ${input.outputDecodingStart - input.settingOutput}ms since output set
+outputDecodingEnd:   ${input.outputDecodingEnd} | ${input.outputDecodingEnd - input.outputDecodingStart}ms output encoding time
+complete:            ${input.complete} | ${input.complete - input.outputDecodingEnd}ms since output decoded
+Total:                             | ${input.complete - input.trigger}ms since trigger`);
+        } catch (err) {}
+
+    }
+
+}
+
+export default TimingWaiter;

src/web/waiters/WorkerWaiter.mjs

@@ -197,6 +197,8 @@ class WorkerWaiter {
         switch (r.action) {
             case "bakeComplete":
                 log.debug(`Bake ${inputNum} complete.`);
+                this.manager.timing.recordTime("bakeComplete", inputNum);
+                this.manager.timing.recordTime("bakeDuration", inputNum, r.data.duration);
 
                 if (r.data.error) {
                     this.app.handleError(r.data.error);
@@ -464,6 +466,7 @@ class WorkerWaiter {
         if (input instanceof ArrayBuffer || ArrayBuffer.isView(input)) {
             transferable = [input];
         }
+        this.manager.timing.recordTime("chefWorkerTasked", nextInput.inputNum);
         this.chefWorkers[workerIdx].worker.postMessage({
             action: "bake",
             data: {
@@ -559,7 +562,9 @@ class WorkerWaiter {
      * @param {boolean} inputData.step - If true, only execute the next operation in the recipe
      * @param {number} inputData.progress - The current progress through the recipe. Used when stepping
      */
-    async bakeAllInputs(inputData) {
+    async bakeInputs(inputData) {
+        log.debug(`Baking input list [${inputData.nums.join(",")}]`);
+
         return await new Promise(resolve => {
             if (this.app.baking) return;
             const inputNums = inputData.nums;
@@ -595,6 +600,7 @@ class WorkerWaiter {
                 numBakes = this.inputNums.length;
             }
             for (let i = 0; i < numBakes; i++) {
+                this.manager.timing.recordTime("trigger", this.inputNums[0]);
                 this.manager.input.inputWorker.postMessage({
                     action: "bakeNext",
                     data: {
@@ -654,7 +660,7 @@ class WorkerWaiter {
     }
 
     /**
-     * Asks the ChefWorker to return the dish as the specified type
+     * Asks the DishWorker to return the dish as the specified type
      *
      * @param {Dish} dish
      * @param {string} type
@@ -662,10 +668,9 @@ class WorkerWaiter {
      */
     getDishAs(dish, type, callback) {
         const id = this.callbackID++;
-
         this.callbacks[id] = callback;
-
         if (this.dishWorker.worker === null) this.setupDishWorker();
+
         this.postDishMessage({
             action: "getDishAs",
             data: {
@@ -677,7 +682,7 @@ class WorkerWaiter {
     }
 
     /**
-     * Asks the ChefWorker to get the title of the dish
+     * Asks the DishWorker to get the title of the dish
      *
      * @param {Dish} dish
      * @param {number} maxLength
@@ -686,9 +691,7 @@ class WorkerWaiter {
      */
     getDishTitle(dish, maxLength, callback) {
         const id = this.callbackID++;
-
         this.callbacks[id] = callback;
-
         if (this.dishWorker.worker === null) this.setupDishWorker();
 
         this.postDishMessage({
@@ -701,6 +704,29 @@ class WorkerWaiter {
         });
     }
 
+    /**
+     * Asks the DishWorker to translate a buffer into a specific character encoding
+     *
+     * @param {ArrayBuffer} buffer
+     * @param {number} encoding
+     * @param {Function} callback
+     * @returns {string}
+     */
+    bufferToStr(buffer, encoding, callback) {
+        const id = this.callbackID++;
+        this.callbacks[id] = callback;
+        if (this.dishWorker.worker === null) this.setupDishWorker();
+
+        this.postDishMessage({
+            action: "bufferToStr",
+            data: {
+                buffer: buffer,
+                encoding: encoding,
+                id: id
+            }
+        });
+    }
+
     /**
      * Queues a message to be sent to the dishWorker
      *

src/web/workers/DishWorker.mjs

@@ -7,6 +7,8 @@
  */
 
 import Dish from "../../core/Dish.mjs";
+import Utils from "../../core/Utils.mjs";
+import cptable from "codepage";
 import loglevelMessagePrefix from "loglevel-message-prefix";
 
 loglevelMessagePrefix(log, {
@@ -26,6 +28,9 @@ self.addEventListener("message", function(e) {
         case "getDishTitle":
             getDishTitle(r.data);
             break;
+        case "bufferToStr":
+            bufferToStr(r.data);
+            break;
         case "setLogLevel":
             log.setLevel(r.data, false);
             break;
@@ -76,3 +81,32 @@ async function getDishTitle(data) {
         }
     });
 }
+
+/**
+ * Translates a buffer to a string using a specified encoding
+ *
+ * @param {object} data
+ * @param {ArrayBuffer} data.buffer
+ * @param {number} data.id
+ * @param {number} data.encoding
+ */
+async function bufferToStr(data) {
+    let str;
+    if (data.encoding === 0) {
+        str = Utils.arrayBufferToStr(data.buffer);
+    } else {
+        try {
+            str = cptable.utils.decode(data.encoding, new Uint8Array(data.buffer));
+        } catch (err) {
+            str = err;
+        }
+    }
+
+    self.postMessage({
+        action: "dishReturned",
+        data: {
+            value: str,
+            id: data.id
+        }
+    });
+}

src/web/workers/InputWorker.mjs

@@ -174,7 +174,7 @@ self.autoBake = function(inputNum, progress, step=false) {
     const input = self.inputs[inputNum];
     if (input) {
         self.postMessage({
-            action: "bakeAllInputs",
+            action: "bakeInputs",
             data: {
                 nums: [parseInt(inputNum, 10)],
                 step: step,
@@ -196,7 +196,7 @@ self.bakeAllInputs = function() {
         .map(n => parseInt(n, 10));
 
     self.postMessage({
-        action: "bakeAllInputs",
+        action: "bakeInputs",
         data: {
             nums: nums,
             step: false,