All NodeJS apps on my server are leaking memory

[gerenrot]

• NodeJS: 8.9.0:
• OS: CentOS Linux release 7.3.1611 (Core):
• Scope: runtime:

I'm trying to solve a memory leak in my NodeJS app for a long time now. The strange thing is that I have several completely different NodeJS apps on my server and they all leak memory. Their RSS grows indefinitely over time.

• My main app. Its based on hapijs 16.6.2. Its a REST web server that also implements chat using nes 6.4.3 (based ws on 1.1.4)
• An SSR server based on express 4.15.5
• PM2: KM Agent
• PM2 v2.6.1: God

My attempts to find the issue concentrate on the main app. Here is what I did:

• Took many heap dumps: The heap seems stable
• Upgraded NodeJS: the leak was originally observed on NodeJS 6.11.2. An upgrade to 8.9.0 slowed down the leak a bit. It takes the app ~20% more time to reach 1G.
• Tried to run the app without PM2 or cluster mode. The leak still occurs
• Tried to disable THP: the leak still occurs
• Tried to reproduce the leak on staging with not luck

At this point I'm out of ideas what to do next.

Can any of you experts offer a good advise?

[bnoordhuis]

Do the applications actually crash with an out-of-memory error? If so, what's the exact message it prints?

[gerenrot]

@bnoordhuis, thanks for the quick response.
PM2 is configured to restart the apps on a memory limit before they crash. I'll have to check that.

[gerenrot]

@bnoordhuis, I canceled the memory limit restart. The nine app instances run for an hour. RSS grew to 1.8-2.0G but none of them crashed.

At this point performance deteriorated too much and I had to restart.
I'm attaching some NewRelic charts of several metrics that might help. At 02:20 the app was reloaded without a memory restart limit. At 03:17 it was reloaded again.

[gireeshpunathil]

• the memory growth and GC pause times seem to hold a linear relation
• the heap seems stable

these 2 observations do not connect well IMO. Can you double-confirm the heap statistics by collecting one soon after the reload and one around the peak load?

[bnoordhuis]

Is 9 * 2 GB > physical RAM? If yes, start node with --max_old_space_size=n where n ~= 1/10th physical RAM expressed in megabytes. It's not an exact science; experiment with different values and see what works best for you.

If the total footprint of the node processes is bigger than physical memory, the machine starts swapping and performance falls off a cliff.

[gerenrot]

@bnoordhuis, had about 5G left just before restarting the app. The server was not swapping.

@gireeshpunathil, Scavenge is not flat and so is Mark Sweep. The latter only looked flat due to scale. Here's how it looks when I remove Scavenge from the plot:

[gireeshpunathil]

@gerenrot - thanks. I did not mean flat, instead meant to say they reflect the memory growth in some form. The new chart also confirms that relation I guess.

@bnoordhuis - what is your interpretation of the chart data especially around the memory growth and the GC efforts?
Don't they indicate a steadily growing heap?
Or if the memory belongs to native heap, are there such native artifacts which have implications to GC?

[bnoordhuis]

The graphs don't look out of the ordinary. The footprint growing over time does not necessarily indicate a memory leak and seems unlikely since no processes abort.

[gerenrot]

The CPU has 10 cores and 20 threads. CPU is a bit below 50% before the restart and GC Scavenge time is approaching 250 seconds.

Doesn't this mean the 9 threads running the app are constantly garbage collecting?
What could be causing the performance degradation if it's not a leak?

[bnoordhuis]

To clarify, the memory footprint doesn't look unusual, but are you saying scavenge times are in seconds, not milliseconds? That seems almost impossible.

[gerenrot]

According to NewRelic, yes they are in seconds.
CPU load seems to agree with that. It went from about 10% to 50%. 9 CPU threads that are constantly busy would be 270 seconds. The 250 seconds for scavenge seem to account for the extra 40% in CPU.

[bnoordhuis]

What I'd do is start node with node --perf_basic_prof and once it starts spinning, check with perf top -p <pid> what it's doing. At the very least that should tell you if it's actually scavenging.

