Does my NodeJS application leak memory? – 5

Mark-Sweep, Mark-Compact

In the last post I talked about Scavenges, semi-spaces, new and old spaces, new space to old space promotion, garbage collection algorithms and tracing garbage collection events. In this installment I will discuss the “Mark-Sweep, Mark-Compact” garbage collector.

Mark-Sweep and Mark-Compact operate in two phases. Marking (marking all the live objects) and Sweeping, Compacting (getting rid of dead objects and reducing fragmentation if needed). Commonly referred to as mark-and-sweep collector.

Marking involves locating and processing all the live objects. An object is considered live if it is being referenced by some chain of pointers to a root object or another live object. Putting it another way, an object is live if and only if, it can be reached by following a chain of references from a set of known roots(e.g. global variables for instance)

Essentially, the marking process involves scanning, locating(discovering) and then processing(marking) the live objects. The garbage collector considers all the unmarked (unprocessed) objects as disposable or dead. Marking is done using tri color abstraction, where white, grey and black represent the marking states. In reality they are bits in a marking bitmap.

In this, white objects have not been located(or discovered) by the marker, while grey objects have been discovered but not much is known about its neighbors and finally black objects have been fully processed and are considered live. To assist in this effort a marker queue is used which tracks the marking progress.

The marking process uses the Depth First Search algorithm to scan the object graph and is best explained using an example. Consider: const a = {b: {c: [1, 2], d: [3, 4]}}; This can be written as:

const a = {};
a.b = {};
a.b.c = [1, 2];
a.b.d = [3, 4];

#1. The initial object graph. All objects are white as they have yet to be scanned. The marker queue is empty – Q = [ ].

#2. The scan starts with the root which is the variable “a”. It is marked grey and pushed to the queue. The grey indicates that “a” has been discovered(or visited, located) but has still to be fully processed. In other words its neighbors(children) if any have yet to be discovered. We now have Q = [a].

leaks-post.031

#3. Continuing with the depth search(following edge a.b) object “b” is discovered, marked grey and pushed on to the marker queue.

#4. The depth search continues and object “c” is discovered(edge b.c).  It too is marked grey and pushed to the queue – Q = [a, b, c]. At this point the search stops as there is nothing beyond “c”(c is a leaf).

#5. As the search cannot continue object “c” is popped from the queue and marked black as it now has been fully processed. In other words it has been visited and it has no neighbors.

At this point Q = [a, b].

#6. Now that object “c” has been processed, the search continues by backtracking to the parent object “b”. Continuing it identifies(discovered)  object “d” a child of “b”. Object “d” is now marked grey and pushed to the queue. We now have Q = [a, b, d].

#7. As the search cannot continue, object “d” is popped from the queue and marked black as it now has been fully processed. In other words it has been visited and it has no neighbors or children. At this point Q = [a, b].

#8. The search continues by backtracking to object “b”. As all its children(neighbors) have been processed it is considered fully processed and so it is popped and marked black. Q = [a];

leaks-post.037

#9. The search continues by backtracking to object “a”. As all its children(neighbors) have been processed it is considered fully processed and so it is popped and marked black. We now have q = []. The queue is empty as all objects have been processed. In this case all objects are live and no garbage collection will take place.

leaks-post.038Assume that in the above example at some point in the program execution, object “d” has been assigned null. So a = {b: {c: [1, 2], d: null}}; This can be written as: a.b.d = null;

This is how the marking will progress:

As “d” is detached from the tree it is never visited or processed. Object “d”, remains white after the marking process is complete and will be garbage collected.

Once marking is complete V8 triggers a sweep event when it believes memory will be required. The sweeper follows a simple process, it destroys all the unmarked (white) objects and optionally compacts the fragmented live objects.

Note that the old space could be very large in size. The default is in excess of 1 GB. It would take the collector a long time(in hundreds of milliseconds) to mark a large number of live objects. This would have an impact on performance as, this is, like I have mentioned before, stop the world gc. To avoid this, an “incremental marker” is used. In this, the live objects are marked in small increments or steps, making sure that no step takes more than 5ms giving as much time as possible to allow the application program to run and be performant. Using the same premise as marking, it would take a sweeper a long time to sweep large swaths of memory. For this, lazy sweeping is used, where only the “just” needed amount of sweeping is done based on how much memory that needs to be freed for the current requests. Rest of the sweeping is kept for a later time.

Now that the theory is out of the way and that you have understood how marking and sweeping take place let’s trace through the logs of two contrived examples. To quickly illustrate the point we will be running both programs in limited memory space by limiting the new space to 1MB and old space to 20 MB.

Example 1:

In the first example the program with every iteration, pushes a string of 1,000,000 characters into the array a.b.c. No memory is being freed. As the maximum old space is limited to a little more than 20MB, the application will eventually run out of memory.

/*
Example-1
Run with: node -trace_gc --trace_incremental_marking --max_semi_space_size=1 --max_old_space_size=20 example-1.js
A contrived example to gradually exhaust memory
*/

