Debug API (visgl#3957)

forestofrain · Dec 5, 2019 · 71e764d · 71e764d
1 parent 9225d45
commit 71e764d
Show file tree

Hide file tree

Showing 17 changed files with 234 additions and 185 deletions.
diff --git a/.gitignore b/.gitignore
@@ -1,6 +1,6 @@
 build/
 dist/
-dist.min.js
+*.min.js
 node_modules/
 coverage/
 test/**/*-failed.png

diff --git a/docs/upgrade-guide.md b/docs/upgrade-guide.md
@@ -39,6 +39,12 @@
   + `LNGLAT_DEPRECATED`: use `LNGLAT`
   + `METERS`: use `METER_OFFSETS`
 
+
+##### Debugging
+
+deck.gl now removes most logging when bundling under `NODE_ENV=production`.
+
+
 ##### Standalone bundle
 
 The pre-bundled version, a.k.a. the [scripting API](/docs/get-started/using-standalone.md#using-the-scripting-api) has been aligned with the interface of the core [Deck](/docs/api-reference/deck.md) class.

diff --git a/modules/core/bundle/debug.js b/modules/core/bundle/debug.js
@@ -0,0 +1,5 @@
+/* global deck */
+import {getLoggers} from '../src/debug/loggers';
+
+const loggers = getLoggers(deck.log);
+deck._registerLoggers(loggers);
diff --git a/modules/core/package.json b/modules/core/package.json
@@ -22,12 +22,14 @@
   "files": [
     "dist",
     "src",
+    "debug.min.js",
     "dist.min.js"
   ],
   "sideEffects": false,
   "scripts": {
+    "build-debugger": "webpack ./bundle/debug.js -p -o ./debug.min.js --config ../../scripts/bundle.config.js",
     "build-bundle": "webpack --config ../../scripts/bundle.config.js",
-    "prepublishOnly": "npm run build-bundle && npm run build-bundle -- --env.dev"
+    "prepublishOnly": "npm run build-debugger && npm run build-bundle && npm run build-bundle -- --env.dev"
   },
   "dependencies": {
     "@loaders.gl/core": "^1.3.4",

diff --git a/modules/core/src/debug/index.js b/modules/core/src/debug/index.js
@@ -0,0 +1,23 @@
+import deckLog from '../utils/log';
+import {getLoggers} from './loggers';
+
+/* debug utility */
+
+let loggers;
+
+// Conditionally load default loggers in development mode
+// eslint-disable-next-line
+if (process.env.NODE_ENV !== 'production') {
+  loggers = getLoggers(deckLog);
+}
+
+export function register(handlers) {
+  loggers = handlers;
+}
+
+export default function debug(eventType) {
+  if (deckLog.priority > 0 && loggers[eventType]) {
+    // Not using ...args to defeat perf hit from array construction
+    loggers[eventType].call(...arguments);
+  }
+}
diff --git a/modules/core/src/debug/loggers.js b/modules/core/src/debug/loggers.js
@@ -0,0 +1,132 @@
+const logState = {
+  attributeUpdateMessages: []
+};
+
+const PRIORITY_MAJOR_UPDATE = 1; // Events with direct perf impact
+const PRIORITY_MINOR_UPDATE = 2; // Events that may affect perf
+const PRIORITY_UPDATE_DETAIL = 3;
+const PRIORITY_INFO = 4;
+const PRIORITY_DRAW = 2;
+
+export const getLoggers = log => ({
+  /* Layer events */
+
+  'layer.changeFlag': (layer, key, flags) => {
+    log.log(PRIORITY_UPDATE_DETAIL, `${layer.id} ${key}: `, flags[key])();
+  },
+
+  'layer.initialize': layer => {
+    log.log(PRIORITY_MAJOR_UPDATE, `Initializing ${layer}`)();
+  },
+  'layer.update': (layer, needsUpdate) => {
+    if (needsUpdate) {
+      const flags = layer.getChangeFlags();
+      log.log(
+        PRIORITY_MINOR_UPDATE,
+        `Updating ${layer} because: ${Object.keys(flags)
+          .filter(key => flags[key])
+          .join(', ')}`
+      )();
+    } else {
+      log.log(PRIORITY_INFO, `${layer} does not need update`)();
+    }
+  },
+  'layer.matched': (layer, changed) => {
+    if (changed) {
+      log.log(PRIORITY_INFO, `Matched ${layer}, state transfered`)();
+    }
+  },
+  'layer.finalize': layer => {
+    log.log(PRIORITY_MAJOR_UPDATE, `Finalizing ${layer}`)();
+  },
+
+  /* CompositeLayer events */
+
+  'compositeLayer.renderLayers': (layer, updated, subLayers) => {
+    if (updated) {
+      log.log(
+        PRIORITY_MINOR_UPDATE,
+        `Composite layer rendered new subLayers ${layer}`,
+        subLayers
+      )();
+    } else {
+      log.log(PRIORITY_INFO, `Composite layer reused subLayers ${layer}`, subLayers)();
+    }
+  },
+
+  /* LayerManager events */
+
+  'layerManager.setLayers': (layerManager, updated, layers) => {
+    if (updated) {
+      log.log(PRIORITY_MINOR_UPDATE, `Updating ${layers.length} deck layers`)();
+    }
+  },
+
+  'layerManager.activateViewport': (layerManager, viewport) => {
+    log.log(PRIORITY_UPDATE_DETAIL, 'Viewport changed', viewport)();
+  },
+
+  /* AttributeManager events */
+
+  'attributeManager.invalidate': (attributeManager, trigger, attributeNames) => {
+    log.log(
+      PRIORITY_MAJOR_UPDATE,
+      attributeNames
+        ? `invalidated attributes ${attributeNames} (${trigger}) for ${attributeManager.id}`
+        : `invalidated all attributes for ${attributeManager.id}`
+    )();
+  },
+
+  'attributeManager.updateStart': attributeManager => {
+    logState.attributeUpdateMessages.length = 0;
+    logState.attributeManagerUpdateStart = Date.now();
+  },
+  'attributeManager.updateEnd': (attributeManager, numInstances) => {
+    const timeMs = Math.round(Date.now() - logState.attributeManagerUpdateStart);
+    log.groupCollapsed(
+      PRIORITY_MINOR_UPDATE,
+      `Updated attributes for ${numInstances} instances in ${attributeManager.id} in ${timeMs}ms`
+    )();
+    for (const updateMessage of logState.attributeUpdateMessages) {
+      log.log(PRIORITY_UPDATE_DETAIL, updateMessage)();
+    }
+    log.groupEnd(PRIORITY_MINOR_UPDATE)();
+  },
+
+  /* Attribute events */
+
+  'attribute.updateStart': attribute => {
+    logState.attributeUpdateStart = Date.now();
+  },
+  'attribute.allocate': (attribute, numInstances) => {
+    const message = `${attribute.id} allocated ${numInstances}`;
+    logState.attributeUpdateMessages.push(message);
+  },
+  'attribute.updateEnd': (attribute, numInstances) => {
+    const timeMs = Math.round(Date.now() - logState.attributeUpdateStart);
+    const message = `${attribute.id} updated ${numInstances} in ${timeMs}ms`;
+    logState.attributeUpdateMessages.push(message);
+  },
+
+  /* Render events */
+
+  'deckRenderer.renderLayers': (deckRenderer, renderStats, opts) => {
+    const {pass, redrawReason, stats} = opts;
+    for (const status of renderStats) {
+      const {totalCount, visibleCount, compositeCount, pickableCount} = status;
+      const primitiveCount = totalCount - compositeCount;
+      const hiddenCount = primitiveCount - visibleCount;
+
+      log.log(
+        PRIORITY_DRAW,
+        `RENDER #${deckRenderer.renderCount} \
+  ${visibleCount} (of ${totalCount} layers) to ${pass} because ${redrawReason} \
+  (${hiddenCount} hidden, ${compositeCount} composite ${pickableCount} pickable)`
+      )();
+
+      if (stats) {
+        stats.get('Redraw Layers').add(visibleCount);
+      }
+    }
+  }
+});
diff --git a/modules/core/src/index.js b/modules/core/src/index.js
@@ -98,7 +98,7 @@ import {count} from './utils/count';
 import memoize from './utils/memoize';
 export {mergeShaders} from './utils/shader';
 
-export {LayerExtension} from './lib/layer-extension';
+export {default as LayerExtension} from './lib/layer-extension';
 
 // props
 import {compareProps} from './lifecycle/props';

diff --git a/modules/core/src/lib/attribute/attribute-manager.js b/modules/core/src/lib/attribute/attribute-manager.js
@@ -21,51 +21,18 @@
 /* eslint-disable guard-for-in */
 import Attribute from './attribute';
 import log from '../../utils/log';
+import debug from '../../debug';
 
 import AttributeTransitionManager from './attribute-transition-manager';
 
-const LOG_START_END_PRIORITY = 2;
-const LOG_DETAIL_PRIORITY = 3;
-
-// Default loggers
-const logFunctions = {
-  savedMessages: [],
-  timeStart: null,
-  onUpdateStart: () => {
-    logFunctions.savedMessages.length = 0;
-    logFunctions.timeStart = Date.now();
-  },
-  onUpdate: message => {
-    logFunctions.savedMessages.push(message);
-  },
-  onUpdateEnd: message => {
-    const timeMs = Math.round(Date.now() - logFunctions.timeStart);
-    log.group(LOG_START_END_PRIORITY, `${message} in ${timeMs}ms`, {
-      collapsed: true
-    })();
-    for (const updateMessage of logFunctions.savedMessages) {
-      log.log(LOG_DETAIL_PRIORITY, updateMessage)();
-    }
-    log.groupEnd(LOG_START_END_PRIORITY)();
-  }
-};
+const TRACE_INVALIDATE = 'attributeManager.invalidate';
+const TRACE_UPDATE_START = 'attributeManager.updateStart';
+const TRACE_UPDATE_END = 'attributeManager.updateEnd';
+const TRACE_ATTRIBUTE_UPDATE_START = 'attribute.updateStart';
+const TRACE_ATTRIBUTE_ALLOCATE = 'attribute.allocate';
+const TRACE_ATTRIBUTE_UPDATE_END = 'attribute.updateEnd';
 
 export default class AttributeManager {
-  /**
-   * Sets log functions to help trace or time attribute updates.
-   * Default logging uses deck logger.
-   *
-   * To enable detailed control of timming and e.g. hierarchical logging,
-   * hooks are also provided for update start and end.
-   *
-   * @param {Object} [opts]
-   * @param {String} [onUpdateStart=] - called before update() starts
-   * @param {String} [onUpdateEnd=] - called after update() ends
-   */
-  static setDefaultLogFunctions(functions) {
-    Object.assign(logFunctions, functions);
-  }
-
   /**
    * @classdesc
    * Automated attribute generation and management. Suitable when a set of
@@ -172,18 +139,15 @@ export default class AttributeManager {
   invalidate(triggerName, dataRange) {
     const invalidatedAttributes = this._invalidateTrigger(triggerName, dataRange);
     // For performance tuning
-    log.log(
-      LOG_DETAIL_PRIORITY,
-      `invalidated attributes ${invalidatedAttributes} (${triggerName}) for ${this.id}`
-    )();
+    debug(TRACE_INVALIDATE, this, triggerName, invalidatedAttributes);
   }
 
   invalidateAll(dataRange) {
     for (const attributeName in this.attributes) {
       this.attributes[attributeName].setNeedsUpdate(attributeName, dataRange);
     }
     // For performance tuning
-    log.log(LOG_DETAIL_PRIORITY, `invalidated all attributes for ${this.id}`)();
+    debug(TRACE_INVALIDATE, this, 'all');
   }
 
   // Ensure all attribute buffers are updated from props or data.
@@ -199,7 +163,7 @@ export default class AttributeManager {
     // keep track of whether some attributes are updated
     let updated = false;
 
-    logFunctions.onUpdateStart();
+    debug(TRACE_UPDATE_START, this);
     if (this.stats) {
       this.stats.get('Update Attributes').timeStart();
     }
@@ -238,7 +202,7 @@ export default class AttributeManager {
 
     if (updated) {
       // Only initiate alloc/update (and logging) if actually needed
-      logFunctions.onUpdateEnd(`Updated attributes for ${numInstances} instances in ${this.id}`);
+      debug(TRACE_UPDATE_END, this, numInstances);
     }
 
     if (this.stats) {
@@ -385,20 +349,17 @@ export default class AttributeManager {
 
   _updateAttribute(opts) {
     const {attribute, numInstances} = opts;
+    debug(TRACE_ATTRIBUTE_UPDATE_START, attribute);
 
     if (attribute.allocate(numInstances)) {
-      logFunctions.onUpdate(`${attribute.id} allocated ${numInstances}`);
+      debug(TRACE_ATTRIBUTE_ALLOCATE, attribute, numInstances);
     }
 
     // Calls update on any buffers that need update
-    const timeStart = Date.now();
-
     const updated = attribute.updateBuffer(opts);
     if (updated) {
       this.needsRedraw = true;
-
-      const timeMs = Math.round(Date.now() - timeStart);
-      logFunctions.onUpdate(`${attribute.id} updated ${numInstances} in ${timeMs}ms`);
+      debug(TRACE_ATTRIBUTE_UPDATE_END, attribute, numInstances);
     }
   }
 }
diff --git a/modules/core/src/lib/composite-layer.js b/modules/core/src/lib/composite-layer.js
@@ -18,9 +18,11 @@
 // OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN
 // THE SOFTWARE.
 import Layer from './layer';
-import log from '../utils/log';
+import debug from '../debug';
 import {flatten} from '../utils/flatten';
 
+const TRACE_RENDER_LAYERS = 'compositeLayer.renderLayers';
+
 export default class CompositeLayer extends Layer {
   get isComposite() {
     return true;
@@ -206,17 +208,16 @@ export default class CompositeLayer extends Layer {
   // Called by layer manager to render subLayers
   _renderLayers() {
     let {subLayers} = this.internalState;
-    if (subLayers && !this.needsUpdate()) {
-      log.log(3, `Composite layer reused subLayers ${this}`, this.internalState.subLayers)();
-    } else {
+    const shouldUpdate = !subLayers || this.needsUpdate();
+    if (shouldUpdate) {
       subLayers = this.renderLayers();
       // Flatten the returned array, removing any null, undefined or false
       // this allows layers to render sublayers conditionally
       // (see CompositeLayer.renderLayers docs)
       subLayers = flatten(subLayers, {filter: Boolean});
       this.internalState.subLayers = subLayers;
-      log.log(2, `Composite layer rendered new subLayers ${this}`, subLayers)();
     }
+    debug(TRACE_RENDER_LAYERS, this, shouldUpdate, subLayers);
 
     // populate reference to parent layer (this layer)
     // NOTE: needs to be done even when reusing layers as the parent may have changed