Forcing a core dump with gcore and inspecting it with lldb+llnode is also a good option.

If live debugging is an option: node --inspect

[gerenrot]

I'll try that, thanks.

[gerenrot]

@bnoordhuis followed your advise about perf top. When CPU went from 10% to 35 (running on 9 out of the 20 cores) I run perf top:

18.52%  node [.] v8::internal::VisitWeakList<v8::internal::JSFunction>
4.79%  node [.] v8::internal::ScavengeWeakObjectRetainer::RetainAs
3.54%  node [.] v8::internal::StoreBuffer::MoveEntriesToRememberedSet
3.25%  node [.] v8::internal::Heap::Scavenge

It is scavenging too much. Since scavenge evolves moving objects and updating pointers, could this be caused by deleting properties instead of setting them to unknown?

[bnoordhuis]

@gerenrot Scavenges don't move objects around, that's the mark-compact phase.

That weak list it's spending so much time on is the list of optimized functions. As a quick (well...) sanity check, does node --turbo_filter="" app.js make the problem go away? That disables the optimizer.

[gerenrot]

The problem persists with --turbo_filter="".
Here's how perf top looks now:

> 4.56%  perf-21525.map                                                   [.] 0x00001ba04506ca83
> 3.10%  perf-21525.map                                                   [.] 0x00001ba04506ca94
> 2.77%  node                                                             [.] v8::internal::BinarySearch<(v8::internal::SearchMode)1, v8::internal::DescriptorArray>
> 2.32%  perf-21525.map                                                   [.] 0x00001ba044f91fcb
> 1.42%  node                                                             [.] v8::internal::StoreBuffer::MoveEntriesToRememberedSet

[bnoordhuis]

You get a different top 5 now so it clearly did something.

Those first two are JS functions. If you start node with --perf_basic_prof, you should get human-readable JS functions names in perf top -g -p <pid> (and call graphs because of -g.)

[gerenrot]

I'm already running node with --perf-basic-prof and I can see JS code symbols in the map file. Not sure why some symbols are still missing.

[gerenrot]

Found why I'm not getting the symbols. Its a file owner issue. Will update later.

[gerenrot]

Here's perf top -g with the optimizer disabled:

+   90.96%     0.09%  node                                                             [.] v8::Function::Call                                                                                                                                                         
+   90.74%     0.16%  node                                                             [.] v8::internal::Execution::Call                                                                                                                                              
+   88.78%     0.00%  node                                                             [.] uv_run                                                                                                                                                                     
+   85.30%     0.00%  node                                                             [.] node::InternalMakeCallback                                                                                                                                                 
+   69.97%     0.00%  node                                                             [.] node::InternalCallbackScope::Close                                                                                                                                         
+   68.43%     0.00%  node                                                             [.] v8::Function::Call                                                                                                                                                         
+   46.22%     0.02%  perf-26492.map                                                   [.] Builtin:JSEntryTrampoline                                                                                                                                                  
+   45.76%     0.03%  perf-26492.map                                                   [.] Stub:JSEntryStub                                                                                                                                                           
+   45.73%     2.91%  perf-26492.map                                                   [.] Builtin:InterpreterEntryTrampoline                                                                                                                                         
+   44.82%     2.80%  perf-26700.map                                                   [.] Builtin:InterpreterEntryTrampoline                                                                                                                                         
+   44.55%     0.01%  perf-26700.map                                                   [.] Stub:JSEntryStub                                                                                                                                                           
+   43.78%     0.01%  perf-26700.map                                                   [.] Builtin:JSEntryTrampoline                                                                                                                                                  
+   43.48%     0.00%  node                                                             [.] node::AsyncWrap::MakeCallback                                                                                                                                              
+   42.25%     0.00%  node                                                             [.] uv__io_poll                                                                                                                                                                
+   33.83%     0.30%  perf-26492.map                                                   [.] BytecodeHandler:CallUndefinedReceiver2                                                                                                                                     
+   32.79%     0.36%  perf-26700.map                                                   [.] BytecodeHandler:CallUndefinedReceiver2                                                                                                                                     
+   32.52%     0.24%  perf-26492.map                                                   [.] Builtin:ArgumentsAdaptorTrampoline                                                                                                                                         
+   32.39%     0.27%  perf-26700.map                                                   [.] Builtin:ArgumentsAdaptorTrampoline          