"use strict";
const a = {b: {c: []}};
let i = 0;

function aString (s) {
let text = '';
for (let i = 0; i < 10000; i++) {
//string of 100 characters
text += 'Lorem Ipsum is simply dummy text of the printing and typesetting industry. Lorem Ipsum has been the ';
}
s.push(text); //push in 1,000,000 bytes of data
}

//Push in 1,000,000 bytes of data till the system
//runs out of memory
setInterval(function () {
aString(a.b.c);
}, 500);

We will use the command:

node -trace_gc -trace_gc_verbose –trace_incremental_marking  –max_semi_space_size=1  –max_old_space_size=20 example-1.js

where:
trace_gc – Creates the basic gc trace, discussed in the previous post
max_semi_space_size – The size of the new space. This is set at 1MB. Remember there are two semi spaces in the new space.
max_old_space_size – The max size of old space. This is set at 20MB
trace_incremental_marking – traces the progress of the incremental marker

The following is the trace with the commentary interspersed:

node -trace_gc --trace_incremental_marking --max_semi_space_size=1 --max_old_space_size=20 example-1.js

V8 initialization - we ignore this
[35841:0x103000000] 72 ms: Scavenge 2.1 (6.0) -> 2.1 (7.0) MB, 0.8 / 0.0 ms [allocation failure].
[35841:0x103000000] 73 ms: Scavenge 2.1 (7.0) -> 2.1 (8.0) MB, 0.7 / 0.0 ms [allocation failure].

Scavenge GC events. With every iteration 1,000,000 bytes are pushed and as the new space is limited to 1MB the new space will fill up pretty much immediately
promoting all data to old space. The scavenge event has been triggered due to "allocation failure" as there is no new space available for 
incoming data and no data is being deleted. In a time span of about 7 seconds the size of the objects grows from 4.0MB to 8.9MB. 
Allocation grows from 11MB to 16MB

[35841:0x103000000] 640 ms: Scavenge 4.0 (11.0) -> 3.7 (11.0) MB, 0.9 / 0.0 ms [allocation failure].
[35841:0x103000000] 643 ms: Scavenge 4.0 (11.0) -> 3.9 (12.0) MB, 1.6 / 0.0 ms [allocation failure].
[35841:0x103000000] 1666 ms: Scavenge 4.7 (12.0) -> 4.6 (12.0) MB, 1.7 / 0.0 ms [allocation failure].
[35841:0x103000000] 2173 ms: Scavenge 4.9 (12.0) -> 4.9 (12.0) MB, 2.4 / 0.0 ms [allocation failure].
[35841:0x103000000] 3181 ms: Scavenge 5.6 (12.0) -> 5.6 (13.0) MB, 2.2 / 0.0 ms [allocation failure].
[35841:0x103000000] 3183 ms: Scavenge 5.9 (13.0) -> 5.9 (13.0) MB, 2.0 / 0.0 ms [allocation failure].
[35841:0x103000000] 4191 ms: Scavenge 6.5 (13.0) -> 6.5 (14.0) MB, 2.0 / 0.0 ms [allocation failure].
[35841:0x103000000] 4698 ms: Scavenge 6.9 (14.0) -> 6.9 (14.0) MB, 1.8 / 0.0 ms [allocation failure].
[35841:0x103000000] 5709 ms: Scavenge 7.5 (14.0) -> 7.5 (15.0) MB, 1.9 / 0.0 ms [allocation failure].
[35841:0x103000000] 6213 ms: Scavenge 7.9 (15.0) -> 7.9 (15.0) MB, 2.3 / 0.0 ms [allocation failure].
[35841:0x103000000] 6718 ms: Scavenge 8.5 (15.0) -> 8.5 (16.0) MB, 2.0 / 0.0 ms [allocation failure].
[35841:0x103000000] 7223 ms: Scavenge 8.9 (16.0) -> 8.9 (16.0) MB, 2.4 / 0.0 ms [allocation failure].

V8 needs to free memory for allocation. All the promoted data is now accumulating in the old space. V8 triggers incremental marking for a possible sweep GC event.
[IncrementalMarking] Start (GC epilogue)
[IncrementalMarking] Start marking
[IncrementalMarking] Running

The scavenge event happens in the new space while marking happens in the old space. So these two events can happen concurrently.
[IncrementalMarking] Scavenge during marking.
The inflow of data from the new space is being promoted to the old space at a steady pace and the incremental marker decides to speed up it rate of marking to keep up with the inflow

[35841:0x103000000] Increasing marking speed to 3 due to high promotion rate
In this scavenge event the marker marked memory in 9 steps which took a total of 1.2 ms or 0.13ms per step. Note that this is since last gc event which was at 7223ms.

