Performance regression with libxmljs

[sluukkonen]

• Version: 12.x, 13.x
• Platform: macOS, Linux
• Subsystem: gc

Not sure if this is an issue with node or libxmljs (which wraps the libxml2 library), but anyhow, here's a reduced test case of behavior I've observed. All test have been run on a Macbook Pro running macOS Catalina.

const libxml = require("libxmljs2");

const xml =
  '<?xml version="1.0" encoding="utf-8" ?>' +
  "<root>" +
  new Array(10000)
    .fill()
    .map(() => "<element />")
    .join() +
  "</root>";

while (true) {
  libxml.parseXml(xml);
}

If I run this script on Node 11.15.0, 10.16.3 or 8.16.1 (with --trace-gc enabled), everything works as expected. Mark-sweep operations take approximately 10 milliseconds each.

$ node --trace-gc test.js
[55391:0x102849000]      521 ms: Mark-sweep 5.5 (11.2) -> 4.2 (11.2) MB, 94.0 / 92.9 ms  (+ 11.1 ms in 40042 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 120 ms) (average mu = 1.000, current mu = 1.000) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]      774 ms: Mark-sweep 4.2 (11.2) -> 4.1 (11.2) MB, 104.8 / 104.0 ms  (+ 11.0 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 131 ms) (average mu = 0.578, current mu = 0.578) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     1056 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 117.4 / 116.9 ms  (+ 11.9 ms in 40036 steps since start of marking, biggest step 1.5 ms, walltime since start of marking 147 ms) (average mu = 0.579, current mu = 0.579) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     1302 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 96.1 / 95.6 ms  (+ 11.4 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 123 ms) (average mu = 0.590, current mu = 0.602) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     1562 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 95.8 / 95.1 ms  (+ 13.1 ms in 40036 steps since start of marking, biggest step 2.2 ms, walltime since start of marking 127 ms) (average mu = 0.606, current mu = 0.623) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     1803 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 93.0 / 92.7 ms  (+ 10.7 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 119 ms) (average mu = 0.607, current mu = 0.608) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     2044 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 93.2 / 92.8 ms  (+ 11.2 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 119 ms) (average mu = 0.606, current mu = 0.604) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     2280 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 91.8 / 91.4 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 118 ms) (average mu = 0.606, current mu = 0.605) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     2521 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 93.7 / 93.4 ms  (+ 11.0 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 120 ms) (average mu = 0.604, current mu = 0.603) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     2756 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 93.1 / 92.7 ms  (+ 11.0 ms in 40036 steps since start of marking, biggest step 1.9 ms, walltime since start of marking 119 ms) (average mu = 0.600, current mu = 0.597) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     3003 ms: Mark-sweep 4.1 (11.2) -> 4.1 (11.2) MB, 95.9 / 95.4 ms  (+ 11.1 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 122 ms) (average mu = 0.602, current mu = 0.604) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     3243 ms: Mark-sweep 4.1 (11.2) -> 4.1 (8.2) MB, 93.7 / 93.2 ms  (+ 11.2 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 120 ms) (average mu = 0.602, current mu = 0.601) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     3481 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.5 / 93.0 ms  (+ 11.1 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 120 ms) (average mu = 0.601, current mu = 0.600) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     3716 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.3 / 90.9 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 117 ms) (average mu = 0.602, current mu = 0.604) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     3951 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.3 / 92.8 ms  (+ 11.3 ms in 40036 steps since start of marking, biggest step 2.0 ms, walltime since start of marking 120 ms) (average mu = 0.599, current mu = 0.595) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     4186 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.9 / 91.4 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 118 ms) (average mu = 0.600, current mu = 0.601) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     4419 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.7 / 91.3 ms  (+ 11.2 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 118 ms) (average mu = 0.599, current mu = 0.598) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     4655 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.3 / 92.8 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 119 ms) (average mu = 0.598, current mu = 0.597) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     4889 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.4 / 93.0 ms  (+ 11.0 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 120 ms) (average mu = 0.596, current mu = 0.595) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     5129 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.0 / 91.6 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 118 ms) (average mu = 0.603, current mu = 0.609) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     5375 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 96.1 / 95.5 ms  (+ 12.6 ms in 40036 steps since start of marking, biggest step 2.9 ms, walltime since start of marking 125 ms) (average mu = 0.600, current mu = 0.597) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     5623 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 96.0 / 95.5 ms  (+ 11.9 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 125 ms) (average mu = 0.603, current mu = 0.606) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     5865 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 89.9 / 89.5 ms  (+ 12.3 ms in 40036 steps since start of marking, biggest step 2.2 ms, walltime since start of marking 118 ms) (average mu = 0.612, current mu = 0.621) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     6103 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.3 / 91.9 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 118 ms) (average mu = 0.608, current mu = 0.604) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     6342 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 96.8 / 96.4 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 123 ms) (average mu = 0.597, current mu = 0.587) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     6575 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.0 / 90.6 ms  (+ 10.7 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 116 ms) (average mu = 0.600, current mu = 0.602) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     6810 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 94.1 / 93.7 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 120 ms) (average mu = 0.596, current mu = 0.593) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     7045 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.8 / 91.3 ms  (+ 11.7 ms in 40036 steps since start of marking, biggest step 2.0 ms, walltime since start of marking 120 ms) (average mu = 0.599, current mu = 0.601) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     7280 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.5 / 92.0 ms  (+ 11.0 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 119 ms) (average mu = 0.598, current mu = 0.598) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     7517 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 95.5 / 95.0 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 121 ms) (average mu = 0.594, current mu = 0.590) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     7752 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.6 / 93.2 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 119 ms) (average mu = 0.595, current mu = 0.596) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     7987 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.1 / 92.7 ms  (+ 10.7 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 118 ms) (average mu = 0.596, current mu = 0.596) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     8220 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.6 / 92.1 ms  (+ 11.2 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 118 ms) (average mu = 0.595, current mu = 0.595) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     8457 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 94.6 / 94.2 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 120 ms) (average mu = 0.595, current mu = 0.594) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     8691 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.2 / 91.8 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 118 ms) (average mu = 0.596, current mu = 0.598) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     8926 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 94.3 / 93.9 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 120 ms) (average mu = 0.594, current mu = 0.591) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     9165 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.2 / 92.8 ms  (+ 11.1 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 120 ms) (average mu = 0.599, current mu = 0.603) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     9401 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.7 / 92.2 ms  (+ 11.1 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 119 ms) (average mu = 0.599, current mu = 0.600) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     9638 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 96.7 / 96.2 ms  (+ 11.2 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 123 ms) (average mu = 0.592, current mu = 0.585) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]     9873 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.2 / 92.8 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 119 ms) (average mu = 0.594, current mu = 0.596) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    10107 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.1 / 91.7 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 118 ms) (average mu = 0.596, current mu = 0.598) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    10339 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.4 / 91.0 ms  (+ 11.1 ms in 40036 steps since start of marking, biggest step 1.9 ms, walltime since start of marking 117 ms) (average mu = 0.597, current mu = 0.599) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    10575 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 94.3 / 93.9 ms  (+ 11.1 ms in 40036 steps since start of marking, biggest step 2.0 ms, walltime since start of marking 120 ms) (average mu = 0.594, current mu = 0.592) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    10810 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.4 / 92.9 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 119 ms) (average mu = 0.594, current mu = 0.594) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    11047 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 90.7 / 90.2 ms  (+ 12.4 ms in 40036 steps since start of marking, biggest step 2.0 ms, walltime since start of marking 120 ms) (average mu = 0.602, current mu = 0.609) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    11282 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.0 / 92.6 ms  (+ 10.6 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 118 ms) (average mu = 0.600, current mu = 0.598) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    11518 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 94.6 / 94.1 ms  (+ 11.0 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 121 ms) (average mu = 0.596, current mu = 0.593) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    11752 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 93.5 / 93.0 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 119 ms) (average mu = 0.595, current mu = 0.593) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    11986 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.5 / 92.1 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 118 ms) (average mu = 0.596, current mu = 0.597) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    12217 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.2 / 90.8 ms  (+ 10.9 ms in 40036 steps since start of marking, biggest step 1.7 ms, walltime since start of marking 117 ms) (average mu = 0.597, current mu = 0.598) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    12448 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 91.3 / 91.0 ms  (+ 11.0 ms in 40036 steps since start of marking, biggest step 1.8 ms, walltime since start of marking 117 ms) (average mu = 0.597, current mu = 0.598) finalize incremental marking via stack guard GC in old space requested
[55391:0x102849000]    12681 ms: Mark-sweep 4.1 (8.2) -> 4.1 (8.2) MB, 92.6 / 92.2 ms  (+ 10.8 ms in 40036 steps since start of marking, biggest step 1.6 ms, walltime since start of marking 118 ms) (average mu = 0.596, current mu = 0.595) finalize incremental marking via stack guard GC in old space requested