Expanded:

-   90.58%     0.09%  node                                                             [.] v8::Function::Call                                                                                                                                                         
   - 23.20% v8::Function::Call                                                                                                                                                                                                                                        
      - 23.08% v8::internal::Execution::Call                                                                                                                                                                                                                          
         - 13.34% Stub:JSEntryStub                                                                                                                                                                                                                                    
            - 14.32% Builtin:JSEntryTrampoline                                                                                                                                                                                                                        
               - 13.22% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                            
                  - 9.22% BytecodeHandler:CallUndefinedReceiver2                                                                                                                                                                                                      
                     - 9.18% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                       
                        - 7.87% BytecodeHandler:CallUndefinedReceiver1                                                                                                                                                                                                
                           - 6.45% Builtin:ArgumentsAdaptorTrampoline                                                                                                                                                                                                 
                              - 6.03% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                              
                                 - 5.22% BytecodeHandler:CallProperty2                                                                                                                                                                                                
                                      4.23% Builtin:ArgumentsAdaptorTrampoline                                                                                                                                                                                        
                             1.61% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                 
                    1.83% BytecodeHandler:CallProperty0                                                                                                                                                                                                               
                  + 1.19% BytecodeHandler:CallUndefinedReceiver1                                                                                                                                                                                                      
         - 9.61% Stub:JSEntryStub                                                                                                                                                                                                                                     
            - 10.63% Builtin:JSEntryTrampoline                                                                                                                                                                                                                        
               - 9.82% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                             
                  - 6.77% BytecodeHandler:CallUndefinedReceiver2                                                                                                                                                                                                      
                     - 6.74% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                       
                        - 6.40% BytecodeHandler:CallUndefinedReceiver1                                                                                                                                                                                                
                           - 5.87% Builtin:ArgumentsAdaptorTrampoline                                                                                                                                                                                                 
                              - 5.48% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                              
                                 + 4.77% BytecodeHandler:CallProperty2                                                                                                                                                                                                
                  - 1.68% BytecodeHandler:CallProperty0                                                                                                                                                                                                               
-   90.31%     0.15%  node                                                             [.] v8::internal::Execution::Call                                                                                                                                              
   - 22.95% v8::internal::Execution::Call                                                                                                                                                                                                                             
      - 13.34% Stub:JSEntryStub                                                                                                                                                                                                                                       
         - 14.33% Builtin:JSEntryTrampoline                                                                                                                                                                                                                           
            - 13.22% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                               
               - 9.22% BytecodeHandler:CallUndefinedReceiver2                                                                                                                                                                                                         
                  - 9.19% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                          
                     - 7.87% BytecodeHandler:CallUndefinedReceiver1                                                                                                                                                                                                   
                        - 6.45% Builtin:ArgumentsAdaptorTrampoline                                                                                                                                                                                                    
                           - 6.03% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                 
                              - 5.22% BytecodeHandler:CallProperty2                                                                                                                                                                                                   
                                 + 4.23% Builtin:ArgumentsAdaptorTrampoline                                                                                                                                                                                           
                        + 1.62% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                    
               - 1.83% BytecodeHandler:CallProperty0                                                                                                                                                                                                                  
                  + 1.14% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                          
               + 1.19% BytecodeHandler:CallUndefinedReceiver1                                                                                                                                                                                                         
      - 9.62% Stub:JSEntryStub                                                                                                                                                                                                                                        
         - 10.64% Builtin:JSEntryTrampoline                                                                                                                                                                                                                           
            - 9.83% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                                
               - 6.78% BytecodeHandler:CallUndefinedReceiver2                                                                                                                                                                                                         
                  - 6.75% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                          
                     - 6.41% BytecodeHandler:CallUndefinedReceiver1                                                                                                                                                                                                   
                        - 5.87% Builtin:ArgumentsAdaptorTrampoline                                                                                                                                                                                                    
                           - 5.48% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                 
                              + 4.77% BytecodeHandler:CallProperty2                                                                                                                                                                                                   
               - 1.68% BytecodeHandler:CallProperty0                                                                                                                                                                                                                  
