Expose enable() & disable() for node.js #27

Closed
wants to merge 10 commits into
from

Conversation

Projects
None yet
5 participants
@AlexeyKupershtokh

I have a long running server with repl via socket access - it's very useful for interactive debugging running processes.

But I would also like to be able to log in into repl and enable/disable some logs without restarting the server with new ENV.

@tj

This comment has been minimized.

Show comment Hide comment
@tj

tj Nov 8, 2012

Owner

i was thinking about this yesterday as well, it would be cool to just signal a proc to start debugging, we would have to change the implementation a bit so that we're not returning a noop so the debug() calls will be more expensive

Owner

tj commented Nov 8, 2012

i was thinking about this yesterday as well, it would be cool to just signal a proc to start debugging, we would have to change the implementation a bit so that we're not returning a noop so the debug() calls will be more expensive

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Nov 9, 2012

https://github.com/AlexeyKupershtokh/debug/blob/runtime-enable/lib/debug.js
Almost rewrote the whole module :)

  • Converted names and skips to dictionaries with RE strings as keys and therefore fixed the disable().
  • Made closures lightweight.
  • Made printer (responsible for output, default is console.error) and formatter (responsible for colorizing) pluggable via setFormatter and setPrinter.
  • Enabled "strict mode".
  • Replaced new Date with a faster Date.now() and so on.

I can use it now 😎

https://github.com/AlexeyKupershtokh/debug/blob/runtime-enable/lib/debug.js
Almost rewrote the whole module :)

  • Converted names and skips to dictionaries with RE strings as keys and therefore fixed the disable().
  • Made closures lightweight.
  • Made printer (responsible for output, default is console.error) and formatter (responsible for colorizing) pluggable via setFormatter and setPrinter.
  • Enabled "strict mode".
  • Replaced new Date with a faster Date.now() and so on.

I can use it now 😎

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Nov 9, 2012

For some reason it still doesn't allow me enabling debug in runtime in a real application 👎

I added a setInterval statement in the module to print out module.filename, names and skips every 1 sec. It outputs 2 different sets twice a second:

/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$', '^.*?$' ] skips []
/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$' ] skips []
/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$', '^.*?$' ] skips []
/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$' ] skips []

For some reason it still doesn't allow me enabling debug in runtime in a real application 👎

I added a setInterval statement in the module to print out module.filename, names and skips every 1 sec. It outputs 2 different sets twice a second:

/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$', '^.*?$' ] skips []
/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$' ] skips []
/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$', '^.*?$' ] skips []
/var/local/projects/ha/server/node_modules/debug/lib/debug.js names [ '^$' ] skips []
@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Nov 9, 2012

Ok, that's seem fixed by not doing require('debug') after repl start.

More on this issue here: joyent/node#3226

Ok, that's seem fixed by not doing require('debug') after repl start.

More on this issue here: joyent/node#3226

@tj

This comment has been minimized.

Show comment Hide comment
@tj

tj Nov 14, 2012

Owner

any perf results vs the empty function? curious about that, we use this really heavily all over server/client

Owner

tj commented Nov 14, 2012

any perf results vs the empty function? curious about that, we use this really heavily all over server/client

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Nov 15, 2012

I'll try to benchmark this today.

I'll try to benchmark this today.

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Nov 16, 2012

mkdir node_modules
npm install 'git://github.com/AlexeyKupershtokh/debug.git#runtime-enable' --force
mv node_modules/debug node_modules/debug2
npm install debug --force

index.php:

var d1 = require('debug')('test');
console.log(d1.toString());
var d2 = require('debug2')('test');
console.log(d2.toString());

var t = Date.now();
for (var i = 0; i < 10000000; i++)  {
  d1("test test test");
}
var t = Date.now() - t;
console.log('d1', t);

var t = Date.now();
for (var i = 0; i < 10000000; i++)  {
  d2("test test test");
}
var t = Date.now() - t;
console.log('d2', t);

results of node index.js:

function disabled(){}
function () {
    // invalidate `enabled` if skips/names has been updated
    if (this_enabled_cache_id === undefined || this_enabled_cache_id < enabled_cache_id) {
      this_enabled = undefined;
    }

    // check if has a cached enabled value, set if necessary
    if (this_enabled === undefined) {
      this_enabled_cache_id = enabled_cache_id;
      this_enabled = debug.enabled(name);
    }

    // if disabled, then noop
    if (this_enabled === false) return;

    formatter(name, c, arguments);
  }
d1 133
d2 658

So the disabled() gives 75 000 000 ops/sec and my one gives "only" 15 000 000 ops/sec on a laptop with a core 2 duo @ 2GHz. So they both perform fast enough when debug is disabled.

mkdir node_modules
npm install 'git://github.com/AlexeyKupershtokh/debug.git#runtime-enable' --force
mv node_modules/debug node_modules/debug2
npm install debug --force

index.php:

var d1 = require('debug')('test');
console.log(d1.toString());
var d2 = require('debug2')('test');
console.log(d2.toString());

var t = Date.now();
for (var i = 0; i < 10000000; i++)  {
  d1("test test test");
}
var t = Date.now() - t;
console.log('d1', t);

var t = Date.now();
for (var i = 0; i < 10000000; i++)  {
  d2("test test test");
}
var t = Date.now() - t;
console.log('d2', t);

results of node index.js:

function disabled(){}
function () {
    // invalidate `enabled` if skips/names has been updated
    if (this_enabled_cache_id === undefined || this_enabled_cache_id < enabled_cache_id) {
      this_enabled = undefined;
    }

    // check if has a cached enabled value, set if necessary
    if (this_enabled === undefined) {
      this_enabled_cache_id = enabled_cache_id;
      this_enabled = debug.enabled(name);
    }

    // if disabled, then noop
    if (this_enabled === false) return;

    formatter(name, c, arguments);
  }
d1 133
d2 658

So the disabled() gives 75 000 000 ops/sec and my one gives "only" 15 000 000 ops/sec on a laptop with a core 2 duo @ 2GHz. So they both perform fast enough when debug is disabled.

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Nov 17, 2012

When debug is enabled but console.error = noop:

console.error = function() {};

var d1 = require('debug')('test');
console.log(d1.toString());
var d2 = require('debug2')('test');
console.log(d2.toString());

var t = Date.now();
for (var i = 0; i < 1000000; i++)  {
  d1("test test test");
}
var t = Date.now() - t;
console.log('d1', t);

var t = Date.now();
for (var i = 0; i < 1000000; i++)  {
  d2("test test test");
}
var t = Date.now() - t;
console.log('d2', t);

Output:

wicked@wnote:~/Alawar/debug$ DEBUG=test node index.js 
function colored(fmt) {
    var curr = new Date;
    var ms = curr - (prev[name] || curr);
    prev[name] = curr;

    fmt = '  \033[9' + c + 'm' + name + ' '
      + '\033[3' + c + 'm\033[90m'
      + fmt + '\033[3' + c + 'm'
      + ' +' + humanize(ms) + '\033[0m';

    console.error.apply(this, arguments);
  }
function () {
    // invalidate `enabled` if skips/names has been updated
    if (this_enabled_cache_id === undefined || this_enabled_cache_id < enabled_cache_id) {
      this_enabled = undefined;
    }

    // check if has a cached enabled value, set if necessary
    if (this_enabled === undefined) {
      this_enabled_cache_id = enabled_cache_id;
      this_enabled = debug.enabled(name);
    }

    // if disabled, then noop
    if (this_enabled === false) return;

    formatter(name, c, arguments);
  }
d1 2892
d2 1633

So my variant processes 610k ops/sec where yours gives 'only' 350k ops/sec. They both are also fast enough to have minimal impact on the app.

When debug is enabled but console.error = noop:

console.error = function() {};

var d1 = require('debug')('test');
console.log(d1.toString());
var d2 = require('debug2')('test');
console.log(d2.toString());

