node debug repl freezes when dumping variables

[ackalker]

Wanting to play around with some jQuery selectors from within Node, I modded an http-agent demo to get this:

var repl = require('repl');

var httpAgent = require('http-agent'),
    jsdom = require('jsdom');

var agent = httpAgent.create('www.google.com', ['finance', 'news', 'images']);

agent.addListener('next', function (err, agent) {
  jsdom.env({
    html: agent.body,
    scripts: [
      'http://code.jquery.com/jquery.min.js'
    ]
  }, function (err, window) {
    var $ = window.jQuery;

    // jQuery is now loaded on the jsdom window created from 'agent.body'
    debugger;
    //console.log($('body').html());

    agent.next();
  });
});

agent.addListener('stop', function (agent) {
  console.log('the agent has stopped');
});

agent.start();

Running node debug agent.js and continuing until the breakpoint in the callback, I wanted to inspect the contents of $('head'):

debug> repl
> $('head')

This freezes the repl and the debugger (or at least it might return something after a very long time, sometimes minutes).

Doing instead:

debug> repl
> console.dir($('head'))

returns results immediately, although not nicely colour-coded etc.

[ackalker]

The same thing happens when trying to dump global, merely typing that and pressing might return results in ~ 3 to 10 seconds, or freeze up altogether.
Again console.dir(global) returns result immediately.

[ackalker]

htop shows nodejs process spinning madly at ~100% cpu while repl is frozen.

[indutny]

What node version are you referring to?

[ackalker]

$ node --version
v0.8.14

(Ubuntu PPA: chris lea)

[ackalker]

I also had to rebuild jsdom to get contextify, otherwise the example wouldn't work at all (different issue)

[ackalker]

much simpler testcase:

timeout.js

setTimeout( function() {
  var bla = 42;
  console.log(bla)
  debugger;
}, 1000)

$ node debug timeout.js
< debugger listening on port 5858
connecting... ok
break in timeout.js:1
  1 setTimeout( function() {
  2   var bla = 42;
  3   console.log(bla)
debug> c
< 42
break in timeout.js:4
  2   var bla = 42;
  3   console.log(bla)
  4   debugger;
  5 }, 1000)
  6 
debug> repl
Press Ctrl + C to leave debug repl
> this

Freeze as before, have to killall nodejs.
Oddly, dumping process works, after a longer delay than what I'm used to from normal repl.

[danmilon]

This test works as expected for me (same version).
Although I get these freezes when I try to dump large/deep objects (eg a mongoose model) from within the repl.

[ackalker]

I understand, debugger has to communicate with debuggee process, but long or permanent freezes on even small objects are somewhat annoying, particularly if there's no way to interrupt them.

[indutny]

/tmp > node debug 1.js
< debugger listening on port 5858
connecting... ok
break in 1.js:1
  1 setTimeout( function() {
  2   var bla = 42;
  3   console.log(bla)
debug> c
< 42
break in 1.js:4
  2   var bla = 42;
  3   console.log(bla)
  4   debugger;
  5 }, 1000)
  6 
debug> repl
Press Ctrl + C to leave debug repl
> this
{ _idleTimeout: 1000,
  _onTimeout: 'function () {\n  var bla = 42;\n  console.log(bla)\n  debugger;\n}',
  _idlePrev: null,
  _idleNext: null,
  _idleStart: Tue Nov 06 2012 19:09:17 GMT+0400 (MSK) }
debug> 
(^C again to quit)
debug> no
debug> 
(^C again to quit)
debug> 
/tmp > node -v
v0.8.14

Same for me.

[indutny]

Freezes are little bit expected, data should be serialized/deserialized. And some objects apparently may refer others in their kind, so sending small object may result in sending whole objects list

[ackalker]

Thanks all of you for helping out!
I think I'm finally gonna build my own node, not rely on prebuilt anymore.
Better way to stay up to date also.

[ackalker]

Working like a charm with self-compiled node. Thanks again!

[ackalker]

Sorry about the spam, I have to reopen.
While the small setTimeout example now works, the original example still doesn't.

Even with node v0.9.4-pre compiled straight from Git, dumping this, process or any medium-sized object still freezes the repl. Again, console.dir(object) works, no noticeable delay, so I seriously doubt that serializing/deserializing the object is the (only) problem here.

[ackalker]

Attaching strace to the spinning node --debug-brk agent.js process shows that it is spinning around reams and reams of:
futex(0x7fa2780008c8, FUTEX_WAKE_PRIVATE, 1) = 1
interspersed with:
mmap(0x128cd5f6c000, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0) = 0x128cd5f6c000 munmap(0x128cd5f6c000, 606208) = 0 munmap(0x128cd6100000, 442368) = 0 mmap(0x128cd6000000, 1048576, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0x128cd6000000 futex(0x7fa2780008c8, FUTEX_WAKE_PRIVATE, 1) = 1
Hopefully this is useful to anyone...

[ackalker]

Link to FlameGraph of spinning process: https://docs.google.com/open?id=0Bw_zs5IJ-GDvN1dncGExSTlRb1k
Sorry about lots of unknowns, perf has no ustack helper :(

Any help with running the test on a system with DTrace support will be greatly appreciated.

[jasnell]

@ackalker ... is this still an issue for you?

[ackalker]

Using node v0.12.3, I no longer see the issue, i.e. the REPL returns results quickly.

[jasnell]

Thanks for checking! Closing for now