Linkerd: Non-heap Memory Leak on 1.3.1

We observed nearly all of our linkerd JVM processes using in excess of 4GB of RAM (RSS) after increasing the amount of traffic going to them, despite the heap limit being set to 1GB. The memory increase doesn’t appear to be caused by the most common non-heap JVM memory usage culprits (metaspace, etc).

Specifically, we increased the traffic to one of our h1 routers (bcapp-https-out) to be ~1K req/sec across the entire linkerd cluster.

We took two snapshots an hour apart on one of our problematic nodes, they are attached below.

metrics-non-heap.json (581.2 KB)
metrics-non-heap-2.json (581.3 KB)

Could this be a netty direct buffer memory leak? Any guidance would be appreciated.

Thanks for the report. We’ll take a look right away.

1 Like

A couple of thoughts so far:

  • This is the only HTTP 1 router we have using Netty 4 at the moment, as we’ve had the others in our environment hardcoded at Netty 3 for quite a while due to previous issues (I believe it was when there was ambiguity around maxChunkKB etc - I know Netty 3 goes away in 1.3, so we’re solving that right now). For now we’ve set one instance of this router back to Netty 3 to see if we’re seeing the memory leak there.
  • I don’t think we’re seeing the same CPU issues with the Consul namer that were fixed in 1.3, but it’s possible it’s manifesting in a different way (we don’t have that many Consul services and we aren’t burning CPU with linkerd)

We’re gonna sit on the Netty change for a bit and see what happens to memory usage.

Pulled a heap dump on a misbehaving node to check for any DirectByteBuffer instances. It looks like there’s only ~181MB of native memory used by those instances.

I don’t think we’ve ever seen a leak in non-heap memory before. Are you able to look at the loaded classes to see if class loading has gone out of control? Can you provide a memory dump?

@Alex here’s a jstat output from a node using almost 7GB of RSS:

# sudo -u linkerd jstat -gc 4416
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT
1088.0 1088.0 346.0   0.0    8704.0   2098.0   165520.0   106938.9  64332.0 58605.1 9548.0 9124.4 466354 1614.492 3216    35.899 1650.391

Metaspace Capacity (kB) = 106938
Metaspace Usage (kB) = 64332

# cat /proc/4416/status
Name:	java
Umask:	0022
State:	S (sleeping)
Tgid:	4416
Ngid:	0
Pid:	4416
PPid:	1
TracerPid:	0
Uid:	116	116	116	116
Gid:	124	124	124	124
FDSize:	2048
Groups:	124
NStgid:	4416
NSpid:	4416
NSpgid:	4416
NSsid:	4416
VmPeak:	26483992 kB
VmSize:	26418456 kB
VmLck:	       0 kB
VmPin:	       0 kB
VmHWM:	 6802952 kB
VmRSS:	 6802888 kB
RssAnon:	 6781704 kB
RssFile:	   21184 kB
RssShmem:	       0 kB
VmData:	 7571624 kB
VmStk:	     132 kB
VmExe:	       4 kB
VmLib:	   19116 kB
VmPTE:	   15544 kB
VmPMD:	     112 kB
VmSwap:	       0 kB
HugetlbPages:	       0 kB
Threads:	356
SigQ:	0/257175
SigPnd:	0000000000000000
ShdPnd:	0000000000000000
SigBlk:	0000000000000000
SigIgn:	0000000000000000
SigCgt:	2000000181005ccf
CapInh:	0000000000000000
CapPrm:	0000000000000000
CapEff:	0000000000000000
CapBnd:	0000003fffffffff
CapAmb:	0000000000000000
Seccomp:	0
Cpus_allowed:	ffffff,ffffffff
Cpus_allowed_list:	0-55
Mems_allowed:	00000000,00000003
Mems_allowed_list:	0-1
voluntary_ctxt_switches:	2
nonvoluntary_ctxt_switches:	2

Memory usage pattern also appears to be similar between netty3 and netty4 routers. Will continue to monitor.

This is pretty mysterious. Are you certain that it’s non-heap that’s growing? i.e. is it possible that the 1GB heap limit is somehow being ignored? What does a heap dump look like? Very strange that the nearly 7GB of RSS is not accounted for anywhere in jstat…