var t = Date.now();
for (var i = 0; i < 1000000; i++)  {
  d1("test test test");
}
var t = Date.now() - t;
console.log('d1', t);

var t = Date.now();
for (var i = 0; i < 1000000; i++)  {
  d2("test test test");
}
var t = Date.now() - t;
console.log('d2', t);

Output:

wicked@wnote:~/Alawar/debug$ DEBUG=test node index.js 
function colored(fmt) {
    var curr = new Date;
    var ms = curr - (prev[name] || curr);
    prev[name] = curr;

    fmt = '  \033[9' + c + 'm' + name + ' '
      + '\033[3' + c + 'm\033[90m'
      + fmt + '\033[3' + c + 'm'
      + ' +' + humanize(ms) + '\033[0m';

    console.error.apply(this, arguments);
  }
function () {
    // invalidate `enabled` if skips/names has been updated
    if (this_enabled_cache_id === undefined || this_enabled_cache_id < enabled_cache_id) {
      this_enabled = undefined;
    }

    // check if has a cached enabled value, set if necessary
    if (this_enabled === undefined) {
      this_enabled_cache_id = enabled_cache_id;
      this_enabled = debug.enabled(name);
    }

    // if disabled, then noop
    if (this_enabled === false) return;

    formatter(name, c, arguments);
  }
d1 2892
d2 1633

So my variant processes 610k ops/sec where yours gives 'only' 350k ops/sec. They both are also fast enough to have minimal impact on the app.

@tj

This comment has been minimized.

Show comment Hide comment
@tj

tj Nov 22, 2012

Owner

cool sounds good enough to me, if it ever shows up in profiles we can tinker with it further

Owner

tj commented Nov 22, 2012

cool sounds good enough to me, if it ever shows up in profiles we can tinker with it further

@kosmikko

This comment has been minimized.

Show comment Hide comment
@kosmikko

kosmikko Jan 8, 2013

+1 would be nice feature

kosmikko commented Jan 8, 2013

+1 would be nice feature

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Jan 30, 2013

Sorry for delay. Should I submit a PR?

Sorry for delay. Should I submit a PR?

@tj

This comment has been minimized.

Show comment Hide comment
@tj

tj Feb 6, 2013

Owner

sure man that would be great, I definitely like the idea

Owner

tj commented Feb 6, 2013

sure man that would be great, I definitely like the idea

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Feb 7, 2013

Ok, I'll do this later today.

Ok, I'll do this later today.

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Feb 8, 2013

Ready. There are more changes than for this issue this but I'm afraid they are heavily wired. Review anyway.

Ready. There are more changes than for this issue this but I'm afraid they are heavily wired. Review anyway.

@AlexeyKupershtokh

This comment has been minimized.

Show comment Hide comment
@AlexeyKupershtokh

AlexeyKupershtokh Apr 7, 2013

@visionmedia any chance to get this in the master? I would like to use the original debug package, rather than my fork.

@visionmedia any chance to get this in the master? I would like to use the original debug package, rather than my fork.

@bard

This comment has been minimized.

Show comment Hide comment
@bard

bard Aug 18, 2013

bump

enable() and disable() from node would be great.

bard commented Aug 18, 2013

bump

enable() and disable() from node would be great.

@ajostergaard

This comment has been minimized.

Show comment Hide comment
@ajostergaard

ajostergaard Oct 18, 2013

@visionmedia - perhaps the holdup is lack of documentation?

@visionmedia - perhaps the holdup is lack of documentation?

inca added a commit to inca/debug that referenced this pull request Mar 14, 2014

tj added a commit that referenced this pull request Mar 30, 2014

Merge pull request #82 from inca/master
Exposing enable() method for Node.js to address #27
@tj

This comment has been minimized.

Show comment Hide comment
@tj

tj Apr 28, 2014

Owner

github.com/jstrace/jstrace is nicer for live stuff

Owner

tj commented Apr 28, 2014

github.com/jstrace/jstrace is nicer for live stuff

@tj tj closed this Apr 28, 2014

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment