node.js javascript debugger starting very slowly

Running on linux (ubuntu 12.04), Idea 11.1.5 or Idea 11.1.4, node v0.8.22 or v0.8.8. 16GB RAM, plenty of disk space, Intel i7 CPU, no software firewall running.

I am working in node v0.8.22, Idea 11.0.5 on a client-server project on a local disk. When starting the debugger, it seems that lately it takes about 3 minutes (2:55 typically) for Idea to bring up the javascript program and connect with it. (I see the same issue with v0.8.8 and Idea 11.0.4.)

Once the connection is made, debugging works just fine in every way.

If I use node-inspector instead of Idea and run the program from the command-line, it starts and connects immediately. It goes without saying that I like debugging with Idea much better than with node-inspector and Chrome.  

I cannot be absolutely sure, but this issue seems to have come up since December 2012 when I last worked on the project. I am sure I would have noticed it if I had seen it before.

It may be something strange in my environment, but I can't figure out where to start looking. Has anyone else seen a problem with this? Or have any suggestions where to start looking?  
Thanks for any suggestions

John

12 comments

Problem solved, I believe. While doing something else, I found an Idea process running that did not look like it should be there. After killing all Idea processes and restarting, I no longer see the problem.  
I would love to know the underlying cause, but I am happy to have JavaScript debugging back.

0

Maybe this issue is relevant http://youtrack.jetbrains.com/issue/WEB-6581 .
If you encounter this problem once more, please attach here your idea.log file (on the main menu Help | Reveal Log in Nautilus).

0

Alas, the problem is back on two different Ubuntu (12.04 Precise) systems, one at home and one at work. Two minutes and 30 seconds to first load the javascript app. I am attaching a log although it seems to be empty for the two minutes during the loading time (from about 13:55:47 to 1:57:27).  The app starts up instantaneously in 'RUN' mode (instead of debug).

I have looked at the other issue (WEB-6581) and can try the small app given there if you recommend that.

Thank you. --JB



Attachment(s):
idea.log.zip
0

Thanks for the log.
Well, looks like http://youtrack.jetbrains.com/issue/WEB-6581 issue isn't relevant for your situation, because according to the log you are running NodeJS 117.746 plugin version, and that issue affects versions >= 126.159.
Anyway, please try the small app attached to the http://youtrack.jetbrains.com/issue/WEB-6581#comment=27-450298. Looking forward to the results.

0

I think I have determined that IDEA is somehow interfering with modules loaded using the NODE_PATH environment variable.
The first two sections below list loading times for
1. small app
2. my large app using NODE_PATH to find and load modules
3. my large app in an earlier version in which all dependency modules were all symlinked to the node_modules directory under each program module. NODE_PATH is left undefined.

For the small app:
---------------------------

From terminal window
> debugger listening on port 5858
> Taken time: 0.08370537683367729 seconds

In Idea
> debugger listening on port 39808
> Taken time: 0.951734478585422 seconds


For my big app I added a time log message at the beginning of the script before any 'require' or configuration loading.
---------------------------------------------------------------------
From keyboard:  node --debug ...
> Time: 9:21:47
> +!1364390507479|0|jobserver|INFO|jobserver|anon|13-3-27 9:21:47.479| Startup 1364390507479

In Idea:
> debugger listening on port 42840
> Time: 9:11:02
> +!1364390021118|0|jobserver|INFO|jobserver|anon|13-3-27 9:13:41.118| Startup 1364390021117


In the big app, there are a number of scripts, loaded as modules accessible from two directories, and the environment NODE_PATH is used to locate the modules. Up until about a month ago, the "external" modules were all symlinked under the "node_modules" directory for each reference.


!!AHA!! I pulled an older version of the app, which does not rely on NODE_PATH, but uses the symlinked modules to load everything:
We have about 14 module dependencies in the symlinked version of the script I was testing (those dependency modules might rely on an average of 0-2 symlinked modules apiece).
The NODE_PATH version uses about the same number of dependency modules.

Times using symlinks to locate modules instead of NODE_PATH
----------------------------------------------------------------------------------------------
From terminal:  (-- no change -- )
> debugger listening on port 5858
> Time: 9:42:42
> +!1364391762513|0|jobserver|INFO|jobserver|anon|13-3-27 9:42:42.513| Startup 1364391762513