On Node 12, the following behavior can be observed.

$ node --trace-gc test.js
[58317:0x1028c4000]       33 ms: Scavenge 2.3 (3.0) -> 1.9 (4.0) MB, 1.3 / 0.0 ms  (average mu = 1.000, current mu = 1.000) allocation failure 
[58317:0x1028c4000]       43 ms: Scavenge 2.4 (4.3) -> 2.2 (5.0) MB, 1.0 / 0.0 ms  (average mu = 1.000, current mu = 1.000) allocation failure 
[58317:0x1028c4000]    83077 ms: Mark-sweep 2.8 (5.0) -> 1.9 (4.0) MB, 112.7 / 110.1 ms  (+ 82707.5 ms in 24342 steps since start of marking, biggest step 7.4 ms, walltime since start of marking 82898 ms) (average mu = 1.000, current mu = 1.000) finalize incremental marking via stack guard GC in old space requested
[58317:0x1028c4000]   166046 ms: Mark-sweep 2.0 (4.0) -> 1.9 (4.3) MB, 97.4 / 96.2 ms  (+ 82685.5 ms in 24342 steps since start of marking, biggest step 4.4 ms, walltime since start of marking 82854 ms) (average mu = 0.999, current mu = 0.999) finalize incremental marking via stack guard GC in old space requested
[58317:0x1028c4000]   249031 ms: Mark-sweep 1.9 (4.3) -> 1.9 (4.3) MB, 101.0 / 100.6 ms  (+ 82687.1 ms in 24342 steps since start of marking, biggest step 5.6 ms, walltime since start of marking 82873 ms) (average mu = 0.999, current mu = 0.999) finalize incremental marking via stack guard GC in old space requested
[58317:0x1028c4000]   332024 ms: Mark-sweep 1.9 (4.3) -> 1.8 (4.3) MB, 110.2 / 109.7 ms  (+ 82684.6 ms in 24342 steps since start of marking, biggest step 4.5 ms, walltime since start of marking 82879 ms) (average mu = 0.999, current mu = 0.999) finalize incremental marking via stack guard GC in old space requested
[58317:0x1028c4000]   415008 ms: Mark-sweep 1.9 (4.3) -> 1.8 (4.3) MB, 108.5 / 108.1 ms  (+ 82683.3 ms in 24342 steps since start of marking, biggest step 4.5 ms, walltime since start of marking 82863 ms) (average mu = 0.999, current mu = 0.999) finalize incremental marking via stack guard GC in old space requested

The Mark-sweep operations now take over 80 second each and everything grinds to a halt. For what it's worth, I haven't been able to observe any memory leaks.

The time taken for each GC pause seems to be roughly proportional to the number of elements in the XML document.

Number of elements in the document	Average pause time
100	~950ms
1000	~8300ms
10000	~82000ms
100000	~1080000ms

I've tested and observed this on the following Node 12 versions: 12.0.0, 12.8.0 and 12.12.0.

Flame graphs captured with DTrace.

Node 12

Node 10

[sluukkonen]

I patched libxmljs2 to call Nan::AdjustExternalMemory less often (call it when the amount of allocated memory has changed by 1 MB or more), which seems to resolve the issue.

Seems that calling Nan::AdjustExternalMemory too often tanks performance on Node 12 and 13.