@Alex yeah, if you look at the jstat output I pasted above, it shows the capacity and usage in each of the GC tiers. A heap dump doesn’t contain anything out of the ordinary.

Here’s a reference for the column names:

S0C: Current survivor space 0 capacity (kB).
S1C: Current survivor space 1 capacity (kB).
S0U: Survivor space 0 utilization (kB).
S1U: Survivor space 1 utilization (kB).
EC: Current eden space capacity (kB).
EU: Eden space utilization (kB).
OC: Current old space capacity (kB).
OU: Old space utilization (kB).
MC: Metaspace capacity (kB).
MU: Metacspace utilization (kB).
CCSC: Compressed class space capacity (kB).
CCSU: Compressed class space used (kB).
YGC: Number of young generation garbage collection events.
YGCT: Young generation garbage collection time.
FGC: Number of full GC events.
FGCT: Full garbage collection time.
GCT: Total garbage collection time.

The memory usage does appear to be traffic dependent. After draining the containers off of a particular node, we observed the native memory usage flatten out:

I’ve also taken a Java Flight Recorder run from a linkerd process, I couldn’t find anything out of the ordinary (heap settings looked correct there).

We enabled NMT in production today on one of our nodes. The RSS usage hasn’t made it up to crazy levels yet (this was measured from 408M to 507M), but here’s a preliminary example of RSS rising 100MB without any corresponding rise in a memory level that the JVM is aware of.

*** RSS = 408M ***

Total: reserved=2755234KB +740KB, committed=676738KB +932KB

-                 Java Heap (reserved=1048576KB, committed=56360KB +192KB)
                            (mmap: reserved=1048576KB, committed=56360KB +192KB)

