benchmark more loading stats

- Display time to load just the (json) data
- Display progress and time for content
- Display progress and time hydrating the downloaded assets

src/playground/benchmark.js

@@ -7,6 +7,42 @@ if (window.performance) {
     performance.mark('Scratch.EvalStart');
 }
 
+class LoadingMiddleware {
+    constructor () {
+        this.middleware = [];
+        this.host = null;
+        this.original = null;
+    }
+
+    install (host, original) {
+        this.host = host;
+        this.original = original;
+        const {middleware} = this;
+        return function (...args) {
+            let i = 0;
+            const next = function (_args) {
+                if (i >= middleware.length) {
+                    return original.call(host, ..._args);
+                }
+                return middleware[i++](_args, next);
+            };
+            return next(args);
+        };
+    }
+
+    push (middleware) {
+        this.middleware.push(middleware);
+    }
+}
+
+const importLoadCostume = require('../import/load-costume');
+const costumeMiddleware = new LoadingMiddleware();
+importLoadCostume.loadCostume = costumeMiddleware.install(importLoadCostume, importLoadCostume.loadCostume);
+
+const importLoadSound = require('../import/load-sound');
+const soundMiddleware = new LoadingMiddleware();
+importLoadSound.loadSound = soundMiddleware.install(importLoadSound, importLoadSound.loadSound);
+
 const ScratchStorage = require('scratch-storage');
 const VirtualMachine = require('..');
 const Runtime = require('../engine/runtime');