-   84.23%     0.00%  node                                                             [.] node::InternalMakeCallback                                                                                                                                                 
   - 21.99% node::InternalMakeCallback                                                                                                                                                                                                                                
      - 18.71% node::InternalCallbackScope::Close                                                                                                                                                                                                                     
         - 18.67% v8::Function::Call                                                                                                                                                                                                                                  
              18.67% v8::Function::Call                                                                                                                                                                                                                               
      - 3.28% v8::Function::Call                                                                                                                                                                                                                                      
         - 3.27% v8::internal::Execution::Call                                                                                                                                                                                                                        
            - 2.07% Stub:JSEntryStub                                                                                                                                                                                                                                  
               - 2.09% Builtin:JSEntryTrampoline                                                                                                                                                                                                                      
                  + 1.47% Builtin:InterpreterEntryTrampoline                                                                                                                                                                                                          
            + 1.21% Stub:JSEntryStub                

[gerenrot]

Here's a flame graph with optimizer enabled and before it starts spinning:
perf-kernel.svg.gz

[bnoordhuis]

Going by the number of samples, that's about 4 seconds? Nothing in there that really stands out, at a quick glance anyway.

[gerenrot]

Its one node instance for 60 seconds:
perf record -F 99 -a -g -p 22250 -- sleep 60

Thanks for having a look.

[bnoordhuis]

Ah, you might want to raise the frequency to -F 997 (or -c 100, lower = more samples) because you're sampling at a ~10 ms rate now.

[gerenrot]

Here are two more flame graphs. One with the optimizer on and the other with the optimizer turned off. Changed the sample frequency to -F 997 and the sample duration is 60 seconds as before.

optimizer-on.svg.gz
optimizer-off.svg.gz

@bnoordhuis, does anything stand out?

[gerenrot]

Forgot to mention, I waited until the CPU increased from ~8% to ~35% before recording these graphs.

[bnoordhuis]

I've stared at it for quite some time and the most striking difference is GC time: <1% vs. >30%.

Maybe the optimized version runs faster but it fills up the new space 5x more often (~50x vs ~250x), which sets off the garbage collector.

The optimized function linked list is scanned for live objects every scavenge and it's seemingly really long in your application because it takes > ~20 ms every time (avg 66, std 96 - quite a few outliers.)

I think we've identified the cause now but I don't know how to fix it yet. Can you check with node --trace_opt --trace_deopt if your application has repeated opt/deopt cycles? That could explain why that optimized function list is so long.

(Redirect stdout because those options can log a lot of info.)

[gerenrot]

Run node with --trace_opt --trace_deopt for two minutes.
Had 4265 optimizing logs and 688 deoptimizing logs during this time.
Here are the functions that were deoptimized the most number of times:

 52 Instance.set
 32 formatValue
 26 exports.clone
 16 _validate
 16 Module._load
 14 merge
 12 Instance.get
 12 emit
 12 baseClone

I can send you the log privately but rather not post it here. Not sure the data it contains will not introduce a security risk.

[bnoordhuis]

Does it reach a kind of steady state after a few minutes? It doesn't have to be a complete cessation of opt/deopt messages but it should quiet down after a while.

cc @nodejs/v8 - see #947 (comment), the troublesome list is v8::internal::VisitWeakList<v8::internal::JSFunction>.

[hashseed]

Isn't the list gone by now? https://v8project.blogspot.de/2017/10/lazy-unlinking.html?m=1

[bnoordhuis]