[35841:0x103000000] 8236 ms: Scavenge 9.5 (16.0) -> 9.5 (17.0) MB, 2.1 / 0.0 ms (+ 1.2 ms in 9 steps since last GC) [allocation failure].
Marking and Scavenging continues...
[IncrementalMarking] Scavenge during marking.
[35841:0x103000000] 8743 ms: Scavenge 9.9 (17.0) -> 9.9 (17.0) MB, 2.2 / 0.0 ms (+ 1.1 ms in 6 steps since last GC) [allocation failure].
[IncrementalMarking] Scavenge during marking.
[35841:0x103000000] 9251 ms: Scavenge 10.5 (17.0) -> 10.5 (18.0) MB, 2.1 / 0.0 ms (+ 2.1 ms in 10 steps since last GC) [allocation failure].
[IncrementalMarking] Scavenge during marking.
[35841:0x103000000] 9755 ms: Scavenge 10.8 (18.0) -> 10.8 (18.0) MB, 2.4 / 0.0 ms (+ 1.5 ms in 6 steps since last GC) [allocation failure].
[IncrementalMarking] Scavenge during marking.
[35841:0x103000000] 10766 ms: Scavenge 11.5 (18.0) -> 11.5 (19.0) MB, 2.2 / 0.0 ms (+ 1.9 ms in 10 steps since last GC) [allocation failure].
[IncrementalMarking] Scavenge during marking.
[35841:0x103000000] 11274 ms: Scavenge 11.8 (19.0) -> 11.8 (19.0) MB, 2.1 / 0.0 ms (+ 1.2 ms in 6 steps since last GC) [allocation failure].
[IncrementalMarking] Scavenge during marking.
[35841:0x103000000] 12287 ms: Scavenge 12.4 (19.0) -> 12.4 (20.0) MB, 2.2 / 0.0 ms (+ 2.1 ms in 10 steps since last GC) [allocation failure].

[IncrementalMarking] requesting finalization of incremental marking.
[IncrementalMarking] (Incremental marking task: finalize incremental marking).
[IncrementalMarking] Finalize incrementally round 0, spent 0 ms, marking progress 0.

In the marking phase objects can be in three possible states
White - The GC has not found this one yet
Grey - The GC has found this one but has not looked at its neighboring objects. In other words it is yet to confirm whether this object is being referenced by any of its neighboring objects
Black - GC has found this object and has looked at all its neighbors. These have been fully processed.

[IncrementalMarking] Black allocation started
[IncrementalMarking] Stopping.
[IncrementalMarking] Black allocation finished

Old space is filling up. Based on heuristics, V8 understands that a scavenge will not work so triggers more of the mark-sweep events. Hence the reason - [scavenge might not succeed]
In this marking event notice that it is from the start of the marking event which started after the 7223ms scavenge event and not from the last GC event as was the case previously. In this case it also specifies that the longest step was 0.4ms.

[35841:0x103000000] 12800 ms: Mark-sweep 12.8 (20.0) -> 12.6 (20.0) MB, 6.2 / 0.0 ms (+ 13.7 ms in 69 steps since start of marking, biggest step 0.4 ms) [allocation failure] [scavenge might not succeed].

Object size is now at 16.9 MB. Remember that the max old space is 20MB so we are close to running out. Notice also that the duration of each Mark-sweep event has gone up. From 2.4ms at 7223ms to 17.8ms at 18455ms.

[35841:0x103000000] 13313 ms: Mark-sweep 13.2 (20.0) -> 13.2 (21.0) MB, 11.8 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 13830 ms: Mark-sweep 13.6 (21.0) -> 13.6 (21.0) MB, 12.2 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 14849 ms: Mark-sweep 14.2 (21.0) -> 14.0 (22.0) MB, 12.1 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 15366 ms: Mark-sweep 14.3 (22.0) -> 14.3 (22.0) MB, 12.3 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 15883 ms: Mark-sweep 14.9 (22.0) -> 14.9 (23.0) MB, 12.4 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 16399 ms: Mark-sweep 15.3 (23.0) -> 15.3 (24.0) MB, 11.7 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 17417 ms: Mark-sweep 15.9 (24.0) -> 15.9 (24.0) MB, 12.2 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 17933 ms: Mark-sweep 16.3 (24.0) -> 16.3 (24.0) MB, 12.9 / 0.0 ms [allocation failure] [scavenge might not succeed].
[35841:0x103000000] 18455 ms: Mark-sweep 16.9 (24.0) -> 16.9 (24.0) MB, 17.8 / 0.0 ms [allocation failure] [scavenge might not succeed].
last resort and the system runs out of space

16399 ms: Mark-sweep 15.3 (23.0) -> 15.3 (24.0) MB, 11.7 / 0.0 ms [allocation failure] [scavenge might not succeed].
17417 ms: Mark-sweep 15.9 (24.0) -> 15.9 (24.0) MB, 12.2 / 0.0 ms [allocation failure] [scavenge might not succeed].
17933 ms: Mark-sweep 16.3 (24.0) -> 16.3 (24.0) MB, 12.9 / 0.0 ms [allocation failure] [scavenge might not succeed].
18455 ms: Mark-sweep 16.9 (24.0) -> 16.9 (24.0) MB, 17.8 / 0.0 ms [allocation failure] [scavenge might not succeed].