@@ -77,32 +113,92 @@ const getAssetUrl = function (asset) {
 
 class LoadingProgress {
     constructor (callback) {
-        this.total = 0;
+        this.dataLoaded = 0;
-        this.complete = 0;
+        this.contentTotal = 0;
+        this.contentComplete = 0;
+        this.hydrateTotal = 0;
+        this.hydrateComplete = 0;
+        this.memoryCurrent = 0;
+        this.memoryPeak = 0;
         this.callback = callback;
     }
 
+    sampleMemory () {
+        if (window.performance && window.performance.memory) {
+            this.memoryCurrent = window.performance.memory.usedJSHeapSize;
+            this.memoryPeak = Math.max(this.memoryCurrent, this.memoryPeak);
+        }
+    }
+
+    attachHydrateMiddleware (middleware) {
+        const _this = this;
+        middleware.push((args, next) => {
+            _this.hydrateTotal += 1;
+            _this.sampleMemory();
+            _this.callback(_this);
+            return Promise.resolve(next(args))
+                .then(value => {
+                    _this.hydrateComplete += 1;
+                    _this.sampleMemory();
+                    _this.callback(_this);
+                    return value;
+                });
+        });
+    }
+
     on (storage, vm) {
         const _this = this;
+
+        this.attachHydrateMiddleware(costumeMiddleware);
+        this.attachHydrateMiddleware(soundMiddleware);
+
         const _load = storage.webHelper.load;
         storage.webHelper.load = function (...args) {
-            if (_this.complete === 0 && window.performance) {
+            if (_this.dataLoaded === 0 && window.performance) {
                 // Mark in browser inspectors how long it takes to load the
                 // projects initial data file.
                 performance.mark('Scratch.LoadDataStart');
             }
 
             const result = _load.call(this, ...args);
-            _this.total += 1;
+
-            _this.callback(_this);
+            if (_this.dataLoaded) {
-            result.then(() => {
+                if (_this.contentTotal === 0 && window.performance) {
-                if (_this.complete === 0 && window.performance) {
+                    performance.mark('Scratch.DownloadStart');
-                    // How long did loading the data file take?
-                    performance.mark('Scratch.LoadDataEnd');
-                    performance.measure('Scratch.LoadData', 'Scratch.LoadDataStart', 'Scratch.LoadDataEnd');
                 }
 
-                _this.complete += 1;
+                _this.contentTotal += 1;
+            }
+            _this.sampleMemory();
+            _this.callback(_this);
+
+            result.then(() => {
+                if (_this.dataLoaded === 0) {
+                    if (window.performance) {
+                        // How long did loading the data file take?
+                        performance.mark('Scratch.LoadDataEnd');
+                        performance.measure('Scratch.LoadData', 'Scratch.LoadDataStart', 'Scratch.LoadDataEnd');
+                    }
+
+                    _this.dataLoaded = 1;
+
+                    window.ScratchVMLoadDataEnd = Date.now();
+                } else {
+                    _this.contentComplete += 1;
+                }
+
+                if (_this.contentComplete && _this.contentComplete === _this.contentTotal) {
+                    if (window.performance) {
+                        // How long did it take to download the html, js, and
+                        // all the project assets?
+                        performance.mark('Scratch.DownloadEnd');
+                        performance.measure('Scratch.Download', 'Scratch.DownloadStart', 'Scratch.DownloadEnd');
+                    }
+
+                    window.ScratchVMDownloadEnd = Date.now();
+                }
+
+                _this.sampleMemory();
                 _this.callback(_this);
             });
             return result;
@@ -112,8 +208,8 @@ class LoadingProgress {
             // and not when the data has been decoded. It may be difficult to
             // track that but it isn't hard to track when its all been decoded.
             if (window.performance) {
-                // How long did it take to load the html, js, and all the
+                // How long did it take to load and hydrate the html, js, and
-                // project assets?
+                // all the project assets?
                 performance.mark('Scratch.LoadEnd');
                 performance.measure('Scratch.Load', 'Scratch.LoadStart', 'Scratch.LoadEnd');
             }
@@ -122,6 +218,7 @@ class LoadingProgress {
 
             // With this event lets update LoadingProgress a final time so its
             // displayed loading time is accurate.
+            _this.sampleMemory();
             _this.callback(_this);
         });
     }
@@ -497,12 +594,33 @@ const runBenchmark = function () {
     vm.attachStorage(storage);
 
     new LoadingProgress(progress => {
-        document.getElementsByClassName('loading-total')[0]
+        const setElement = (name, value) => {
-            .innerText = progress.total;
+            document.getElementsByClassName(name)[0].innerText = value;
-        document.getElementsByClassName('loading-complete')[0]
+        };
-            .innerText = progress.complete;
+        const sinceLoadStart = key => (
-        document.getElementsByClassName('loading-time')[0]
+            `(${(window[key] || Date.now()) - window.ScratchVMLoadStart}ms)`
-            .innerText = `(${(window.ScratchVMLoadEnd || Date.now()) - window.ScratchVMLoadStart}ms)`;
+        );
+
+        setElement('loading-total', 1);
+        setElement('loading-complete', progress.dataLoaded);
+        setElement('loading-time', sinceLoadStart('ScratchVMLoadDataEnd'));
+
+        setElement('loading-content-total', progress.contentTotal);
+        setElement('loading-content-complete', progress.contentComplete);
+        setElement('loading-content-time', sinceLoadStart('ScratchVMDownloadEnd'));
+
+        setElement('loading-hydrate-total', progress.hydrateTotal);
+        setElement('loading-hydrate-complete', progress.hydrateComplete);
+        setElement('loading-hydrate-time', sinceLoadStart('ScratchVMLoadEnd'));
+
+        if (progress.memoryPeak) {
+            setElement('loading-memory-current',
+                `${(progress.memoryCurrent / 1000000).toFixed(0)}MB`
+            );
+            setElement('loading-memory-peak',
+                `${(progress.memoryPeak / 1000000).toFixed(0)}MB`
+            );
+        }
     }).on(storage, vm);
 
     let warmUpTime = 4000;

src/playground/index.html

@@ -40,31 +40,45 @@
 
   <canvas id="scratch-stage"></canvas><br />
 
-  <div class="loading">
+  <div class="layer">
-    <label>Loading:</label>
+    <div class="loading">
-    <span class="loading-complete">0</span> / <span class="loading-total">0</span> <span class="loading-time">(--ms)</span>
+      <label>Loading Data:</label>
-  </div>
+      <span class="loading-complete">0</span> / <span class="loading-total">0</span> <span class="loading-time">(--ms)</span>
-  <div class="profile-count-group">
-    <div class="profile-count">
-      <label>Percent of time worked:</label>
-      <span class="profile-count-value profile-count-amount-recorded">...</span>
     </div>
-    <div class="profile-count">
+    <div class="loading">
-      <label>Steps looped:</label>
+      <label>Loading Content:</label>
-      <span class="profile-count-value profile-count-steps-looped">...</span>
+      <span class="loading-content-complete">0</span> / <span class="loading-content-total">0</span> <span class="loading-content-time">(--ms)</span>
     </div>
-    <div class="profile-count">
+    <div class="loading">
-      <label>Blocks executed:</label>
+      <label>Hydrating:</label>
-      <span class="profile-count-value profile-count-blocks-executed">...</span>
+      <span class="loading-hydrate-complete">0</span> / <span class="loading-hydrate-total">0</span> <span class="loading-hydrate-time">(--ms)</span>
+     </div>
+    <div class="loading">
+      <label>Memory:</label>
+      <span class="loading-memory-current">--</span> / <span class="loading-memory-peak">--</span>
+     </div>
+    <div class="profile-count-group">
+      <div class="profile-count">
+        <label>Percent of time worked:</label>
+        <span class="profile-count-value profile-count-amount-recorded">...</span>
+      </div>
+      <div class="profile-count">
+        <label>Steps looped:</label>
+        <span class="profile-count-value profile-count-steps-looped">...</span>
+      </div>
+      <div class="profile-count">
+        <label>Blocks executed:</label>
+        <span class="profile-count-value profile-count-blocks-executed">...</span>
+      </div>
+      <a class="share"><div class="profile-count">
+        <label>Share this report</label>
+      </div></a>
+      <a class="share" target="_parent">
+          <div class="profile-count">
+              <label>Run the full suite</label>
+          </div>
+      </a>
     </div>
-    <a class="share"><div class="profile-count">
-      <label>Share this report</label>
-    </div></a>
-    <a class="share" target="_parent">
-        <div class="profile-count">
-            <label>Run the full suite</label>
-        </div>
-    </a>
   </div>
 
   <div class="profile-tables">