-                     Class (reserved=1105718KB +53KB, committed=65026KB +53KB)
                            (classes #9496)
                            (malloc=3894KB +53KB #16320 +147)
                            (mmap: reserved=1101824KB, committed=61132KB)

-                    Thread (reserved=360636KB +64KB, committed=360636KB +64KB)
                            (thread #350)
                            (stack: reserved=358772KB, committed=358772KB)
                            (malloc=1136KB #1796)
                            (arena=729KB +64 #698)

-                      Code (reserved=51434KB +67KB, committed=9054KB +67KB)
                            (malloc=1514KB +67KB #2919 +113)
                            (mmap: reserved=49920KB, committed=7540KB)

-                        GC (reserved=88510KB, committed=85302KB)
                            (malloc=85090KB #498 +2)
                            (mmap: reserved=3420KB, committed=212KB)

-                  Compiler (reserved=667KB +2KB, committed=667KB +2KB)
                            (malloc=538KB +2KB #850 +61)
                            (arena=130KB #2)

-                  Internal (reserved=40257KB +67KB, committed=40257KB +67KB)
                            (malloc=40225KB +67KB #21018 +4)
                            (mmap: reserved=32KB, committed=32KB)

-                    Symbol (reserved=12548KB, committed=12548KB)
                            (malloc=11133KB #88559 -2)
                            (arena=1415KB #1)

-    Native Memory Tracking (reserved=2119KB +5KB, committed=2119KB +5KB)
                            (malloc=38KB #418)
                            (tracking overhead=2081KB +5KB)

-               Arena Chunk (reserved=903KB +483KB, committed=903KB +483KB)
                            (malloc=903KB +483KB)

-                   Unknown (reserved=43864KB, committed=43864KB)
                            (mmap: reserved=43864KB, committed=43864KB)

*** RSS = 448M ***

Total: reserved=2756422KB +1928KB, committed=679638KB +3832KB

-                 Java Heap (reserved=1048576KB, committed=57872KB +1704KB)
                            (mmap: reserved=1048576KB, committed=57872KB +1704KB)

-                     Class (reserved=1105820KB +154KB, committed=65128KB +154KB)
                            (classes #9496)
                            (malloc=3996KB +154KB #16522 +349)
                            (mmap: reserved=1101824KB, committed=61132KB)

-                    Thread (reserved=360700KB +128KB, committed=360700KB +128KB)
                            (thread #350)
                            (stack: reserved=358772KB, committed=358772KB)
                            (malloc=1136KB #1796)
                            (arena=793KB +128 #698)

-                      Code (reserved=51464KB +96KB, committed=9280KB +292KB)
                            (malloc=1544KB +96KB #3025 +219)
                            (mmap: reserved=49920KB, committed=7736KB +196KB)

-                        GC (reserved=88510KB, committed=85306KB +4KB)
                            (malloc=85090KB #498 +2)
                            (mmap: reserved=3420KB, committed=216KB +4KB)

-                  Compiler (reserved=666KB +1KB, committed=666KB +1KB)
                            (malloc=537KB +1KB #812 +23)
                            (arena=130KB #2)

-                  Internal (reserved=40413KB +223KB, committed=40413KB +223KB)
                            (malloc=40381KB +223KB #21039 +25)
                            (mmap: reserved=32KB, committed=32KB)

-                    Symbol (reserved=12548KB, committed=12548KB)
                            (malloc=11134KB #88560 -1)
                            (arena=1415KB #1)

-    Native Memory Tracking (reserved=2124KB +10KB, committed=2124KB +10KB)
                            (malloc=38KB #418)
                            (tracking overhead=2086KB +10KB)

-               Arena Chunk (reserved=1737KB +1316KB, committed=1737KB +1316KB)
                            (malloc=1737KB +1316KB)

-                   Unknown (reserved=43864KB, committed=43864KB)
                            (mmap: reserved=43864KB, committed=43864KB)

*** RSS = 476M ***

Total: reserved=2756206KB +1712KB, committed=679742KB +3936KB

-                 Java Heap (reserved=1048576KB, committed=58124KB +1956KB)
                            (mmap: reserved=1048576KB, committed=58124KB +1956KB)

-                     Class (reserved=1105900KB +235KB, committed=65208KB +235KB)
                            (classes #9496)
                            (malloc=4076KB +235KB #16521 +348)
                            (mmap: reserved=1101824KB, committed=61132KB)

-                    Thread (reserved=360764KB +192KB, committed=360764KB +192KB)
                            (thread #350)
                            (stack: reserved=358772KB, committed=358772KB)
                            (malloc=1136KB #1796)
                            (arena=856KB +192 #698)

-                      Code (reserved=51450KB +82KB, committed=9330KB +342KB)
                            (malloc=1530KB +82KB #2962 +156)
                            (mmap: reserved=49920KB, committed=7800KB +260KB)

-                        GC (reserved=88510KB, committed=85310KB +8KB)
                            (malloc=85090KB #498 +2)
                            (mmap: reserved=3420KB, committed=220KB +8KB)

-                  Compiler (reserved=667KB +1KB, committed=667KB +1KB)
                            (malloc=537KB +1KB #829 +40)
                            (arena=130KB #2)

-                  Internal (reserved=40514KB +324KB, committed=40514KB +324KB)
                            (malloc=40482KB +324KB #21046 +32)
                            (mmap: reserved=32KB, committed=32KB)

-                    Symbol (reserved=12548KB, committed=12548KB)
                            (malloc=11134KB #88561)
                            (arena=1415KB #1)

-    Native Memory Tracking (reserved=2123KB +10KB, committed=2123KB +10KB)
                            (malloc=38KB #418)
                            (tracking overhead=2085KB +10KB)

-               Arena Chunk (reserved=1289KB +868KB, committed=1289KB +868KB)
                            (malloc=1289KB +868KB)

-                   Unknown (reserved=43864KB, committed=43864KB)
                            (mmap: reserved=43864KB, committed=43864KB)

*** RSS = 507M ***

Total: reserved=2755461KB +967KB, committed=679129KB +3323KB

-                 Java Heap (reserved=1048576KB, committed=58124KB +1956KB)
                            (mmap: reserved=1048576KB, committed=58124KB +1956KB)

-                     Class (reserved=1105982KB +317KB, committed=65290KB +317KB)
                            (classes #9496)
                            (malloc=4158KB +317KB #16662 +489)
                            (mmap: reserved=1101824KB, committed=61132KB)

-                    Thread (reserved=360828KB +256KB, committed=360828KB +256KB)
                            (thread #350)
                            (stack: reserved=358772KB, committed=358772KB)
                            (malloc=1136KB #1796)
                            (arena=920KB +256 #698)

-                      Code (reserved=51484KB +116KB, committed=9496KB +508KB)
                            (malloc=1564KB +116KB #2934 +128)
                            (mmap: reserved=49920KB, committed=7932KB +392KB)

-                        GC (reserved=88510KB, committed=85310KB +8KB)
                            (malloc=85090KB #498 +2)
                            (mmap: reserved=3420KB, committed=220KB +8KB)

-                  Compiler (reserved=668KB +2KB, committed=668KB +2KB)
                            (malloc=538KB +2KB #853 +64)
                            (arena=130KB #2)

-                  Internal (reserved=40679KB +489KB, committed=40679KB +489KB)
                            (malloc=40647KB +489KB #21055 +41)
                            (mmap: reserved=32KB, committed=32KB)

-                    Symbol (reserved=12548KB, committed=12548KB)
                            (malloc=11134KB #88563 +2)
                            (arena=1415KB #1)

-    Native Memory Tracking (reserved=2125KB +11KB, committed=2125KB +11KB)
                            (malloc=38KB #418)
                            (tracking overhead=2087KB +11KB)

-               Arena Chunk (reserved=197KB -224KB, committed=197KB -224KB)
                            (malloc=197KB -224KB)

-                   Unknown (reserved=43864KB, committed=43864KB)
                            (mmap: reserved=43864KB, committed=43864KB)

If the JVM is blind to the increasing memory, it might indicate that this is coming from some kind of JNI call or unclosed resource (e.g., native SSL or a Deflate/Gzip stream instance).

Let it run over night, the RSS is now up to 1.7GB. Here’s the latest NMT delta, can’t see what would be causing this.

Total: reserved=2830631KB +76138KB, committed=765903KB +90098KB

-                 Java Heap (reserved=1048576KB, committed=68020KB +11852KB)
                            (mmap: reserved=1048576KB, committed=68020KB +11852KB)

-                     Class (reserved=1106913KB +1248KB, committed=67373KB +2400KB)
                            (classes #9765 +269)
                            (malloc=5089KB +1248KB #18280 +2107)
                            (mmap: reserved=1101824KB, committed=62284KB +1152KB)

-                    Thread (reserved=366195KB +5622KB, committed=366195KB +5622KB)
                            (thread #353 +3)
                            (stack: reserved=361856KB +3084KB, committed=361856KB +3084KB)
                            (malloc=1146KB +10KB #1811 +15)
                            (arena=3193KB +2528 #704 +6)

-                      Code (reserved=51598KB +230KB, committed=10130KB +1142KB)
                            (malloc=1678KB +230KB #3005 +199)
                            (mmap: reserved=49920KB, committed=8452KB +912KB)

-                        GC (reserved=88511KB +1KB, committed=85347KB +45KB)
                            (malloc=85091KB +1KB #512 +16)
                            (mmap: reserved=3420KB, committed=256KB +44KB)

-                  Compiler (reserved=775KB +109KB, committed=775KB +109KB)
                            (malloc=645KB +109KB #963 +174)
                            (arena=130KB #2)

-                  Internal (reserved=107952KB +67762KB, committed=107952KB +67762KB)
                            (malloc=107920KB +67762KB #21734 +720)
                            (mmap: reserved=32KB, committed=32KB)

-                    Symbol (reserved=12714KB +165KB, committed=12714KB +165KB)
                            (malloc=11267KB +133KB #89773 +1212)
                            (arena=1447KB +32 #1)

-    Native Memory Tracking (reserved=2185KB +72KB, committed=2185KB +72KB)
                            (malloc=38KB #421 +3)
                            (tracking overhead=2147KB +71KB)

-               Arena Chunk (reserved=1349KB +928KB, committed=1349KB +928KB)
                            (malloc=1349KB +928KB)

-                   Unknown (reserved=43864KB, committed=43864KB)
                            (mmap: reserved=43864KB, committed=43864KB)

Minor updatE: there is a possibility this is related to https://github.com/netty/netty-tcnative/commit/88b5425c97cdb212988ccff5a45b7a617189f407. We believe that that fix went into Linkerd 1.3.0.

We’ve upgraded to 1.3.0 and the memory usage looks improved. We won’t know if the leak is fixed for another 24-48 hours though.

I’ll post an update when we find out.

We’re continuing to see a native memory leak, although not as severe. In addition, many linkerd instances are beginning to fail with this error:

Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: WARN 1101 11:59:32.962 CDT finagle/netty4-103: Failed to initialize a channel. Closing: [id: 0xda8ab2a4, L:/10.171.25.200:4143 - R:/10.173.96.206:36226]
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: io.netty.util.internal.OutOfDirectMemoryError: failed to allocate 1048576 byte(s) of direct memory (used: 1037041958, max: 1037959168)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.util.internal.PlatformDependent.incrementMemoryCounter(PlatformDependent.java:618)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.util.internal.PlatformDependent.allocateDirectNoCleaner(PlatformDependent.java:572)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.PoolArena$DirectArena.allocateDirect(PoolArena.java:764)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.PoolArena$DirectArena.newChunk(PoolArena.java:740)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.PoolArena.allocateNormal(PoolArena.java:244)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.PoolArena.allocate(PoolArena.java:226)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.PoolArena.allocate(PoolArena.java:146)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.PooledByteBufAllocator.newDirectBuffer(PooledByteBufAllocator.java:324)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:181)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.buffer.AbstractByteBufAllocator.directBuffer(AbstractByteBufAllocator.java:172)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.handler.ssl.PemX509Certificate.newBuffer(PemX509Certificate.java:152)
Nov 01 11:59:32 nomad-client11-p.dal10sl.bigcommerce.net linkerd[5699]: at io.netty.handler.ssl.PemX509Certificate.append(PemX509Certificate.java:134)```

We’re hitting a leak that is different from before. The previous memory leak appeared to be from native memory being allocated in some JNI code (the JVM was completely unaware of it).

The memory in this leak seems to be owned by DirectByteBuffer instances. We’re bumping into the direct memory limit that the JVM imposes. A heap dump + Netty’s leak detector should shed some light on what parts of linkerd own these DirectByteBuffer instances.

Heap dump showing GC roots for DirectByteBuffers:

We’re observing this suspicious message in our logs:

Nov 03 17:36:55  WARN 1103 17:36:55.421 CDT finagle/netty4-6: An exceptionCaught() event was fired, and it reached at the tail of the pipeline. It usually means the last handler in the pipeline did not handle the exception.
Nov 03 17:36:55  java.io.IOException: Connection reset by peer
Nov 03 17:36:55  at sun.nio.ch.FileDispatcherImpl.read0(Native Method)
Nov 03 17:36:55  at sun.nio.ch.SocketDispatcher.read(SocketDispatcher.java:39)
Nov 03 17:36:55  at sun.nio.ch.IOUtil.readIntoNativeBuffer(IOUtil.java:223)
Nov 03 17:36:55  at sun.nio.ch.IOUtil.read(IOUtil.java:192)
Nov 03 17:36:55  at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:380)
Nov 03 17:36:55  at io.netty.buffer.PooledUnsafeDirectByteBuf.setBytes(PooledUnsafeDirectByteBuf.java:288)
Nov 03 17:36:55  at io.netty.buffer.AbstractByteBuf.writeBytes(AbstractByteBuf.java:1106)
Nov 03 17:36:55  at io.netty.channel.socket.nio.NioSocketChannel.doReadBytes(NioSocketChannel.java:372)
Nov 03 17:36:55  at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:123)
Nov 03 17:36:55  at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:645)
Nov 03 17:36:55  at io.netty.channel.nio.NioEventLoop.processSelectedKeysOptimized(NioEventLoop.java:580)
Nov 03 17:36:55  at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:497)
Nov 03 17:36:55  at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:459)
Nov 03 17:36:55  at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858)
Nov 03 17:36:55  at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
Nov 03 17:36:55  at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
Nov 03 17:36:55  at com.twitter.finagle.util.BlockingTimeTrackingThreadFactory$$anon$1.run(BlockingTimeTrackingThreadFactory.scala:23)
Nov 03 17:36:55  at java.lang.Thread.run(Thread.java:748)

If the exception is making it up to the netty event loop, maybe there’s a buffer not being freed in a finally block somewhere?

Quick update: we’re digging into this issue this week, stay tuned.