Large process getting slower and slower

[Blake McBride]

Greetings,

I have a large, very recursive process that (at best) takes 6 minutes to run.  This process does a lot of IO, and a lot of directory recursion.  In order to play nicely in a single threading event oriented system, I:

1.  use non-blocking function whenever available

2.  rather than perform recursion directly, I call the next step with nextTick or setImmediate and exit

This has worked well in my smaller databases, and the first time through the large one (6 minutes).  But when trying to run the large one a second time, it gets slower and slower until it kind of never ends.  I don't know what is causing the slowdown.

One thing I thought of is that perhaps I am filling the event queue in such a way so that the IO never gets a chance and it has to go through many, many events before any real IO can occur.  Don't know.

Sure appreciate any ideas.

Thanks.

Blake McBride

[zladuric]

Well, for one, IIRC setImmediate will not put this step on the next loop - it will just append the function to the end of the current loop - thus never giving Node.js a chance to go off.

Another thing - did you try to use a debugger or something? Even a simple strace/dtrace would tell you what the node process is doing. Also, did the first program exit? Maybe it didn't and you're leaking more and more memory, thus swapping more and more?

[Tom Boutell]

I believe this statement is not accurate. setImmediate *does* wait for the next loop, while nextTick runs at the end of the current loop; if you overuse nextTick, no I/O can take place.

http://stackoverflow.com/questions/15349733/setimmediate-vs-nexttick

As many commenters point out there, the names are pretty horrendously backwards. In the case of setImmediate that's because that name is used in the browser already and has those semantics, so node is just following the pattern. In the case of nextTick it's because the node developers, in their infinite wisdom, changed the behavior starting in node 0.9. Once upon a time it worked as you describe.

TL;DR: use setImmediate unless you've thought through why nextTick is safe in this case.

[Peter Rust]

If the time is exponentially increasing, it could be an indication that each iteration is adding event handlers and that old event handlers from previous iterations are being inadvertently fired. As zladuric mentions, you'll want to use a debugger or logging to get some insight into what your program is doing that you don't expect.

Personally, I like https://github.com/node-inspector/node-inspector. I would put a breakpoint or some logging at key points in the program (especially expensive event handlers) and ensure they're when I expect & the number of times I expect, especially in subsequent runs of the program.

If you find that your program's execution is running as expected, then it could be a memory leak, causing a bunch of objects to get built up, which makes the garbage collection sweeps take an inordinate amount of time. Unfortunately, node-inspector doesn't have profiling built-in yet, but you could use https://github.com/c4milo/node-webkit-agent or Memwatch/heapdump or StrongLoop's profiling tools or other solutions linked to in Will Villanueva's node.js profiling guide.

[Blake McBride]

Memory is stable.  Also, I am running on a 16 GB machine with 10 GB free.

[Nathan White]

Blake,

You mentioned large amount of directory recursion. I hit a similar wall at roughly 2000 files where the process would start to slow down drastically. My process was very similar to what you described.

After wasting considerable time I noticed that native 'fs' module was complete rewritten in iojs. After switching from node to iojs the problem went away completely. 

What version and OS are you running this on?

--
Job board: http://jobs.nodejs.org/
New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
---
You received this message because you are subscribed to the Google Groups "nodejs" group.
To unsubscribe from this group and stop receiving emails from it, send an email to nodejs+un...@googlegroups.com.
To post to this group, send email to nod...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/e80bfd1f-fcd2-4ca2-847a-4c0425c6db5d%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Blake McBride]

I am running node 0.12.4 on current 64 bit Linux.  

Also, I added a counter to increment each time I called setImmediate, and decremented each time the callback got called - to get  the queue size.  It remained at one.

Thanks!

[Blake McBride]

I tried iojs.  Same problem.

On Thursday, June 4, 2015 at 10:00:14 AM UTC-5, nwhite wrote:

[Tom Boutell]

It's probably time to try to reduce this to a simple proof of concept program.

--

Job board: http://jobs.nodejs.org/
New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
---

You received this message because you are subscribed to a topic in the Google Groups "nodejs" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/nodejs/paiiviSs8P8/unsubscribe.
To unsubscribe from this group and all its topics, send an email to nodejs+un...@googlegroups.com.

To post to this group, send email to nod...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/a03f5f95-f284-4d91-9e23-044ef8491ede%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

--

THOMAS BOUTELL, DEV & OPS

P'UNK AVENUE | (215) 755-1330  |  punkave.com

[Blake McBride]

Think I may have found the problem.  When the second scan is running, until it is done, the system retains and uses the original data structure.  What is happening is that holding both in memory is causing the GC to go nuts - not enough memory.  Apparently, node doesn't just keep allocating more real memory as needed.  There is some max set.

What is the best way to determine what my memory footprint is and how can I control it?

Thanks.

Blake

[Peter Rust]

> what is the best way to determine what my memory footprint is

The *easiest* way is process.memoryUsage(), the *best* way depends on what exactly you want (there are some cool analytics/memory profiling tools in the aforementioned links)

> how can I control it?

There is a command-line flag, --max_old_space_size, but it only goes to a max of 1.4gb. If you need to go beyond that, this article discusses options.

The article also mentions the "ulimit" command, which you may need if you're on OSX and running up against the default maximum number of files open simultaneously.

[Tom Boutell]

I wonder if opening thousands of files is actually faster than opening [some sweet spot number] of files at a time.

--
Job board: http://jobs.nodejs.org/
New group rules: https://gist.github.com/othiym23/9886289#file-moderation-policy-md
Old group rules: https://github.com/joyent/node/wiki/Mailing-List-Posting-Guidelines
---

You received this message because you are subscribed to a topic in the Google Groups "nodejs" group.
To unsubscribe from this topic, visit https://groups.google.com/d/topic/nodejs/paiiviSs8P8/unsubscribe.
To unsubscribe from this group and all its topics, send an email to nodejs+un...@googlegroups.com.

To post to this group, send email to nod...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/nodejs/de0cc1b7-79e7-41ca-b9b3-d6c7546f0b9c%40googlegroups.com.

For more options, visit https://groups.google.com/d/optout.

[Jimb Esser]

The article you referenced is more than 3 years old.  I believe that starting with the V8 version introduced sometime around node 0.10.0, --max_old_space_size works great (we're using --max_old_space_size=8192 and, if I recall correctly, having no problems even when our process was using 4+gb of RAM).

[Peter Rust]

Jimb: Thanks for the correction! Perhaps the joyent FAQ wiki page needs an update? ("The limit can be raised by setting --max_old_space_size to a maximum of ~1024 (~1 GiB) (32-bit) and ~1741 (~1.7GiB) (64-bit)")