Cannot get stack trace in GC.
FATAL ERROR: MarkCompactCollector: semi-space copy, fallback in old gen Allocation failed - JavaScript heap out of memory

To summarize:

  1. First came the scavenge event. No data is being freed so all data is promoted to the old space.
  2. Data keeps being promoted at a high rate which pushes V8 to trigger the incremental marker to prepare for a possible sweep event.
  3. As no data is being freed, all data objects are live the mark-sweep event has no effect.
  4. Eventually the system runs out of memory.

This was an extreme example to show the various GC events. Let us now consider a more saner example. In this example we actually free up memory to see how the sweeping action works. For every tenth iteration the array ‘c’ is emptied.

/*
Example - 2
Run with: node -trace_gc --trace_incremental_marking --max_semi_space_size=1 --max_old_space_size=20 example-2.js
reset when 10,000,000 bytes have been accumulated
*/

"use strict";

const a = {b: {c: []}};

let i = 0;

function aString (s) {
let text = '';
for (let i = 0; i < 10000; i++) {

//string of 100 characters
text += 'Lorem Ipsum is simply dummy text of the printing and typesetting industry. Lorem Ipsum has been the ';
}
s.push(text);
}

setInterval(function () {
aString(a.b.c);

//reset when 10,000,000 bytes have been pushed into the array
if (i === 10) {
i = 0;
a.b.c = [];
}

i++;

}, 500);

We will use the same command line parameters as before:

node -trace_gc -trace_gc_verbose –trace_incremental_marking  –max_semi_space_size=1  –max_old_space_size=20 example-2.js

In the trace below I have removed some of the traces to improve clarity.

node -trace_gc --trace_incremental_marking --max_semi_space_size=1 --max_old_space_size=20 example-2.js

V8 initialization - we ignore this
[40225:0x103000000] 20 ms: Scavenge 2.1 (6.0) -> 2.1 (7.0) MB, 0.7 / 0.0 ms [allocation failure].
[40225:0x103000000] 21 ms: Scavenge 2.1 (7.0) -> 2.1 (8.0) MB, 0.7 / 0.0 ms [allocation failure].

Scavenge events. All data promoted as no space is available in new space
[40225:0x103000000] 562 ms: Scavenge 4.0 (11.0) -> 3.6 (11.0) MB, 0.8 / 0.0 ms [allocation failure].
----more scavenges--------
[40225:0x103000000] 7144 ms: Scavenge 8.8 (16.0) -> 8.8 (16.0) MB, 2.2 / 0.0 ms [allocation failure].

Marking started in preparation for a sweep GC event.
[IncrementalMarking] Start (GC epilogue)
[IncrementalMarking] Start marking
[IncrementalMarking] Running

Marking and scavenges are interspersed
[IncrementalMarking] Scavenge during marking.

All data promoted, marking speed increased to keep up promoted data inflow
[40225:0x103000000] Increasing marking speed to 3 due to high promotion rate
Marking and Scavenge happen concurrently.
[40225:0x103000000] 8155 ms: Scavenge 9.4 (16.0) -> 9.4 (17.0) MB, 2.3 / 0.0 ms (+ 1.0 ms in 8 steps since last GC) [allocation failure].

----more marking and scavenges--------
[40225:0x103000000] 10690 ms: Scavenge 11.4 (18.0) -> 11.4 (19.0) MB, 2.3 / 0.0 ms (+ 1.6 ms in 9 steps since last GC) [allocation failure].
[IncrementalMarking] requesting finalization of incremental marking.
[IncrementalMarking] Black allocation finished

Marking complete and a sweep triggered. Size of objects reduced from 11.7MB to 7.7MB in 2.9 ms. V8 does lazy sweeping, that is,
enough sweeping(cleanup) as it can in the given amount of time so as not to hold up the application.
[40225:0x103000000] 11197 ms: Mark-sweep 11.7 (19.0) -> 7.7 (19.0) MB, 2.9 / 0.0 ms (+ 8.2 ms in 46 steps since start of marking,
biggest step 0.4 ms) [GC interrupt] [GC in old space requested].
Back to scavenges, only promotions. Note the increase in object size
[40225:0x103000000] 11702 ms: Scavenge 8.3 (19.0) -> 8.3 (19.0) MB, 1.6 / 0.0 ms [allocation failure].

----more scavenges--------
[40225:0x103000000] 17247 ms: Scavenge 12.3 (19.0) -> 12.3 (20.0) MB, 1.5 / 0.0 ms [allocation failure].
Second mark-sweep event is triggered. Size of objects reduced from 12.6MB to 5.0MB by lazy sweeping in 5.9 ms.
Time increased compared to last sweep as more memory is swept. In a real live application 5.9ms is very high.
During this time the application has paused.
[40225:0x103000000] 17758 ms: Mark-sweep 12.6 (20.0) -> 5.0 (18.0) MB, 5.9 / 0.0 ms [allocation failure] [scavenge might not succeed].

