How do you add verbose logging code to functions without affecting performance?
Asked Answered
R

3

7

Performance is important for a certain class I'm writing.

I thought about calling a function like so:

debug('This is a debug message, only visible when debugging is on');

And the contents would be like

function debug(message) {
    if (DEBUG) console.log(message);
}

So I wonder: is this enough for V8 to flag this as "dead code" if the DEBUG variable never changes?

Edit: I'm more worried about the performance in Node than on the browser, so removing the code while minifying would be insufficient.

Edit2: I made a JSPerf benchmark out of the proposed solutions, and they are very surprising: http://jsperf.com/verbose-debug-loggin-conditionals-functions-and-no-ops/3

Ruckman answered 12/9, 2014 at 9:16 Comment(1)
github.com/duongchienthang/js-loggerAciculum
L
1

There's a couple of solutions available(aside Petah's...):

  1. Use UglifyJS2 conditional compilation:

You can use the --define (-d) switch in order to declare global variables that UglifyJS will assume to be constants (unless defined in scope). For example if you pass --define DEBUG=false then, coupled with dead code removal UglifyJS will discard the following from the output:

if (DEBUG) {
    console.log("debug stuff");
}

UglifyJS will warn about the condition being always false and about dropping unreachable code; for now there is no option to turn off only this specific warning, you can pass warnings=false to turn off all warnings.

Another way of doing that is to declare your globals as constants in a separate file and include it into the build. For example you can have a build/defines.js file with the following:

const DEBUG = false;
const PRODUCTION = true;
// etc.
and build your code like this:

uglifyjs build/defines.js js/foo.js js/bar.js... -c UglifyJS will notice the constants and, since they cannot be altered, it will evaluate references to them to the value itself and drop unreachable code as usual. The possible downside of this approach is that the build will contain the const declarations.

  1. Use a wrapper function.

For example you have this method:

exports.complicatedMethod = function (arg1, arg2, arg3) {
    stuff...
};

You add logging to it by wrapping it in a logger function:

function logger(fn) {
    if (!DEBUG) {
        return fn;
    }
    return function () {
        console.log(fn.name, arguments); // You can also use `fn.toString()` to get the argument names.
        fn.apply(this, arguments);
    };
}

exports.complicatedMethod = logger(function (arg1, arg2, arg3) {
    stuff...
});

This way the only performance hit would be at startup time. You can also use AOP method with the above wrapper function:

exports.complicatedMethod = function (arg1, arg2, arg3) {
    stuff...
};

if (DEBUG) {
    for (var name in exports) {
       exports[name] = logger(exports[name]);
    }
}

And you can pass information to the logger by adding properties to the function:

exports.complicatedMethod.description = 'This function only shows how tired i was when I was writing it and nothing else!';

You can have a look at this question where someone created code that creates a logger for functions in an object recursively. Also check this answer of mine.

  1. Use C Pre Processor.

You can just do something like this:

#if DEBUG
  console.log("trace message");
#endif

or something like this

#if DEBUG
#define DEBUG_LOG(x) console.log(x);
#else
#define DEBUG_LOG(x) //console.log(x);
#endif

Then you can do this in your code

DEBUG_LOG('put a random message her to confuse sys admins!')

Or you use it's npm warapper: laudanumscript

  1. Create a sweetjs macro.

I haven't been able to find conditional compilation with sweetjs, but I'm sure it wouldn't be too hard to implement it. The end syntax would be(or should be!) similar to cpp.

Lozenge answered 12/9, 2014 at 9:55 Comment(4)
I forgot to say it was mostly for Node.js (I'm less worried about milliseconds on the browser), so fixing it by minifying is not ideal. I did make a JSPerf benchmark to try your proposed solutions, and they are surprising! The no-ops seem to do quite bad, except on Firefox.Ruckman
Actually looking at your benchmark I have a feeling that since, there's no actual code there, JIT optimizations might remove the whole thing as a dead code... You might want to test something that has side effects so it won't be removed as dead code.Lozenge
Yes, but that's the purpose of the no-op debug messages. SpiderMonkey seems to handle them as you would expect: they're the fastest.Ruckman
No, I mean since the there's no side effects, the JIT will not even try to execute NOOP functions... If there would be no JIT optimizations then "Simple conditional" and "Conditional and function" would be faster than other cases, why? Because the cost of an if clause is much lesser than the cost of evaluating a function. But why in the jsperf benchmark that doesn't happen? Because the JIT will just eliminate the dead code from the functions and realizes it's just a NOOP and won't even call them! So putting some side effects will stop the compiler from doing that.Lozenge
B
2

I use comments that when a file is minified get removed, such as:

function name(arg) {
    // <debug>
    if (!arg) {
        throw new Error("arg must be defined"); 
    }
    // </debug>
    ... code goes here
}

For example: https://github.com/PANmedia/raptor-editor/blob/master/src/raptor-widget.js#L29-L33

An my (custom) build script to do the aforementioned https://github.com/PANmedia/raptor-build/blob/master/build/raptor-builder.js#L305-L313

Boothe answered 12/9, 2014 at 9:19 Comment(1)
Similarly, github.com/douglascrockford/ecomcon.Herschelherself
L
1

There's a couple of solutions available(aside Petah's...):

  1. Use UglifyJS2 conditional compilation:

You can use the --define (-d) switch in order to declare global variables that UglifyJS will assume to be constants (unless defined in scope). For example if you pass --define DEBUG=false then, coupled with dead code removal UglifyJS will discard the following from the output:

if (DEBUG) {
    console.log("debug stuff");
}

UglifyJS will warn about the condition being always false and about dropping unreachable code; for now there is no option to turn off only this specific warning, you can pass warnings=false to turn off all warnings.

Another way of doing that is to declare your globals as constants in a separate file and include it into the build. For example you can have a build/defines.js file with the following:

const DEBUG = false;
const PRODUCTION = true;
// etc.
and build your code like this:

uglifyjs build/defines.js js/foo.js js/bar.js... -c UglifyJS will notice the constants and, since they cannot be altered, it will evaluate references to them to the value itself and drop unreachable code as usual. The possible downside of this approach is that the build will contain the const declarations.

  1. Use a wrapper function.

For example you have this method:

exports.complicatedMethod = function (arg1, arg2, arg3) {
    stuff...
};

You add logging to it by wrapping it in a logger function:

function logger(fn) {
    if (!DEBUG) {
        return fn;
    }
    return function () {
        console.log(fn.name, arguments); // You can also use `fn.toString()` to get the argument names.
        fn.apply(this, arguments);
    };
}

exports.complicatedMethod = logger(function (arg1, arg2, arg3) {
    stuff...
});

This way the only performance hit would be at startup time. You can also use AOP method with the above wrapper function:

exports.complicatedMethod = function (arg1, arg2, arg3) {
    stuff...
};

if (DEBUG) {
    for (var name in exports) {
       exports[name] = logger(exports[name]);
    }
}

And you can pass information to the logger by adding properties to the function:

exports.complicatedMethod.description = 'This function only shows how tired i was when I was writing it and nothing else!';

You can have a look at this question where someone created code that creates a logger for functions in an object recursively. Also check this answer of mine.

  1. Use C Pre Processor.

You can just do something like this:

#if DEBUG
  console.log("trace message");
#endif

or something like this

#if DEBUG
#define DEBUG_LOG(x) console.log(x);
#else
#define DEBUG_LOG(x) //console.log(x);
#endif

Then you can do this in your code

DEBUG_LOG('put a random message her to confuse sys admins!')

Or you use it's npm warapper: laudanumscript

  1. Create a sweetjs macro.

I haven't been able to find conditional compilation with sweetjs, but I'm sure it wouldn't be too hard to implement it. The end syntax would be(or should be!) similar to cpp.

Lozenge answered 12/9, 2014 at 9:55 Comment(4)
I forgot to say it was mostly for Node.js (I'm less worried about milliseconds on the browser), so fixing it by minifying is not ideal. I did make a JSPerf benchmark to try your proposed solutions, and they are surprising! The no-ops seem to do quite bad, except on Firefox.Ruckman
Actually looking at your benchmark I have a feeling that since, there's no actual code there, JIT optimizations might remove the whole thing as a dead code... You might want to test something that has side effects so it won't be removed as dead code.Lozenge
Yes, but that's the purpose of the no-op debug messages. SpiderMonkey seems to handle them as you would expect: they're the fastest.Ruckman
No, I mean since the there's no side effects, the JIT will not even try to execute NOOP functions... If there would be no JIT optimizations then "Simple conditional" and "Conditional and function" would be faster than other cases, why? Because the cost of an if clause is much lesser than the cost of evaluating a function. But why in the jsperf benchmark that doesn't happen? Because the JIT will just eliminate the dead code from the functions and realizes it's just a NOOP and won't even call them! So putting some side effects will stop the compiler from doing that.Lozenge
A
1

You can use a logger library that supports:

  1. Logging level
  2. Late binding functions

Example: https://github.com/duongchienthang/js-logger

Aciculum answered 29/1, 2015 at 15:32 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.