MatchGraphBuilder.disambiguate eats my memory #1359

yannick · 2015-12-29T21:47:45Z

dependency "vibe-d" version="0.7.26"

after a short while of production traffic i have huge memory usage.
-profile=gc shows MatchGraphBuilder.disambiguate as the culprit

the only non fully defined route is this:
router.get("*", serveStaticFiles("public"));

cat profilegc.log 
bytes allocated, allocations, type, function, file:line
       87998464           11266 ulong[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../home/build/.dub/packages/vibe-d-0.7.26/source/vibe/http/router.d:915
       13738208          429319 std.array.Appender!string.Appender.Data std.array.Appender!string.Appender.this /usr/include/dlang/dmd/std/array.d:2653
        1901472            9903 msgpack.StreamingUnpacker.Context.Container[] msgpack.StreamingUnpacker.execute.startContainer!"Array".startContainer ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:4189
        1756880            9902 ubyte[] msgpackrpc.transport.tcp.ClientSocket!(Client!(tcp)).ClientSocket.onRead ../../dub-dependencies/msgpack-rpc-d/src/msgpackrpc/transport/tcp.d:139
        1736704              53 ubyte[] msgpack.StreamingUnpacker.InternalBuffer!().feed.expandBuffer ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:1819
        1727736           71989 closure std.conv.emplaceImpl!(JSONValue).emplaceImpl!(JSONValue).emplaceImpl /usr/include/dlang/dmd/std/conv.d:4037
        1552000           48500 std.array.Appender!(JSONValue[]).Appender.Data std.array.Appender!(JSONValue[]).Appender.this /usr/include/dlang/dmd/std/array.d:2653
        1326000              50 vibe.http.router.MatchTree!(Route).MatchTree.Node[] vibe.http.router.MatchTree!(Route).MatchTree.rebuildGraph.process ../../../../../home/build/.dub/packages/vibe-d-0.7.26/source/vibe/http/router.d:736
        1267552           39611 msgpack.Value[] msgpack.StreamingUnpacker.execute ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:4430
        1137984           17781 closure logging.handOffLogs source/logging.d:47
        1048544               2 ubyte[] kafkad.connection.BrokerConnection.this ../../dub-dependencies/kafka-d/source/kafkad/connection.d:60
...etc...

The text was updated successfully, but these errors were encountered:

etcimon · 2015-12-29T22:14:57Z

Ah, you've finally found it. I've resorted to falling back to the old tree matching algorithm a while back because of an infinite loop issue in there :-p

yannick · 2015-12-30T09:08:34Z

hmm after some hours the real leak is actually in somewhere else.
either JSON or msgpack is the culprit. none the less, 87mb for 5 routes is a bit too much...

this is how it looks after some 10 hours:

bytes allocated, allocations, type, function, file:line
     1356693280        42396665 std.array.Appender!string.Appender.Data std.array.Appender!string.Appender.this /usr/include/dlang/dmd/std/array.d:2653
      208223688         8675987 closure std.conv.emplaceImpl!(JSONValue).emplaceImpl!(JSONValue).emplaceImpl /usr/include/dlang/dmd/std/conv.d:4037
      185077248          963923 msgpack.StreamingUnpacker.Context.Container[] msgpack.StreamingUnpacker.execute.startContainer!"Array".startContainer ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:4189
      171016192            5219 ubyte[] msgpack.StreamingUnpacker.InternalBuffer!().feed.expandBuffer ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:1819
      170675856          963881 ubyte[] msgpackrpc.transport.tcp.ClientSocket!(Client!(tcp)).ClientSocket.onRead ../../dub-dependencies/msgpack-rpc-d/src/msgpackrpc/transport/tcp.d:139
      155465600         4858300 std.array.Appender!(JSONValue[]).Appender.Data std.array.Appender!(JSONValue[]).Appender.this /usr/include/dlang/dmd/std/array.d:2653
      123379200         3855600 msgpack.Value[] msgpack.StreamingUnpacker.execute ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:4430
      111940544         1749071 closure logging.handOffLogs source/logging.d:47
       92538336          963941 msgpack.StreamingUnpacker.Context.Container[] msgpack.StreamingUnpacker.initializeContext ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:4508
       87998464           11266 ulong[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../home/build/.dub/packages/vibe-d-0.7.27-alpha.2/source/vibe/http/router.d:925
       83965664         3498551 vibe.inet.path.PathEntry[] vibe.inet.path.splitPath ../../../../../home/build/.dub/packages/vibe-d-0.7.27-alpha.2/source/vibe/inet/path.d:477
       63616080          963880 msgpackrpc.client.Future msgpackrpc.client.Client!(tcp).Client.sendRequest!(string).sendRequest ../../dub-dependencies/msgpack-rpc-d/src/msgpackrpc/client.d:81
       55977696         1749303 std.array.Appender!string.Appender.Data std.array.Appender!string.Appender.ensureAddable /usr/include/dlang/dmd/std/array.d:2732
       55971712         1749116 std.array.Appender!(string[]).Appender.Data std.array.Appender!(string[]).Appender.this /usr/include/dlang/dmd/std/array.d:2653
       55970400         1749075 std.array.Appender!(ubyte[]).Appender.Data std.array.Appender!(ubyte[]).Appender.this /usr/include/dlang/dmd/std/array.d:2653
       49871904         1038998 vibe.data.json.Json[immutable(char)[]] vibe.data.json.Json.opIndex ../../../../../home/build/.dub/packages/vibe-d-0.7.27-alpha.2/source/vibe/data/json.d:332
       31085120          971410 vibe.http.common.CookieValueMap.Cookie[] vibe.http.common.CookieValueMap.opIndexAssign ../../../../../home/build/.dub/packages/vibe-d-0.7.27-alpha.2/source/vibe/http/common.d:678
       30844192          963881 std.array.Appender!(ubyte[]).Appender.Data std.array.Appender!(ubyte[]).Appender.ensureAddable /usr/include/dlang/dmd/std/array.d:2732
       30461280          951915 vibe.data.json.Json[] vibe.data.json.JsonSerializer.beginWriteDictionary!(string[string]).beginWriteDictionary ../../../../../home/build/.dub/packages/vibe-d-0.7.27-alpha.2/source/vibe/data/json.d:1577
       27987952         1749247 immutable(vibe.inet.path.PathEntry)[] vibe.inet.path.Path.opBinary!"~".opBinary ../../../../../home/build/.dub/packages/vibe-d-0.7.27-alpha.2/source/vibe/inet/path.d:265
       27761250         1749071 immutable(char)[] logging.handOffLogs source/logging.d:55
       25077888           87076 msgpack.StreamingUnpacker.Context.Container[] msgpack.StreamingUnpacker.execute.startContainer!"Map".startContainer ../../../../../home/build/.dub/packages/msgpack-d-0.9.6/src/msgpack.d:4189

s-ludwig · 2016-01-09T19:08:27Z

Do you have the GC enabled? I was under the impression that everything done in disambiguate (which is only called once at startup) should be unreferenced after the graph has been built. The only data that lasts is what is created afterwards in MatchTree.rebuildGraph.

yannick · 2016-01-10T01:49:26Z

yes GC enabled

marcioapm · 2016-01-13T19:43:24Z

We deploy to low resource servers and this is a major issue for us right now.
We had to resort to the old implementation, like Etienne. I hope it doesn't get deprecated until the situation with the tree matcher is improved :)

Note: I am still on 0.7.25

s-ludwig · 2016-01-16T20:02:35Z

Hm, I'm not sure how to read that log there. If the GC is enabled, am I right in that those numbers are the total numbers and not the current memory use?

All I can say to this with the current information is that I'm 99.9% certain that all memory claimed by GraphBuilder, including in disambiguate, is unreferenced and re-claimable for the GC after the initialization phase. MatchTree has a relatively well packed representation using much less memory, and MatchTree.match doesn't allocate at all, so that can't be a memory leak there.

marcioapm · 2016-04-05T11:45:16Z

I upgraded to 0.7.28 recently and since VibeOldRouterImpl is broken on this release, I now use the match tree.

It seems the infinite loop is gone, likely to be due to a related fix in DMD, however, the disambiguate() call still takes 13secs for my router setup, which is pretty nasty for development.

Could we maybe switch to an incremental implementation if it's faster? Or at the very least, could we bring back VibeOldRouterImpl?

@s-ludwig could you describe a bit the disambiguate() implementation, or perhaps point me in the direction of any references you used during the implementation? It's not easy for me to understand what the code is trying to do and how.

s-ludwig · 2016-04-06T07:36:25Z

disambiguate() basically converts an NFA, which is created when registering routes, to a DFA. In particular, it collects all nodes of the match graph that have multiple possible target nodes when matching a particular character and creates a single replacement node for those (recursively). At the end, all nodes have either zero or one outgoing edges for a particular match character.

An incremental implementation would not be efficient, but the existing function, I'm pretty sure, can be optimized a lot. I'm currently looking into that.

- Changes the memory layout to store NFA edges - Pre-allocates memory for combined edge lists - Uses simple append instead of addToEdge where possible

s-ludwig · 2016-04-06T12:56:09Z

Okay, got a 5x increase in speed for a synthetic test with 1400 partially overlapping routes (~20s down to ~4s). Further improvements will be more difficult, but I hope that this is enough for all usual real world cases.

Avoids GC allocations for tiny arrays. See #1359.

s-ludwig · 2016-04-06T13:35:24Z

Release build gives another 2x increase. There are some low-hanging fruits, such as avoiding imul when indexing the m_nodes array, but DMD only does that with optimizations enabled.

marcioapm · 2016-04-06T13:54:44Z

Wow! Great @s-ludwig

Thanks for this!

tchaloupka · 2016-08-21T11:18:58Z

Came across this too.
Having some complex REST API server with about 80 methods registered through registerRestInterface.
After start it takes some 30MB, but after first call to simple method it went to 200MB and stays there forever even if not used further (GC on).

vibe-0.7.30-alpha4
dmd-2.071.1

Here is the output from profile-gc just after the first call:

bytes allocated, allocations, type, function, file:line
     1521564672           77058 ulong[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:861
      175044032             348 ulong[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:889
       63155040             348 vibe.http.router.MatchTree!(Route).MatchTree.Node[] vibe.http.router.MatchTree!(Route).MatchTree.rebuildGraph.process ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:679
       23780640            5772 vibe.http.router.MatchGraphBuilder.Node[] vibe.http.router.MatchGraphBuilder.addNode ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:977
        1304064           54336 vibe.http.router.MatchGraphBuilder.TerminalTag[] vibe.http.router.MatchGraphBuilder.addToArray!(TerminalTag).addToArray ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:990
         869376           54336 vibe.http.router.MatchTree!(Route).MatchTree.TerminalTag[] vibe.http.router.MatchTree!(Route).MatchTree.rebuildGraph.process ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:686
         616456           77057 ulong[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:915
         173568               1 bool[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:857
         130152            5423 vibe.http.router.MatchGraphBuilder.TerminalTag[] vibe.http.router.MatchGraphBuilder.addTerminal ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:971
          92352               1 uint[] vibe.http.router.MatchTree!(Route).MatchTree.rebuildGraph ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:669
          23040             288 vibe.http.router.MatchTree!(Route).MatchTree.Terminal[] vibe.http.router.MatchTree!(Route).MatchTree.addTerminal ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:519
          16384               1 vibe.core.core.CoreTask[] vibe.utils.array.FixedRingBuffer!(CoreTask, 0LU, true).FixedRingBuffer.capacity ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/utils/array.d:335
          16352             511 std.array.Appender!string.Appender.Data std.array.Appender!string.Appender.this /usr/include/dmd/phobos/std/array.d:2660
           7008             292 vibe.web.internal.rest.common.PathPart[] vibe.web.internal.rest.common.extractPathParts.addText ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/web/internal/rest/common.d:483
           5280              51 vibe.web.internal.rest.common.Parameter[] vibe.web.internal.rest.common.RestInterface!(EventServiceAdmin).RestInterface.computeRoutes ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/web/internal/rest/common.d:159

s-ludwig · 2016-08-23T12:06:50Z

1521564672 77058 ulong[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:861

It seems like the GC implementation doesn't count actual allocations, but also re-allocations of already allocated blocks. That spot uses assumeSafeAppend to use a dynamic array as a stack that reuses the memory. 1.5 GB doesn't remotely make sense there.

63155040 348 vibe.http.router.MatchTree!(Route).MatchTree.Node[] vibe.http.router.MatchTree!(Route).MatchTree.rebuildGraph.process ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:679

This appears to be the only valid large long-term allocation. However, the amount of memory would amount to over 200000 graph nodes, which means over around 2500 characters per route for 80 routes, which doesn't seem right.

What I suspect is that the profile-gc output contains a lot of old allocations that have already been collected (although I'm not familiar with this). The process generally wouldn't go below 200MB after having used that much once, because the GC simply never gives back memory to the OS - or at least of that hasn't changed recently.

If this is all true, it's likely that this line is the one responsible for allocating almost 200MB in the first place:
175044032 348 ulong[] vibe.http.router.MatchGraphBuilder.disambiguate ../../../../../.dub/packages/vibe-d-0.7.30-alpha.4/vibe-d/source/vibe/http/router.d:889
Unfortunately, there is no low-level way to reduce this number. But maybe there is something sub-optimal going on in the disambiguation algorithm.

To clear up some unknowns, can you post the router log output for LogLevel.debug_ (--vv switch)?

tchaloupka · 2016-08-23T20:25:12Z

I've tried to create some sample app to show the behaviour.
Here is some simply generated one: https://gist.github.com/tchaloupka/cdba5a900eb655121c3011b4fe12e3dd, it uses over 200MB after first request.

It outputs: Match tree has 3467 nodes, 201 terminals

With our original (closed source unfortunatelly) service it outputs: Match tree has 348 nodes, 288 terminals.

profilegc output is pretty similar.

As I looked through the router.d it seems to me that node_stack handling in disambiguate method must reallocate too much. Could this be the problem?

Seemingly doesn't affect the real process usage, but cleans up the -profile=gc output of DMD.

s-ludwig · 2016-08-24T06:45:56Z

All profile log entries turned out to be red herrings, all caused by appending to a dynamic array. The array only grew in place, but obviously the GC stats collector adds the full array length each time. I've eliminated two out of three now and the remaining one is not enough to explain the memory usage.

So I see two possibilities left now:

The GC heap is heavily fragmented
The memory is allocated on some other heap instead

I'll investigate further when I get some time.

tchaloupka · 2018-01-22T10:23:19Z

I've updated the test to use HTTPServeroption.reusePort as distribute is now obsolete: https://gist.github.com/tchaloupka/ffbe14383e525a4b34a3264b59bb73dc

Because of that the URLRouter is created as many times as I have virtual CPUs, which leads on my 8 virtual CPUs to these numbers:

ps -aux | grep test
tcha      6032 22.5  9.3 2541920 1512584 pts/4 Sl+  10:54   0:03 ./urlrouter_test

If I add:

GC.collect();
GC.minimize()

I get:

tcha      7081  3.1  1.8 1273188 291340 pts/4  Sl+  11:13   0:04 ./urlrouter_test

Still pretty crazy for a service which does nothing.

s-ludwig · 2018-01-23T00:07:44Z

Okay, this is definitely caused by memory fragmentation. I replaced all arrays in MatchGraphBuilder with std.container.Array, so that it uses a separate heap, and the memory then usage stays at around 44MB after all routers have been created. The downside is that this made the whole code a lot slower, so some more optimization is required before this can be pushed as a fix.

s-ludwig · 2018-01-24T16:50:58Z

Working version: https://github.com/vibe-d/vibe.d/tree/router_mem_opt
With this I get 36 MB memory use. The only issue is that the code right now has a very low level style with manual linked list handling, making it rather error prone. I'd like to take the time to refactor it a bit before merging it into master.

Includes #1359, #2043

s-ludwig added a commit that referenced this issue Apr 6, 2016

Optimize URLRouter DFA generation. See #1359.

e704298

- Changes the memory layout to store NFA edges - Pre-allocates memory for combined edge lists - Uses simple append instead of addToEdge where possible

s-ludwig added a commit that referenced this issue Apr 6, 2016

Another slight optimization for disambiguate().

77619ff

Avoids GC allocations for tiny arrays. See #1359.

s-ludwig added a commit that referenced this issue Aug 24, 2016

Reduce the number of array appends in URLRouter. See #1359.

15d3ea1

Seemingly doesn't affect the real process usage, but cleans up the -profile=gc output of DMD.

s-ludwig added the http label Jul 5, 2017

s-ludwig mentioned this issue Jan 24, 2018

Optimize memory issues in URLRouter. Fixes #1359. #2043

Merged

dlang-bot closed this as completed in 6984b62 Feb 16, 2018

s-ludwig added a commit that referenced this issue Mar 18, 2018

Backport fixes to URLRouter from master.

29f8d55

Includes #1359, #2043

s-ludwig mentioned this issue Mar 18, 2018

Backport fixes to URLRouter from master. #2128

Merged

s-ludwig added a commit that referenced this issue Apr 25, 2018

Backport fixes to URLRouter from master.

5c46e3b

Includes #1359, #2043

s-ludwig added a commit that referenced this issue Apr 25, 2018

Backport fixes to URLRouter from master.

a6acd82

Includes #1359, #2043

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

MatchGraphBuilder.disambiguate eats my memory #1359

MatchGraphBuilder.disambiguate eats my memory #1359

yannick commented Dec 29, 2015

etcimon commented Dec 29, 2015

yannick commented Dec 30, 2015

s-ludwig commented Jan 9, 2016

yannick commented Jan 10, 2016

marcioapm commented Jan 13, 2016

s-ludwig commented Jan 16, 2016

marcioapm commented Apr 5, 2016

s-ludwig commented Apr 6, 2016

s-ludwig commented Apr 6, 2016

s-ludwig commented Apr 6, 2016

marcioapm commented Apr 6, 2016

tchaloupka commented Aug 21, 2016

s-ludwig commented Aug 23, 2016

tchaloupka commented Aug 23, 2016

s-ludwig commented Aug 24, 2016

tchaloupka commented Jan 22, 2018

s-ludwig commented Jan 23, 2018

s-ludwig commented Jan 24, 2018

MatchGraphBuilder.disambiguate eats my memory #1359

MatchGraphBuilder.disambiguate eats my memory #1359

Comments

yannick commented Dec 29, 2015

etcimon commented Dec 29, 2015

yannick commented Dec 30, 2015

s-ludwig commented Jan 9, 2016

yannick commented Jan 10, 2016

marcioapm commented Jan 13, 2016

s-ludwig commented Jan 16, 2016

marcioapm commented Apr 5, 2016

s-ludwig commented Apr 6, 2016

s-ludwig commented Apr 6, 2016

s-ludwig commented Apr 6, 2016

marcioapm commented Apr 6, 2016

tchaloupka commented Aug 21, 2016

s-ludwig commented Aug 23, 2016

tchaloupka commented Aug 23, 2016

s-ludwig commented Aug 24, 2016

tchaloupka commented Jan 22, 2018

s-ludwig commented Jan 23, 2018

s-ludwig commented Jan 24, 2018