Back to scavenges. Size of objects increased from 5.6MB to 11.5MB
[40225:0x103000000] 18263 ms: Scavenge 5.6 (18.0) -> 5.6 (18.0) MB, 1.6 / 0.0 ms [allocation failure].

----more scavenges here-----
[40225:0x103000000] 26335 ms: Scavenge 11.5 (19.0) -> 11.5 (19.0) MB, 1.9 / 0.0 ms [allocation failure].
Marking started in preparation for another mark-sweep GC
[IncrementalMarking] Start (idle)
[IncrementalMarking] Start sweeping.
[IncrementalMarking] Start marking
[IncrementalMarking] Running

Compared to the previous marking cycle above the reason for speeding up marking is different - "because of low space left"
[40225:0x103000000] Speed up marking because of low space left
[40225:0x103000000] Marking speed increased to 3
[IncrementalMarking] Scavenge during marking.

GC's desperation continues, progressively increasing the marking speed
[40225:0x103000000] Speed up marking because of low space left
[40225:0x103000000] Marking speed increased to 6
----more marking--------
[IncrementalMarking] (GC interrupt: finalize incremental marking).
[IncrementalMarking] Finalize incrementally round 0, spent 0 ms, marking progress 1.
[IncrementalMarking] Complete (normal).
[40225:0x103000000] Speed up marking because of low space left
[40225:0x103000000] Postponing speeding up marking until marking starts
[IncrementalMarking] Stopping.

Making done. mark-sweep is triggered, lazy sweeping now… object size 12.3 => 4.7 in 3.0ms
[40225:0x103000000] 27352 ms: Mark-sweep 12.3 (19.0) -> 4.7 (18.0) MB, 3.0 / 0.0 ms (+ 4.2 ms in 8 steps since start of marking,
biggest step 1.4 ms) [GC interrupt] [GC in old space requested].

Cycle continues
[40225:0x103000000] 27860 ms: Scavenge 5.2 (18.0) -> 5.2 (19.0) MB, 2.7 / 0.0 ms [allocation failure].
[40225:0x103000000] 28364 ms: Scavenge 5.7 (19.0) -> 5.7 (19.0) MB, 1.9 / 0.0 ms [allocation failure].

By now the typical GC cycle must be apparent in this case.

  1. V8 initialization
  2. Starts with Scavenge in the new space. Data gets promoted to old space
  3. As the promoted data increases, V8 starts up the incremental marker
  4. Marking in the old space is intersped with the Scavenge events
  5. Marking completes and triggers the sweeper(mark-sweep)
  6. The Lazy sweeper runs for a small time duration to free up memory.  

The idea is not to dig too deep into these traces but to get an overview of how your app is performing with one important thing in mind. During a GC event the application is blocked. It cannot process any request till the GC is over.

If in the above example we were to reset every 100,000 bytes there would few, if any, mark-sweep events as everything would be done in the new space. No data would be promoted. As scavenges are fast the pauses would be very short. By the same token you can also set the size of the new space to allow for more scavenges. Given this knowledge you now have a way to check if your app is leaking and/or non performant. In my next post I will provide more realistic examples.

Advertisements

Does my NodeJS application leak memory? – 4

The heap, garbage collection and scavenges

In the last post I discussed the heap, dead and live objects and the object graph. Recapping…

Most of the allocations required by an application happen on the heap. The stack only contains SMIs (immediate 31-bit integers). This could be data or pointer to data on the heap. As functions execute, V8 cleans up the dead memory regions that have been abandoned by the stack. This cleanup event(A.K.A garbage collection) is triggered at intervals determined by V8. One such point is when V8 detects that it will soon run out of heap memory. The V8 subsystem that performs garbage collection is called the garbage collector. V8, like most JavaScript engines has a built in “garbage collector”.

V8 uses an extremely simple technique for garbage collection. In this it scans the stack for any references(handles) which are active(live) and considers the referenced objects live. The rest of the heap is considered garbage(dead) and is marked to be reclaimed for re-use.

One of the problems we face is that V8 is single threaded. When garbage collection happens the rest of the program stops. This is why it is called “stop the world” garbage collector. This has performance implications because if the execution of the program is held up for long it may result in sluggish behavior. From a UI standpoint this may result in browser rendering to be less than 60 fps resulting in the user experience being less than optimal. More information on this sluggishness in browser rendering, also called “Jank” can be found here.

Collection types and cycles

If you think about it, most of the allocations we request are localized to the executing function. In comparison the allocations that require to be alive across multiple function calls(e.g. globals) are fewer. For this reason V8 uses a “Generational” garbage collection system where the lifetime of the objects determine their placement in the heap. In this the heap is divided into two major lifetime sections or generations. The new and the old generation(or space). The new space holds objects that are short lived while the old space holds objects that are intended to be around for a longer period of time.