I had noticed that Context::OPTIMIZED_FUNCTIONS_LIST is gone in V8 ToT. Is v8/v8@f0acede something that can safely be backported to node.js? The tracking bug is still open and also has a number of other commits associated with it.

[hashseed]

Iiuc there were quite a few changes preceding it. I would not feel comfortable with backporting.

[gerenrot]

@bnoordhuis after 7 minutes I get deoptimizations at a rate of 450 rpm. Is this normal?

[bnoordhuis]

@gerenrot No, that's pretty high. Try getting rid of the most egregious offenders and see if performance improves; it most likely will.

[gerenrot]

The most dominant offender is sequelize Instance.set(key, value, options). I think what happens is that the function is optimized for value accepting a string. However value is really polymorphic and it will occasionally accept something other than a string which will lead to deoptimization.

How can I filter out optimization of this specific function? Couldn't find documentation on --turbo_filter.

[gerenrot]

That's how Instance.set() deoptimization looks in the log:

> [deoptimizing (DEOPT eager): begin 0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)> (opt #493) @169, FP to SP delta: 96, caller sp: 0x7ffcda531010]
>             ;;; deoptimize at </home/app/server/node_modules/sequelize/lib/instance.js:365:136>, Smi
>   reading input frame Instance.set => bytecode_offset=1164, args=4, height=17; inputs:
>       0: 0x3e64aa02ebe1 ; [fp - 16] 0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)>
>       1: 0x3848cff6c1a9 ; [fp + 40] 0x3848cff6c1a9 <JSObject>
>       2: 0x18bafab28829 ; [fp + 32] 0x18bafab28829 <String[10]: isTutorial>
>       3: 0x00000000 ; rbx 0
>       4: 0x38267c1a3c39 ; [fp - 24] 0x38267c1a3c39 <Object map = 0x117254ea8a01>
>       5: 0xd983f3a0701 ; [fp - 8] 0xd983f3a0701 <FixedArray[16]>
>       6: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>       7: 0x27bdfc302311 ; [fp - 32] 0x27bdfc302311 <undefined>
>       8: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>       9: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      10: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      11: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      12: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      13: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      14: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      15: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      16: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      17: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      18: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      19: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      20: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      21: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      22: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>   translating interpreted frame Instance.set => bytecode_offset=1164, height=136
>     0x7ffcda531008: [top + 216] <- 0x3848cff6c1a9 ;  0x3848cff6c1a9 <JSObject>  (input #1)
>     0x7ffcda531000: [top + 208] <- 0x18bafab28829 ;  0x18bafab28829 <String[10]: isTutorial>  (input #2)
>     0x7ffcda530ff8: [top + 200] <- 0x00000000 ;  0  (input #3)
>     0x7ffcda530ff0: [top + 192] <- 0x38267c1a3c39 ;  0x38267c1a3c39 <Object map = 0x117254ea8a01>  (input #4)
>     -------------------------
>     0x7ffcda530fe8: [top + 184] <- 0x17c09e526467 ;  caller's pc
>     0x7ffcda530fe0: [top + 176] <- 0x7ffcda531070 ;  caller's fp
>     0x7ffcda530fd8: [top + 168] <- 0xd983f3a0701 ;  context    0xd983f3a0701 <FixedArray[16]>  (input #5)
>     0x7ffcda530fd0: [top + 160] <- 0x3e64aa02ebe1 ;  function    0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)>  (input #0)
>     0x7ffcda530fc8: [top + 152] <- 0x27bdfc302311 ;  new_target  0x27bdfc302311 <undefined>  (input #0)
>     0x7ffcda530fc0: [top + 144] <- 0x1e7c378ead71 ;  bytecode array 0x1e7c378ead71 <BytecodeArray[1464]>  (input #0)
>     0x7ffcda530fb8: [top + 136] <- 0x4c100000000 ;  bytecode offset @ 1164
>     -------------------------
>     0x7ffcda530fb0: [top + 128] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #6)
>     0x7ffcda530fa8: [top + 120] <- 0x27bdfc302311 ;  0x27bdfc302311 <undefined>  (input #7)
>     0x7ffcda530fa0: [top + 112] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #8)
>     0x7ffcda530f98: [top + 104] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #9)
>     0x7ffcda530f90: [top + 96] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #10)
>     0x7ffcda530f88: [top + 88] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #11)
>     0x7ffcda530f80: [top + 80] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #12)
>     0x7ffcda530f78: [top + 72] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #13)
>     0x7ffcda530f70: [top + 64] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #14)
>     0x7ffcda530f68: [top + 56] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #15)
>     0x7ffcda530f60: [top + 48] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #16)
>     0x7ffcda530f58: [top + 40] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #17)
>     0x7ffcda530f50: [top + 32] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #18)
>     0x7ffcda530f48: [top + 24] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #19)
>     0x7ffcda530f40: [top + 16] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #20)
>     0x7ffcda530f38: [top + 8] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #21)
>     0x7ffcda530f30: [top + 0] <- 0x27bdfc3025a9 ;  accumulator 0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #22)
> [deoptimizing (eager): end 0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)> @169 => node=1164, pc=0x17c09e1c02c0, caller sp=0x7ffcda531010, state=TOS_REGISTER, took 0.638 ms]
> [deoptimizer unlinked: Instance.set / 3e64aa02ebe1]
> [deoptimizing (DEOPT lazy): begin 0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)> (opt #493) @41, FP to SP delta: 96, caller sp: 0x7ffcda5310a0]
>   reading input frame Instance.set => bytecode_offset=335, args=4, height=17; inputs:
>       0: 0x3e64aa02ebe1 ; [fp - 16] 0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)>
>       1: 0x3848cff6c1a9 ; [fp + 40] 0x3848cff6c1a9 <JSObject>
>       2: 0x3848cff6c2f1 ; [fp + 32] 0x3848cff6c2f1 <Object map = 0x117254ea7c41>
>       3: 0x38267c1a3c39 ; [fp + 24] 0x38267c1a3c39 <Object map = 0x117254ea8a01>
>       4: 0x38267c1a3c39 ; [fp - 32] 0x38267c1a3c39 <Object map = 0x117254ea8a01>
>       5: 0xd983f3a0701 ; [fp - 8] 0xd983f3a0701 <FixedArray[16]>
>       6: 0x3848cff6c2f1 ; [fp + 32] 0x3848cff6c2f1 <Object map = 0x117254ea7c41>
>       7: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>       8: 0x3848cff6c519 ; [fp - 40] 0x3848cff6c519 <JSArray[19]>
>       9: 3 ; (int) [fp - 24]
>      10: 0x1300000000 ; [fp - 48] 19
>      11: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      12: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      13: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      14: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      15: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      16: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      17: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      18: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      19: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      20: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      21: 0x27bdfc3025a9 ; (literal 2) 0x27bdfc3025a9 <Odd Oddball: optimized_out>
>      22: 0x3848cff6c1a9 ; rax 0x3848cff6c1a9 <JSObject>
>   translating interpreted frame Instance.set => bytecode_offset=335, height=136
>     0x7ffcda531098: [top + 216] <- 0x3848cff6c1a9 ;  0x3848cff6c1a9 <JSObject>  (input #1)
>     0x7ffcda531090: [top + 208] <- 0x3848cff6c2f1 ;  0x3848cff6c2f1 <Object map = 0x117254ea7c41>  (input #2)
>     0x7ffcda531088: [top + 200] <- 0x38267c1a3c39 ;  0x38267c1a3c39 <Object map = 0x117254ea8a01>  (input #3)
>     0x7ffcda531080: [top + 192] <- 0x38267c1a3c39 ;  0x38267c1a3c39 <Object map = 0x117254ea8a01>  (input #4)
>     -------------------------
>     0x7ffcda531078: [top + 184] <- 0x17c09e105d1b ;  caller's pc
>     0x7ffcda531070: [top + 176] <- 0x7ffcda5310b8 ;  caller's fp
>     0x7ffcda531068: [top + 168] <- 0xd983f3a0701 ;  context    0xd983f3a0701 <FixedArray[16]>  (input #5)
>     0x7ffcda531060: [top + 160] <- 0x3e64aa02ebe1 ;  function    0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)>  (input #0)
>     0x7ffcda531058: [top + 152] <- 0x27bdfc302311 ;  new_target  0x27bdfc302311 <undefined>  (input #0)
>     0x7ffcda531050: [top + 144] <- 0x1e7c378ead71 ;  bytecode array 0x1e7c378ead71 <BytecodeArray[1464]>  (input #0)
>     0x7ffcda531048: [top + 136] <- 0x18400000000 ;  bytecode offset @ 335
>     -------------------------
>     0x7ffcda531040: [top + 128] <- 0x3848cff6c2f1 ;  0x3848cff6c2f1 <Object map = 0x117254ea7c41>  (input #6)
>     0x7ffcda531038: [top + 120] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #7)
>     0x7ffcda531030: [top + 112] <- 0x3848cff6c519 ;  0x3848cff6c519 <JSArray[19]>  (input #8)
>     0x7ffcda531028: [top + 104] <- 0x300000000 ;  3  (input #9)
>     0x7ffcda531020: [top + 96] <- 0x1300000000 ;  19  (input #10)
>     0x7ffcda531018: [top + 88] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #11)
>     0x7ffcda531010: [top + 80] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #12)
>     0x7ffcda531008: [top + 72] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #13)
>     0x7ffcda531000: [top + 64] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #14)
>     0x7ffcda530ff8: [top + 56] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #15)
>     0x7ffcda530ff0: [top + 48] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #16)
>     0x7ffcda530fe8: [top + 40] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #17)
>     0x7ffcda530fe0: [top + 32] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #18)
>     0x7ffcda530fd8: [top + 24] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #19)
>     0x7ffcda530fd0: [top + 16] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #20)
>     0x7ffcda530fc8: [top + 8] <- 0x27bdfc3025a9 ;  0x27bdfc3025a9 <Odd Oddball: optimized_out>  (input #21)
>     0x7ffcda530fc0: [top + 0] <- 0x3848cff6c1a9 ;  accumulator 0x3848cff6c1a9 <JSObject>  (input #22)
> [deoptimizing (lazy): end 0x3e64aa02ebe1 <JSFunction Instance.set (sfi = 0xfe86a07de09)> @41 => node=335, pc=0x17c09e1c01e0, caller sp=0x7ffcda5310a0, state=TOS_REGISTER, took 0.568 ms]

[bnoordhuis]

How can I filter out optimization of this specific function?

// The filter is a pattern that matches function names in this way:
//   "*"      all; the default
//   "-"      all but the top-level function
//   "-name"  all but the function "name"
//   ""       only the top-level function
//   "name"   only the function "name"
//   "name*"  only functions starting with "name"
//   "~"      none; the tilde is not an identifier

The logic is here if you need it.

[gerenrot]

@bnoordhuis can you refer me to tools or resources for optimization? most articles I can across were outdated or didn't go deep enough to be useful in my case.

[bnoordhuis]

There's https://github.com/nodejs/node/tree/v8.9.0/deps/v8/tools/turbolizer but I'm not the right person to ask how it works, I don't use it much.

[kapilgp]

Is there any final conclusion of this, I am also getting same issue in node application.

GC Pause Time: 8s
Memory Continuous Increasing
Cpu Utilization countionus increasing

And at the end node is down after reaching 100%.

[bleupen]

are you using https in nodejs? we encountered a very similar problem that went away entirely after we moved https processing to nginx. we have a simple test case where we continually post to a long running route (~2 seconds on avg) with lots of IO. You can clearly see where we switched off https at around 12:05.

[kapilgp]

This was due to setInterval functions. So on every hit there is one more setInterval encountered and it's increasing GC and CPU utilizations.