Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Remove debug logging in production environment #3949

Closed
wants to merge 4 commits into from
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
4 changes: 4 additions & 0 deletions docs/upgrade-guide.md
Original file line number Diff line number Diff line change
Expand Up @@ -52,6 +52,10 @@ Users of `SimpleMeshLayer` with texture will need to flip their texture image ve

The change has allowed us to support loading textures from `ImageBitmap`, in use cases such as rendering to `OffscreenCanvas` on a web worker.

##### Production Mode

deck.gl now removes low-level logging when `NODE_ENV` is `production`. This helps reduce bundle size and improve runtime performance.

##### projection system

- The [common space](/docs/shader-module/project.md) is no longer scaled to the current zoom level. This is part of an effort to make the geometry calculation more consistent and predictable. While one old common unit is equivalent to 1 screen pixel at the viewport center, one new common unit is equivalent to `viewport.scale` pixels at the viewport center.
Expand Down
3 changes: 2 additions & 1 deletion modules/core/package.json
Original file line number Diff line number Diff line change
Expand Up @@ -26,8 +26,9 @@
],
"sideEffects": false,
"scripts": {
"build-prod": "npx babel src/lib --config-file ../../babel.config.js --out-dir dist/${BABEL_ENV}/lib.prod --plugins ../../scripts/babel-plugin-remove-log",
"build-bundle": "webpack --config ../../scripts/bundle.config.js",
"prepublishOnly": "npm run build-bundle && npm run build-bundle -- --env.dev"
"prepublishOnly": "BABEL_ENV=es5 npm run build-prod && BABEL_ENV=es6 npm run build-prod && BABEL_ENV=esm npm run build-prod && npm run build-bundle && npm run build-bundle -- --env.dev"
},
"dependencies": {
"@loaders.gl/core": "^1.3.4",
Expand Down
22 changes: 10 additions & 12 deletions modules/core/src/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -41,13 +41,16 @@ export {default as PostProcessEffect} from './effects/post-process-effect';
export {default as _LayersPass} from './passes/layers-pass';

// Experimental Pure JS (non-React) bindings
export {default as Deck} from './lib/deck';

export {default as LayerManager} from './lib/layer-manager';
export {default as AttributeManager} from './lib/attribute/attribute-manager';
export {default as Layer} from './lib/layer';
export {default as CompositeLayer} from './lib/composite-layer';
export {default as DeckRenderer} from './lib/deck-renderer';
export {
Deck,
DeckRenderer,
Effect,
LayerManager,
AttributeManager,
Layer,
CompositeLayer,
LayerExtension
} from './lib-exports';

// Viewports
export {default as Viewport} from './viewports/viewport';
Expand Down Expand Up @@ -79,9 +82,6 @@ export {default as OrthographicController} from './controllers/orthographic-cont

// EXPERIMENTAL EXPORTS

// Experimental Effects (non-React) bindings
export {default as Effect} from './lib/effect';

// Eperimental Transitions
export {TRANSITION_EVENTS} from './controllers/transition-manager';
export {default as LinearInterpolator} from './transitions/linear-interpolator';
Expand All @@ -98,8 +98,6 @@ import {count} from './utils/count';
import memoize from './utils/memoize';
export {mergeShaders} from './utils/shader';

export {LayerExtension} from './lib/layer-extension';

// props
import {compareProps} from './lifecycle/props';

Expand Down
6 changes: 6 additions & 0 deletions modules/core/src/lib-exports.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,6 @@
// eslint-disable-next-line
if (process.env.NODE_ENV === 'production') {
module.exports = require('./lib.prod');
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The conventional wisdowm is that require kills tree shaking as that works on static analysis of export/import...

Recommend validating that this actually leads to smaller apps. My fear is that this will trigger unconditional bundling of lib.prod.

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

core/lib is almost entirely dependencies of the Deck class (with the exception of LayerExtension which is super light).

This change shaves about 1K off the minified bundle. However, the main concern of including the logging functions is performance, because even when log.log returns noOp we spend CPU cycles building the dynamic message strings.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

core/lib is almost entirely dependencies of the Deck class (with the exception of LayerExtension which is super light).

You are saying these should always be bundled anyway? Fine, though

  1. I recommend calling this out in comments above the require statements (E.g. // 'require' defeats tree shaking but we always bundle these symbols anyway)..
  1. When I do this type of setups, they tends to come back and bite me as the library evolves...

However, the main concern of including the logging functions is performance, because even when log.log returns noOp we spend CPU cycles building the dynamic message strings.

Got it. FWIW, to handle this, probe.gl has always allowed for message strings to be supplied as functions that only gets evaluated when the logging actually is enabled, e.g instead of:

log.info(`Dynamic strings generated for ${variableName} every time we execute this`)();
log.info(() => `Don't want dynamic strings generated for ${variableName} when we are not actually logging`)();

In theory, this still mints a function (which should be way faster than building a string, but possibly not zero impact, depends on how the JS engine handles this).

Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I ran some benchmark tests, it's actually 2-3x more expensive to create those functions inline.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for checking and it only goes to prove that actual profiling beats assumptions every time. (Perhaps it is the captured variable that makes it expensive... but that doesn't matter).

In light of this, I'd consider modifying the various probe.gl log calls to take multiple string segment as parameters and then concat them inside the log functions (only when logging actually happens). That should create no small objects and simple parameter passing is typically extremely fast in modern JS engines.

I opened an issue in probe.gl: uber-web/probe.gl#108.

@Pessimistress Happy to help out with this one if this would be considered helpful to the ongoing optimization push.

} else {
module.exports = require('./lib');
}
2 changes: 2 additions & 0 deletions modules/core/src/lib.prod/index.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,2 @@
// This file is overwritten before publish
export * from '../lib';
15 changes: 6 additions & 9 deletions modules/core/src/lib/deck-renderer.js
Original file line number Diff line number Diff line change
Expand Up @@ -134,15 +134,12 @@ export default class DeckRenderer {
const primitiveCount = totalCount - compositeCount;
const hiddenCount = primitiveCount - visibleCount;

let message = '';
message += `RENDER #${this.renderCount} \
${visibleCount} (of ${totalCount} layers) to ${pass} because ${redrawReason} `;
if (log.priority > LOG_PRIORITY_DRAW) {
message += `\
(${hiddenCount} hidden, ${compositeCount} composite ${pickableCount} pickable)`;
}

log.log(LOG_PRIORITY_DRAW, message)();
log.log(
LOG_PRIORITY_DRAW,
`RENDER #${this.renderCount} \
${visibleCount} (of ${totalCount} layers) to ${pass} because ${redrawReason} \
(${hiddenCount} hidden, ${compositeCount} composite ${pickableCount} pickable)`
)();

if (stats) {
stats.get('Redraw Layers').add(visibleCount);
Expand Down
4 changes: 4 additions & 0 deletions modules/core/src/lib/index.js
Original file line number Diff line number Diff line change
Expand Up @@ -22,7 +22,11 @@
export {COORDINATE_SYSTEM} from './constants';

// Export core objects
export {default as Deck} from './deck';
export {default as DeckRenderer} from './deck-renderer';
export {default as Effect} from './effect';
export {default as Layer} from './layer';
export {default as CompositeLayer} from './composite-layer';
export {default as LayerExtension} from './layer-extension';
export {default as AttributeManager} from './attribute/attribute-manager';
export {default as LayerManager} from './layer-manager';
7 changes: 4 additions & 3 deletions modules/core/src/lib/init.js
Original file line number Diff line number Diff line change
Expand Up @@ -31,14 +31,15 @@ import jsonLoader from '../utils/json-loader';
const version =
typeof __VERSION__ !== 'undefined' ? __VERSION__ : global.DECK_VERSION || 'untranspiled source';

const STARTUP_MESSAGE = 'set deck.log.priority=1 (or higher) to trace attribute updates';

if (global.deck && global.deck.VERSION !== version) {
throw new Error(`deck.gl - multiple versions detected: ${global.deck.VERSION} vs ${version}`);
}

if (!global.deck) {
log.log(0, `deck.gl ${version} - ${STARTUP_MESSAGE}`)();
log.log(
0,
`deck.gl ${version} - set deck.log.priority=1 (or higher) to trace attribute updates`
)();

global.deck = global.deck || {
VERSION: version,
Expand Down
2 changes: 1 addition & 1 deletion modules/core/src/lib/layer-extension.js
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,7 @@
// THE SOFTWARE.
import {deepEqual} from '../utils/deep-equal';

export class LayerExtension {
export default class LayerExtension {
constructor(opts = {}) {
this.opts = opts;
}
Expand Down
19 changes: 8 additions & 11 deletions modules/core/src/lib/layer.js
Original file line number Diff line number Diff line change
Expand Up @@ -680,7 +680,7 @@ export default class Layer extends Component {
// Update primary flags
if (flags.dataChanged && !changeFlags.dataChanged) {
changeFlags.dataChanged = flags.dataChanged;
log.log(LOG_PRIORITY_UPDATE + 1, () => `dataChanged: ${flags.dataChanged} in ${this.id}`)();
log.log(LOG_PRIORITY_UPDATE + 1, `dataChanged: ${flags.dataChanged} in ${this.id}`)();
}
if (flags.updateTriggersChanged && !changeFlags.updateTriggersChanged) {
changeFlags.updateTriggersChanged =
Expand All @@ -689,32 +689,29 @@ export default class Layer extends Component {
: flags.updateTriggersChanged || changeFlags.updateTriggersChanged;
log.log(
LOG_PRIORITY_UPDATE + 1,
() =>
'updateTriggersChanged: ' +
`${Object.keys(flags.updateTriggersChanged).join(', ')} in ${this.id}`
`updateTriggersChanged: ${Object.keys(flags.updateTriggersChanged).join(', ')} in ${
this.id
}`
)();
}
if (flags.propsChanged && !changeFlags.propsChanged) {
changeFlags.propsChanged = flags.propsChanged;
log.log(LOG_PRIORITY_UPDATE + 1, () => `propsChanged: ${flags.propsChanged} in ${this.id}`)();
log.log(LOG_PRIORITY_UPDATE + 1, `propsChanged: ${flags.propsChanged} in ${this.id}`)();
}
if (flags.extensionsChanged && !changeFlags.extensionsChanged) {
changeFlags.extensionsChanged = flags.extensionsChanged;
log.log(
LOG_PRIORITY_UPDATE + 1,
() => `extensionsChanged: ${flags.extensionsChanged} in ${this.id}`
`extensionsChanged: ${flags.extensionsChanged} in ${this.id}`
)();
}
if (flags.viewportChanged && !changeFlags.viewportChanged) {
changeFlags.viewportChanged = flags.viewportChanged;
log.log(
LOG_PRIORITY_UPDATE + 2,
() => `viewportChanged: ${flags.viewportChanged} in ${this.id}`
)();
log.log(LOG_PRIORITY_UPDATE + 2, `viewportChanged: ${flags.viewportChanged} in ${this.id}`)();
}
if (flags.stateChanged && !changeFlags.stateChanged) {
changeFlags.stateChanged = flags.stateChanged;
log.log(LOG_PRIORITY_UPDATE + 1, () => `stateChanged: ${flags.stateChanged} in ${this.id}`)();
log.log(LOG_PRIORITY_UPDATE + 1, `stateChanged: ${flags.stateChanged} in ${this.id}`)();
}

// Update composite flags
Expand Down
21 changes: 21 additions & 0 deletions scripts/babel-plugin-remove-log.js
Original file line number Diff line number Diff line change
@@ -0,0 +1,21 @@
const logMethods = ['log', 'deprecated', 'info', 'group', 'groupCollapsed', 'groupEnd', 'table'];
Copy link
Collaborator Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@tsherif Eventually this should be moved to luma repo's dev-modules

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why not move it to probe.gl? After all it is complementary to the probe.gl log class...


module.exports = function _(opts) {
return {
visitor: {
MemberExpression(path, state) {
const object = path.get('object');

if (object.isIdentifier({name: 'log'})) {
const property = path.get('property');
const methodName = logMethods.find(name => property.isIdentifier({name}));
if (methodName) {
// Uncomment to debug
// console.log(`${state.file.opts.filename}: log.${methodName} removed`);
path.parentPath.parentPath.remove();
}
}
}
}
};
};
24 changes: 14 additions & 10 deletions scripts/bundle.config.js
Original file line number Diff line number Diff line change
Expand Up @@ -45,6 +45,17 @@ function getExternals(packageInfo) {
return externals;
}

const babelOptions = {
presets: [['@babel/preset-env', {forceAllTransforms: true}]],
// all of the helpers will reference the module @babel/runtime to avoid duplication
// across the compiled output.
plugins: [
'@babel/transform-runtime',
'inline-webgl-constants',
['remove-glsl-comments', {patterns: ['**/*.glsl.js']}]
]
};

const config = {
mode: 'production',

Expand All @@ -69,16 +80,7 @@ const config = {
test: /\.js$/,
loader: 'babel-loader',
include: /src/,
options: {
presets: [['@babel/preset-env', {forceAllTransforms: true}]],
// all of the helpers will reference the module @babel/runtime to avoid duplication
// across the compiled output.
plugins: [
'@babel/transform-runtime',
'inline-webgl-constants',
['remove-glsl-comments', {patterns: ['**/*.glsl.js']}]
]
}
options: babelOptions
}
]
},
Expand Down Expand Up @@ -114,6 +116,8 @@ module.exports = (env = {}) => {
config.output.filename = 'dist/dist.dev.js';
// Disable transpilation
config.module.rules = [];
} else {
babelOptions.plugins.push(resolve(__dirname, './babel-plugin-remove-log'));
}

// NOTE uncomment to display config
Expand Down