This is how it works. Most objects(if they are not too big) start their life in the new space(young generation). When memory is required, V8 quickly scans the new space for any live objects and considers the rest of the objects as dead and re-usable. This quick scan and cleanup is called a scavenge(minor collection cycle) and usually lasts less than a millisecond.

If an object survives two scavenge cycles it is considered “old” and moved(promoted) to the old space. At some point when V8 determines that it may need more memory in the old space it triggers a major garbage collection cycle(mark-sweep and mark compact) and removes dead objects from the old space.

One consequence of garbage collection is memory fragmentation. Dead and live objects are intermixed in the heap. If there are many of these pockets of free memory(space occupied by dead objects it would make allocation of new memory slow as objects would have to be split  up for storage. To fix this the garbage collector moves objects around and lays them out in a contiguous memory space. This process is called “memory compaction”.

Spaces in the Heap

To understand both the minor(scavenge) and major(mark-sweep and mark-compact) cycle, it is helpful to visualize how the heap is divided in to spaces and their functions. The heap is divided into multiple sections or spaces. The spaces that are relevant to us are shown in Figure 4.1. below which provides a pictorial representation.

Spaces in the heap

Briefly, here is what each space does:

  • New space: Short lived objects allocated here. Scavenge works in this space
  • Old Space = Old data space + Old pointer space: Promoted objects from new space and other raw data objects and pointers respectively. Mark-sweep and mark-compact work in this space.
  • Code space: Executable instructions
  • Other miscellaneous spaces: These include the Cell space, property cell space and map space and they contain specialized data and pointers. No garbage collection takes place here.

Within  these spaces we will concern ourselves only with the new space and the old space. Let’s look at scavenges and the new space first.

Scavenges

Consider this simple example(Figure 4.2) in which a string of 100,000 bytes  in length is created and stored in the local variable text. The setInterval timer runs the aString function every 200ms till the program is aborted .

Figure 4.2

It is clear that there should not be any memory growth, because every time the function returns the variable “text” goes out of scope and is discarded. The program does not have any practical application but works well for learning about scavenges. Running this piece of code with the trace_gc option in the terminal we get the output in figure 4.3.

Log

The dissected trace(the one in bold) is shown below in figure 4.4.

 

Trace Dissected

This is the simplest of the gc traces that V8 offers. It gives an excellent overview of memory allocation. This is also the first trace I run to check on how memory allocation is doing.  The explanations given in the figure for the dissected trace are self explanatory.

Analyzing the above trace:

  • It is a scavenge event, triggered as a result of allocation failure. In other words V8 ran out of memory in the new space and decided to reclaim dead space.
  • Each gc event is less then 1.0 ms. This is ok. If this time tends to increase then there is a possibility of a leak. It means that V8 is finding it hard to gc.
  • The difference in size of before and after objects which is about 1MB remains fairly constant.
  • The before and after overall memory size(41.1MB) remains fairly constant. This indicates that all of the dead space is being cleaned up. If it did not, then this would be another indication of a leak. In real applications it is not this ideal and some variation should be expected.

Continuing with the analysis let us assume that the new space is 1MB in size and that it is only used for text. Visualizing at a very simplistic level:

  1. For a 1MB sized new space the start and end of new space in the heap would be between 0 and 1048575 bytes
  2. Initially the pointer is at 0th byte.
  3. Allocation is requested for 100,000 bytes
  4. The pointer moves 100,000 bytes from 0 to 99999 bytes. The pointer is at the 100000th  position waiting for the next allocation.
  5. After the 10th allocation the pointer is at 1000000th position
  6. For the 11th allocation there is no memory left so a GC is triggered
  7. When allocation is requested for the text variable (11th allocation) V8 finds that there is no memory left in the new space.
  8. V8 reaches out to the stack and finds that there are no live objects. This means all of the new space contains dead objects and can be re-used.

Please keep in mind that V8 uses a variety of techniques to trigger a GC. Also, it tends to manipulate the size of new space depending on current conditions. This is the reason why the trigger points are never the same. It is the trend that is important and not the exactness of the values.

V8’s scavenge is based on Cheney’s algorithm. In this, the new space is divided into two semi-spaces, the to-space and from-space. There are five steps  that the garbage collector goes through to GC.

  1. Memory allocation starts in the to-space
  2. Once the to-space is out of memory a GC event is triggered
  3. To and from spaces are swapped out. At this point to-space is empty and from-space is full.
  4. Live objects are copied from from-space to to-space, laying them next to each other in contiguous memory locations. This also compacts the memory. from-space now only contains dead objects while to-space contains only live objects.

Note: Live objects are in blue, while the dead objects are in gray.

from-space is now fully reclaimed and can be reused and the cycle continues. For a pictorial representation see figure 4.5 below.

 

Cheyney's Alogorithm

We used a simple example to displayed the V8 GC trace and further dissected it to see how scavenges work. No special tools were used. As such, you can start using it with your existing projects. I will talk about Mark sweep and mark compact next time.

References:

  1. A tour of V8: Garbage Collection (An excellent series of blog posts on GC by Jay Conrod)
  2. An excellent collection of references on V8 performance by Thorsten Lorenz

Does my NodeJS application leak memory? – 3

The heap, objects dead or live?

In the last post I discussed the stack. To quickly recap, the stack is LIFO which is fast and managed automatically. It is small in size and stores only local variables(immediate small integers). Everything else is stored on the heap.

The heap, compared to the stack is bigger in size, more freeform in nature and stores reference types such as objects and strings. Variables that have to span function calls, including globals and variables captured by closures are also stored here.

The heap is dynamically allocated by the OS. It is self managed, that is, the running program(in this case V8)  makes requests from the OS for allocation and de-allocation. It is divided into multiple sections or spaces. The spaces that are relevant to us are the New Space, Old space, Code space, Map Space, Large object space. More on this when I talk about garbage collection. However for now it is extremely important to understand how the stack and the heap interact when a function or an application is executing.

A heap can be imagined as a network of interconnected objects. Consider the example we used in the previous post drawn a little differently.

leaks-post.010
Figure 3.1

In the above figure(3.1):

  1. aSmallInt is a SMI (immediate 31-bit integer) stored on the stack.
  2. aFloat is a number object so a reference(a handle in V8 speak) is stored on the stack with the number object on the heap.
  3. anObject is a literal object. Reference to this object is stored on the stack while the object itself is stored on the heap. The object is split up into three other string objects one each for a country code.

We can draw this in a different way:

leaks-post.011
Figure 3.2

This is a very simplistic rendering of an object graph. The local handles (or references) point to the objects on the heap. The fact that the heap is a network of interconnected objects becomes clear with an object graph.

As long as the parameters of the function test exists on the stack, its handles(references) exist and so do the objects on the heap. The objects in the heap are called live objects. Once the function ends  (returns) both the handles go out of scope and the objects in the heap are now considered dead. V8 can now reclaim the memory area used up by these objects. Understanding  dead and live objects is important for visualizing how the code affects garbage collection.

Objects, Dead or Live?

An object is considered live if it is being referenced by some chain of pointers to a root object or another live object. I will discuss two examples to illustrate this.

Simple Example

Consider the following simple snippet. The function  getCountryCode returns the countryCode if one is found or otherwise an empty string:

var countryCodes = {no: &amp;amp;amp;amp;quot;+47&amp;amp;amp;amp;quot;, us: &amp;amp;amp;amp;quot;+1&amp;amp;amp;amp;quot;, uk: &amp;amp;amp;amp;quot;+44&amp;amp;amp;amp;quot;};
var cc = '';

function getCountryCode(countryAbbreviation) {
    var ret = null;

    if (countryAbbreviation in countryCodes) {
       ret = countryCodes[countryAbbreviation];
    }

    return ret;
}

cc = getCountryCode('no');

 

In this code snippet:

  • The literal object countryCodes is global.
  • cc, the variable which will hold the results is initialized with an empty string and is a global.
  • countryAbbreviation is a local variable and a string.
  • ret, the return variable is also a local variable and a string.

1. Before getCountryCode is run the graph looks like in the following figure(3.4).  Note that both the global variables, cc and countryCodes are stored in the heap pointed to by global handles.

 

leaks-post.013
Figure 3.4

 

2. Before the functions ends, that is before getCountryCode returns, here is how the object graph looks (figure 3.5). Now there are two local variables. Both are string objects and stored on the heap pointed to by local handles.

leaks-post.014
Figure 3.5

 

 

3. Once the function ends(returns) the graph looks like in figure 3.6. As the function has ended, both ret and countryAbbreviation string objects have lost their references and now can be cleaned up by the garbage collector as these objects are dead. On the other hand both the global variables cc and countryCodes remain alive and the garbage collector will not touch them.

leaks-post.015
Figure 3.6

 

In summary:

  1. On entering the module, countryCodes object and cc which are global variables are allocated space on the heap. Both the globals are considered as root objects. The stack is empty at this point.
  2. On entering getCountryCode, ret and countryAbbreviation, both local variables (not small integers) are stored on the heap with the references on the stack. Both the local variables are considered root objects. They are also live objects as they can be accessed within the function scope. In other words they are live for the entire execution of the function.
  3. When the function returns, the global variable cc contains the value of 47, the country code for Norway.
  4. Both ret and countryAbbreviation go out of scope, are popped from the stack and discarded.
  5. The references to the heap for ret and countryAbbreviation are removed. Both ret and countryAbbreviation in the heap are considered dead.
  6. Both globals are still live as they can be used again till the program terminates.

 

Example with a Closure

Now consider the same example but in a form of a closure in which processCountryCodes returns a reference to the inner function getCountryCode. Please note that the variable getCountryCode to which the function is assigned is redundant and used here for clarity. I could have easily returned the function itself directly.

var cc, code;

function processCountryCodes() {
    var countryCodes = {no: &amp;amp;amp;amp;quot;+47&amp;amp;amp;amp;quot;, usa: &amp;amp;amp;amp;quot;+1&amp;amp;amp;amp;quot;, uk: &amp;amp;amp;amp;quot;+44&amp;amp;amp;amp;quot;};
    var getCountryCode = function (countryAbbreviation) {
        var ret = null;

        if (countryAbbreviation in countryCodes) {
            ret = countryCodes[countryAbbreviation];
        }
        return ret;
    };

    return getCountryCode;
}

cc = processCountryCodes();
code = cc('no');
console.log(code);//+47

1. Before the function processCountryCodes is run the object graph looks like in the figure(3.8) below. Both global variables are allocated space on the heap. They are referenced via global handles. Simple enough.

Figure 3.8
Figure 3.8

 

2. Before the function processCountryCodes returns the object graph looks like in the following figure 3.9:

Figure 3.9
Figure 3.9

The inner function getCountryCode is a closure and closes over the object countryCodes. In other words before processCountryCodes returns it needs to save a reference to the countryCodes object. This is because once processCountryCodes returns, the stack will be wiped clean. To retain the reference V8 automatically creates an internal object called the “Context object” which is an instance of the JSFunction class and adds the countryCodes object to it as a property. For the same reason V8 also allocates space for the inner function in the heap. Please remember that V8 creates the context object when it enters the outer function processCountryCodes.

3. Before the function processCountryCodes returns the object graph looks like in the figure 3.10. The global variable cc now holds a reference to the inner function getCountryCode.

Figure 3.10
Figure 3.10

 

4. On execution of the inner function the graph looks like in the figure 3.11 The global variable cc now holds a reference to the inner function getCountryCode. Global variable code now contains the result “+47”.

Figure 3.11
Figure 3.11

 

Please note that I have not included the objects for the inner function because that is the same as the earlier example.

In summary:

  1. On entering the module, cc and code which are globals are allocated space on the heap. The stack is empty at this point. cc and code are now considered live root objects.
  2. On entering processCountryCodes V8 builds a special “Context” object on the heap and adds the countryCodes object as a property to it.
  3. Before processCountryCodes returns, the local variable now holds a reference to the inner function which is allocated space on the heap
  4. Once processCountryCodes returns, global variable cc holds the reference to the inner function.
  5. Global variable holds the result “+47” once the inner function is executed via the global variable cc.

The key point here to note is that even though both processCountryCodes and getCountryCode have been executed the heap structure remains intact. The reason is that both the global variables will keep holding references to the objects in the heap till the program terminates.

I hope that you now have the necessary tools to visualize your code in terms of an object graph. In the next post I will talk about Garbage collection as it relates to the heap and build on the information in this post.

 

Does my NodeJS application leak memory? – 1

A Gentle Introduction

A journey of a thousand miles begins with a single step – Lao Tzu

One of the key requirements for writing software for emergency management is consistent performance. Every time user feedback and/or testing reveals performance issues, the question that always comes to my mind is whether the application is leaking memory or if is it something else. The last thing an emergency software developer wants to hear is that the alerts did not get to the recipients in time or that emergency personnel experienced sluggish performance.

Simply put, a memory leak is when an application can no longer efficiently manage its memory resources resulting either in a crash or sluggish performance. Putting it differently, a memory leak occurs when freed memory is not reclaimed for reuse. Depending on the size and frequency of leak an application could either crash or behave erratically. While all platforms and programming languages are susceptible to memory leaks, I will be restricting my scope to NodeJS/V8.

Memory leaks in the front end (or client) code can go unnoticed for a long time or may never be detected. This is because the user could shut down the browser or refresh the page before a potential memory leak causes a problem. This is not the case when you are writing backend server real time applications for messaging, authentication and Internet of Things. A server issue affects all its clients not just one user. It is not practical to restart the server every time there is an issue. 

The go to response of a developer is to scour the internet and typically end up examining heap dumps or watching the growth of memory. If one has not understood the theory behind memory leaks and garbage collection this exercise usually results in frustration. For example, just pure memory growth for some period of time does not necessarily mean that there is a leak.

I went through the same frustrations  like most of my fellow developers and decided that I had to find a simpler way to check for leaks. This was very important to me as all my work relates to developing NodeJS backend server apps.

One of the things we tend to ignore is the power of the logs. Both in terms of analyzing them and of implementing them in our code. Depending on the type of log, the vitals of the server app can be provided in realtime. This can provide warning of an upcoming problem, be it leak or a security threat.

There are a ton of log analysis and management tools, including monitoring tools available, but that creates a learning curve for a specific product which may not be available in the near future. Many also do not fit the budget of a small startup. Many free open source tools tend to have difficulty in keeping up with the evolution of NodeJS/V8.

In my quest to find something that was not dependent of any external product or that required code modification, I decided to stick with understanding the garbage collection trace events of V8/NodeJS. My journey took me through analyzing the V8 source code, thousands of lines of garbage collection traces, including a quick detour into the world of Linux internals.

In the series of posts that follow I will describe my journey on how I use the V8 logs to look for leaks starting with some basic information on memory management