From IDEA:   ( -- BIG change --)
> debugger listening on port 36532
> Time: 9:40:0
> +!1364391614045|0|jobserver|INFO|jobserver|anon|13-3-27 9:40:14.045| Startup 1364391614045


So it looks like somehow IDEA is somehow interfering with the NODE_PATH search.




0

Test 2:
After painstakingly linking all the modules in the current version of my app (and removing any circularities that the Idea node js plugin found), I thought I had got a shorter load time:
but it turned out the loading-time was now spread throughout the load rather than being incurred at once.  So on closer inspection,the sym-linking turns out to be a non-solution.
I suspect that if I re-run the experiment from my previous reply, I will likely find that I was fooled by the speed to the first log message (14 seconds) and did not check the time to the startup-completion log message. (Sad.)

IDEA version ~4 minutes to real startup
--------------------
> debugger listening on port 52095
> Time:14:49:25
> +!1364410190406|0|jobserver|INFO|jobserver|anon|13-3-27 14:49:50.406| Startup 1364410190406

> +!1364410403161|62|jobserver|INFO|ak6n82C|5heC1|jobserver-init|anon|13-3-27 14:53:23.161| HTTP Server listening on port 9080



Commandline version: < 1 second to real startup.
--------------------------------


Vs the version from the terminal which takes < 1 second:
> node --debug jobserver/jobserver.js >&js.log &
>Time:14 : 55 : 58
...
> +!1364410558392|62|jobserver|INFO|ak6n82C|NLEns|jobserver-init|anon|13-3-27 14:55:58.392| HTTP Server listening on port 9080

More news  NODE_PATH version is even worse.
===================================
The symlinked version took 4 minutes to get to real start-up.
The NODE_PATH version of the same code takes 8 minutes to get to real start-up.

Conclusion, the symlinked version performs twice as fast as the NODE_PATH-dependent version, but is still not usable. So back to node-inspector for a while.

For what its worth: the big (~ 1 minute) speed-bumps I can see from my app's log involve opening another socket to communicate with a service by socket: MongoDB client or Zookeeper

0

If I understand you correctly the problem is reproducible even on empty JavaScript file (because you said you added a time log message at the beginning of the script before any 'require' or configuration loading).
If so, could you please describe how I can create the same dependencies to reproduce the problem (or if possible attach archived version here).
Thanks.

0

So far I haven't been able to come up with a reasonably small app that causes the problem.  I will keep trying.
The script that I used to produce the time logs was a very small file with two 'require' lines. I put the first time log message at the very beginning of the file and that comes out right away.Then the small file calls a bigger script that loads everything else and kicks things off. So it's not really an empty file. It is more like the handle of a long lever.

The whole app is pretty big and depends on a lot of environment: MongoDB, ZooKeeper, nginx, etc.  So it would be pretty hopeless at this stage to try and package it for someone else to test.  

Since the long pauses seemed to come after log lines about connecting to MongoDB or to ZooKeeper, I tried to put together a small app that just does that. It did not reproduce the behavior, so I will have to probe deeper.

Thanks for the help so far,

JB

0

The problem disappeared in the same mysterious way that it had appeared. Apparently something in my environment was interacting with something in the node plugin.Unfortunately, I have not been able to reproduce the problem by modifying various things in the environment.  If I find what caused the problem, I will report it. For the last two days, Idea has been starting up in debug mode with no delay.

Thanks for helping me try to track this down. It still amazes me how Idea continues to be a great IDE while keeping up with all the technology.

JB

0

I think I found the issue that was causing my slowdown. I had set a 'JavaScript Exception Breakpoint' on 'Type Error'.  I verified that setting a JavaScript breakpoint on "All exceptions" causes the extremely slow startup. I believe that the 'Type Error' or similar generic exception breakpoint will also cause a slow startup problem.  Once I think about the implications of instrumenting to check for an exception on every JavaScript instruction, it makes sense that the debugger might slow down significantly when loading a large body of code.
--JB

0

It seems our bug. But a lot of work was done in this area since WebStorm 6 release, WebStorm 7 EAP will begin soon.

0

Please sign in to leave a comment.