perf milestone and measurement updates for minecraft

.vscode/launch.json

@@ -43,6 +43,28 @@
 			"sourceMaps": false,
 			"outFiles": []
 		},
+		{
+			"name": "pxt serve (minecraft)",
+			"type": "node",
+			"request": "launch",
+			"program": "${workspaceRoot}/built/pxt.js",
+			"stopOnEntry": false,
+			"args": [
+				"serve",
+				"--noauth"
+			],
+			"cwd": "${workspaceRoot}/../pxt-minecraft",
+			"runtimeExecutable": null,
+			"runtimeArgs": [
+				"--nolazy"
+			],
+			"env": {
+				"NODE_ENV": "development"
+			},
+			"console": "integratedTerminal",
+			"sourceMaps": false,
+			"outFiles": []
+		},
 		{
 			"name": "pxt serve (microbit)",
 			"type": "node",

docfiles/pxtweb/cookieCompliance.ts

@@ -38,20 +38,50 @@ namespace pxt {
     let eventLogger: TelemetryQueue<string, Map<string>, Map<number>>;
     let exceptionLogger: TelemetryQueue<any, string, Map<string>>;
 
+    type EventListener<T = any> = (payload: T) => void;
+    type EventSource<T> = {
+        subscribe(listener: (payload: T) => void): () => void;
+        emit(payload: T): void;
+    };
+
+    function createEventSource<T = any>(): EventSource<T> {
+        const listeners: EventListener<T>[] = [];
+
+        return {
+            subscribe(listener: EventListener<T>): () => void {
+                listeners.push(listener);
+                // Return an unsubscribe function
+                return () => {
+                    const index = listeners.indexOf(listener);
+                    if (index !== -1) {
+                        listeners.splice(index, 1);
+                    }
+                };
+            },
+            emit(payload: T): void {
+                listeners.forEach(listener => listener(payload));
+            }
+        };
+    }
+
     // performance measuring, added here because this is amongst the first (typescript) code ever executed
     export namespace perf {
         let enabled: boolean;
 
+        export const onMilestone = createEventSource<{ milestone: string, time: number, params?: Map<string> }>();
+        export const onMeasurement = createEventSource<{ name: string, start: number, duration: number, params?: Map<string> }>();
+
         export let startTimeMs: number;
         export let stats: {
             // name, start, duration
-            durations: [string, number, number][],
+            durations: [string, number, number, Map<string>?][],
             // name, event
-            milestones: [string, number][]
+            milestones: [string, number, Map<string>?][]
         } = {
             durations: [],
             milestones: []
         }
+        export function isEnabled() { return enabled; }
         export let perfReportLogged = false
         export function splitMs(): number {
             return Math.round(performance.now() - startTimeMs)
@@ -75,8 +105,10 @@ namespace pxt {
             return prettyStr(splitMs())
         }
 
-        export function recordMilestone(msg: string, time: number = splitMs()) {
-            stats.milestones.push([msg, time])
+        export function recordMilestone(msg: string, params?: Map<string>) {
+            const time = splitMs()
+            stats.milestones.push([msg, time, params])
+            onMilestone.emit({ milestone: msg, time, params });
         }
         export function init() {
             enabled = performance && !!performance.mark && !!performance.measure;
@@ -89,7 +121,7 @@ namespace pxt {
         export function measureStart(name: string) {
             if (enabled) performance.mark(`${name} start`)
         }
-        export function measureEnd(name: string) {
+        export function measureEnd(name: string, params?: Map<string>) {
             if (enabled && performance.getEntriesByName(`${name} start`).length) {
                 performance.mark(`${name} end`)
                 performance.measure(`${name} elapsed`, `${name} start`, `${name} end`)
@@ -98,7 +130,8 @@ namespace pxt {
                     let measure = e[0]
                     let durMs = measure.duration
                     if (durMs > 10) {
-                        stats.durations.push([name, measure.startTime, durMs])
+                        stats.durations.push([name, measure.startTime, durMs, params])
+                        onMeasurement.emit({ name, start: measure.startTime, duration: durMs, params });
                     }
                 }
                 performance.clearMarks(`${name} start`)
@@ -108,34 +141,44 @@ namespace pxt {
         }
         export function report(filter: string = null) {
             perfReportLogged = true;
-
             if (enabled) {
-                const milestones: {[index: string]: number} = {};
-                const durations: {[index: string]: number} = {};
+                const milestones: { [index: string]: number } = {};
+                const durations: { [index: string]: number } = {};
 
-                let report = `performance report:\n`
-                for (let [msg, time] of stats.milestones) {
+                let report = `Performance Report:\n`
+                report += `\n`
+                report += `\tMilestones:\n`
+                for (let [msg, time, params] of stats.milestones) {
                     if (!filter || msg.indexOf(filter) >= 0) {
                         let pretty = prettyStr(time)
-                        report += `\t\t${msg} @ ${pretty}\n`
+                        report += `\t\t${msg} @ ${pretty}`
+                        for (let k of Object.keys(params || {})) {
+                            report += `\n\t\t\t${k}: ${params[k]}`
+                        }
+                        report += `\n`
                         milestones[msg] = time;
                     }
                 }
 
                 report += `\n`
-                for (let [msg, start, duration] of stats.durations) {
+                report += `\tMeasurements:\n`
+                for (let [msg, start, duration, params] of stats.durations) {
                     let filterIncl = filter && msg.indexOf(filter) >= 0
                     if ((duration > 50 && !filter) || filterIncl) {
                         let pretty = prettyStr(duration)
                         report += `\t\t${msg} took ~ ${pretty}`
                         if (duration > 1000) {
                             report += ` (${prettyStr(start)} - ${prettyStr(start + duration)})`
+                            for (let k of Object.keys(params || {})) {
+                                report += `\n\t\t\t${k}: ${params[k]}`
+                            }
                         }
                         report += `\n`
                     }
                     durations[msg] = duration;
                 }
                 console.log(report)
+                enabled = false; // stop collecting milestones and measurements after report
                 return { milestones, durations };
             }
             return undefined;
@@ -210,7 +253,7 @@ namespace pxt {
 
         // App Insights automatically sends a page view event on setup, but we send our own later with additional properties.
         // This stops the automatic event from firing, so we don't end up with duplicate page view events.
-        if(envelope.baseType == "PageviewData" && !envelope.baseData.properties) {
+        if (envelope.baseType == "PageviewData" && !envelope.baseData.properties) {
             return false;
         }
 

gulpfile.js

@@ -782,6 +782,8 @@ exports.pxtrunner = gulp.series(
     pxtembed,
 );
 
+exports.pxtweb = pxtweb;
+exports.pxtlib = pxtlib;
 exports.skillmapTest = testSkillmap;
 exports.updatestrings = updatestrings;
 exports.lint = lint

localtypings/pxteditor.d.ts

@@ -1145,7 +1145,10 @@ declare namespace pxt.editor {
         blocklyPatch?: (pkgTargetVersion: string, dom: Element) => void;
         webUsbPairDialogAsync?: (pairAsync: () => Promise<boolean>, confirmAsync: (options: any) => Promise<number>) => Promise<number>;
         mkPacketIOWrapper?: (io: pxt.packetio.PacketIO) => pxt.packetio.PacketIOWrapper;
-
+        onPostHostMessage?: (msg: pxt.editor.EditorMessageRequest) => void;
+        onPerfMilestone?: (payload: { milestone: string, time: number, params?: Map<string> }) => void;
+        onPerfMeasurement?: (payload: { name: string, start: number, duration: number, params?: Map<string> }) => void;
+
         // Used with the @tutorialCompleted macro. See docs/writing-docs/tutorials.md for more info
         onTutorialCompleted?: () => void;
         onMarkdownActivityLoad?: (path: string, title?: string, editorProjectName?: string) => Promise<void>;

pxteditor/editorcontroller.ts

@@ -335,8 +335,17 @@ export function bindEditorMessages(getEditorAsync: () => Promise<IProjectView>)
 /**
  * Sends analytics messages upstream to container if any
  */
+let controllerAnalyticsEnabled = false;
 export function enableControllerAnalytics() {
-    if (!pxt.appTarget.appTheme.allowParentController || !pxt.BrowserUtils.isIFrame()) return;
+    if (controllerAnalyticsEnabled) return;
+
+    const hasOnPostHostMessage = !!pxt.commands.onPostHostMessage;
+    const hasAllowParentController = pxt.appTarget.appTheme.allowParentController;
+    const isInsideIFrame = pxt.BrowserUtils.isIFrame();
+
+    if (!(hasOnPostHostMessage || (hasAllowParentController && isInsideIFrame))) {
+        return;
+    }
 
     const te = pxt.tickEvent;
     pxt.tickEvent = function (id: string, data?: pxt.Map<string | number>): void {
@@ -379,6 +388,8 @@ export function enableControllerAnalytics() {
             data
         })
     }
+
+    controllerAnalyticsEnabled = true;
 }
 
 function sendResponse(request: pxt.editor.EditorMessage, resp: any, success: boolean, error: any) {
@@ -424,6 +435,16 @@ export function postHostMessageAsync(msg: pxt.editor.EditorMessageRequest): Prom
             window.parent.postMessage(env, "*");
         }
 
+        // Post to editor extension if it wants to be notified of these messages.
+        // Note this is a one-way notification. Responses are not supported.
+        if (pxt.commands.onPostHostMessage) {
+            try {
+                pxt.commands.onPostHostMessage(msg);
+            } catch (err) {
+                pxt.reportException(err);
+            }
+        }
+
         if (!msg.response)
             resolve(undefined)
     })

pxtlib/analytics.ts

@@ -53,8 +53,8 @@ namespace pxt.analytics {
 
             if (!data) pxt.aiTrackEvent(id);
             else {
-                const props: Map<string> = { ...defaultProps } || {};
-                const measures: Map<number> = { ...defaultMeasures } || {};
+                const props: Map<string> = { ...defaultProps };
+                const measures: Map<number> = { ...defaultMeasures };
                 Object.keys(data).forEach(k => {
                     if (typeof data[k] == "string") props[k] = <string>data[k];
                     else if (typeof data[k] == "number") measures[k] = <number>data[k];

pxtlib/browserutils.ts

@@ -1182,14 +1182,14 @@ namespace pxt.BrowserUtils {
         }
 
         setAsync(filename: string, snippets: Map<Map<number>>, code: string[], highlights: Map<Map<number>>, codeValidationMap: Map<Map<string[]>>, branch?: string): Promise<void> {
-            pxt.perf.measureStart("tutorial info db setAsync")
+            pxt.perf.measureStart(Measurements.TutorialInfoDbSetAsync)
             const key = getTutorialInfoKey(filename, branch);
             const hash = getTutorialCodeHash(code);
             return this.setWithHashAsync(filename, snippets, hash, highlights, codeValidationMap);
         }
 
         setWithHashAsync(filename: string, snippets: Map<Map<number>>, hash: string, highlights: Map<Map<number>>, codeValidationMap: Map<Map<string[]>>, branch?: string): Promise<void> {
-            pxt.perf.measureStart("tutorial info db setAsync")
+            pxt.perf.measureStart(Measurements.TutorialInfoDbSetAsync)
             const key = getTutorialInfoKey(filename, branch);
             const blocks: Map<number> = {};
             Object.keys(snippets).forEach(hash => {
@@ -1210,7 +1210,7 @@ namespace pxt.BrowserUtils {
 
             return this.db.setAsync(TutorialInfoIndexedDb.TABLE, entry)
                 .then(() => {
-                    pxt.perf.measureEnd("tutorial info db setAsync")
+                    pxt.perf.measureEnd(Measurements.TutorialInfoDbSetAsync)
                 })
         }
 

pxtlib/cmds.ts

@@ -38,6 +38,9 @@ namespace pxt.commands {
     export let electronDeployAsync: (r: ts.pxtc.CompileResult) => Promise<void> = undefined; // A pointer to the Electron deploy function, so that targets can access it in their extension.ts
     export let webUsbPairDialogAsync: (pairAsync: () => Promise<boolean>, confirmAsync: (options: any) => Promise<WebUSBPairResult>, implicitlyCalled?: boolean) => Promise<WebUSBPairResult> = undefined;
     export let onTutorialCompleted: () => void = undefined;
+    export let onPostHostMessage: (msg: any /*pxt.editor.EditorMessageRequest*/) => void;
+    export let onPerfMilestone: (payload: { milestone: string, time: number, params?: Map<string> }) => void = undefined;
+    export let onPerfMeasurement: (payload: { name: string, start: number, duration: number, params?: Map<string> }) => void = undefined;
     export let workspaceLoadedAsync: () => Promise<void> = undefined;
     export let onMarkdownActivityLoad: (path: string, title?: string, editorProjectName?: string) => Promise<void> = undefined;
 }

pxtlib/constants.ts

@@ -0,0 +1,7 @@
+namespace Measurements {
+    export const TutorialInfoDbSetAsync = "tutorial info db setAsync";
+    export const ReloadAppTargetVariant = "reloadAppTargetVariant";
+    export const Sha256Buffer = "sha256buffer";
+    export const WebworkerRecvHandler = "webworker recvHandler";
+    export const NetworkRequest = "network.request";
+}

pxtlib/main.ts

@@ -7,16 +7,26 @@
 /// <reference path="tickEvent.ts"/>
 
 namespace pxt.perf {
+    export type EventSource<T> = {
+        subscribe(listener: (payload: T) => void): () => void;
+        //emit(payload: T): void; // not used externally
+    };
+
     // These functions are defined in docfiles/pxtweb/cookieCompliance.ts
+    export declare function isEnabled(): boolean;
     export declare let perfReportLogged: boolean;
     export declare function report(): { milestones: {[index: string]: number}, durations: {[index: string]: number} } | undefined;
-    export declare function recordMilestone(msg: string, time?: number): void;
+    export declare function recordMilestone(msg: string, params?: Map<string>): void;
     export declare function measureStart(name: string): void;
-    export declare function measureEnd(name: string): void;
+    export declare function measureEnd(name: string, params?: Map<string>): void;
+    export declare const onMilestone: EventSource<{ milestone: string, time: number, params?: Map<string> }>;
+    export declare const onMeasurement: EventSource<{ name: string, start: number, duration: number, params?: Map<string> }>;
 }
 (function () {
     // Sometimes these aren't initialized, for example in tests. We only care about them
     // doing anything in the browser.
+    if (!pxt.perf.isEnabled)
+        pxt.perf.isEnabled = () => false
     if (!pxt.perf.report)
         pxt.perf.report = () => undefined
     if (!pxt.perf.recordMilestone)
@@ -258,7 +268,7 @@ namespace pxt {
     }
 
     export function reloadAppTargetVariant(temporary = false) {
-        pxt.perf.measureStart("reloadAppTargetVariant")
+        pxt.perf.measureStart(Measurements.ReloadAppTargetVariant)
         const curr = temporary ? "" : JSON.stringify(appTarget);
         appTarget = U.cloneTargetBundle(savedAppTarget)
         if (appTargetVariant) {
@@ -272,7 +282,7 @@ namespace pxt {
         // check if apptarget changed
         if (!temporary && onAppTargetChanged && curr != JSON.stringify(appTarget))
             onAppTargetChanged();
-        pxt.perf.measureEnd("reloadAppTargetVariant")
+        pxt.perf.measureEnd(Measurements.ReloadAppTargetVariant)
     }
 
     // this is set by compileServiceVariant in pxt.json

pxtlib/util.ts

@@ -871,6 +871,11 @@ namespace ts.pxtc.Util {
     export function requestAsync(options: HttpRequestOptions): Promise<HttpResponse> {
         //if (debugHttpRequests)
         //    pxt.debug(`>> ${options.method || "GET"} ${options.url.replace(/[?#].*/, "...")}`); // don't leak secrets in logs
+        const measureParams: pxt.Map<string> = {
+            "url": `${encodeURI(options.url.replace(/[?#].*/, "..."))}`, // don't leak secrets in logs
+            "method": `${options.method || "GET"}`
+        };
+        pxt.perf.measureStart(Measurements.NetworkRequest)
         return httpRequestCoreAsync(options)
             .then(resp => {
                 //if (debugHttpRequests)
@@ -888,6 +893,24 @@ namespace ts.pxtc.Util {
                     resp.json = U.jsonTryParse(resp.text)
                 return resp
             })
+            .then(resp => {
+                const contentLength = resp.headers["content-length"];
+                if (contentLength) {
+                    measureParams["sizeInBytes"] = `${contentLength}`;
+                } else if (resp.text) {
+                    if (pxt.perf.isEnabled()) {
+                        // only do this work if perf measurement is actually enabled
+                        const encoder = new TextEncoder();
+                        const encoded = encoder.encode(resp.text);
+                        measureParams["sizeInBytes"] = encoded.length + "";
+                    }
+                }
+                measureParams["statusCode"] = `${resp.statusCode}`;
+                return resp
+            })
+            .finally(() => {
+                pxt.perf.measureEnd(Measurements.NetworkRequest, measureParams)
+            })
     }
 
     export function httpGetTextAsync(url: string) {
@@ -2003,9 +2026,9 @@ namespace ts.pxtc.BrowserImpl {
     }
 
     export function sha256string(s: string) {
-        pxt.perf.measureStart("sha256buffer")
+        pxt.perf.measureStart(Measurements.Sha256Buffer)
         const res = sha256buffer(Util.toUTF8Array(s));
-        pxt.perf.measureEnd("sha256buffer")
+        pxt.perf.measureEnd(Measurements.Sha256Buffer)
         return res;
     }
 }