Probably false alarm regarding small Server Rendering Memory leak

[justin808]

https://github.com/shakacode/react_on_rails/search?utf8=%E2%9C%93&q=therubyracer

mini_racer is faster!

• https://github.com/discourse/mini_racer
• https://github.com/rails/execjs

[justin808]

This has already been done in the https://github.com/shakacode/react-webpack-rails-tutorial and some of the docs are updated. Possibly, this is complete.

[mariusandra]

Hey, I changed therubyracer to mini_racer just like here, but instead of a speedup I got a 2-3x slowdown.

Before:

# ab -n 25 https://www.apprentus.be/cours-particuliers/bruxelles
Requests per second:    2.01 [#/sec] (mean)
Time per request:       496.426 [ms] (mean)

After:

# ab -n 25 https://www.apprentus.be/cours-particuliers/bruxelles
Requests per second:    0.91 [#/sec] (mean)
Time per request:       1097.705 [ms] (mean)

Any thoughts on what could be wrong? Must I somewhere specify that I want to use mini_racer or is it just enough to add it to the Gemfile?

[justin808]

@mariusandra Please investigate this, as it's not what we experienced with https://www.friendsandguests.com/. I suggest you do some more detailed profiling in production. Do you use new relic?

[mariusandra]

@justin808 I investigated and found the bug! I was stuck with execjs 2.6, but needed 2.7. Upgrading it solved the situation.

I'm not sure what execjs 2.6 was using for the big slowdown, probably an external node that was reloading the big server bundle every time.

I do see a speed increase now!

With therubyracer:

Time per request:       193.497 [ms] (mean)

With the mystery node:

Time per request:       1081.708 [ms] (mean)

With mini_racer:

Time per request:       135.992 [ms] (mean)

New relic shows that the average time spent in the view that renders the react component (for this page) went from 57.6ms (to 956ms) to 38ms, a 35% improvement.

So, thanks a lot and I hope this helps someone with a similar issue in the future.

[mariusandra]

Hey! Somehow I got a new issue.

The blue part in this graph shows how long the react component renders on the server side:

It starts out great, but then keeps getting longer and longer until something either kills it or something gets garbage collected.

As a temporary (Windows 98 style) fix, I added a cron job that restarts the server every 30min, stabilising the situation., but obviously this is not ideal :).

@justin808, have you experienced something similar? Any hints on how to debug this?

[Judahmeek]

@mariusandra there's a lot of good info on debugging react performance here: http://benchling.engineering/performance-engineering-with-react/

[justin808]

@mariusandra No idea on how to fix what you're seeing.

[mariusandra]

I finally fixed my memory leak issue. It came from using a component called react-helmet. I probably should have paid more attention to their Server Usage section.

They recommend calling Helmet.rewind(); after ReactDOM.renderToString, but since it isn't easy to hook this up with react_on_rails, I went for a simpler solution.

Debugging this memory leak took a bit of time. In case anyone else needs to do this, here are the steps I took:

1. Clone react_on_rails and reference the local version in your Gemfile:

gem "react_on_rails", path: '../react_on_rails'

2. Add this trace_message to eval_js in react_on_rails/lib/server_rendering_pool/exec.rb:

        # around line 75
        def eval_js(js_code)
          trace_messsage(js_code, "tmp/js-code.js", true) # new line
          @js_context_pool.with do |js_context|

3. Add true to this trace_message in create_js_context around line 95:

            begin
              trace_messsage(base_js_code, file_name, true) # add 'true' here
              ExecJS.compile(base_js_code)
            rescue => e

4. Turn on server rendering, go to the page that you suspect causes problems and refresh. This should generate the files tmp/base_js_code.js (your server-bundle) and tmp/js-code.js (calling the right component with the right props).

5. In the console:

cd tmp
npm install heapdump
echo "var heapdump = require('heapdump'); for(var i=0;i<10000;i++) { if (i % 100 === 0) { heapdump.writeSnapshot('heap-' + i + '-' + Date.now() + '.heapsnapshot'); }" > debug1.js
echo "}" > debug2.js
echo "rm heap-*; cat base_js_code.js debug1.js js-code.js debug2.js  > combined.js; node --trace_gc combined.js" > test-leak.sh

6. To run the memory leak test:

sh test-leak.sh

Now you can see if the memory is actually leaking (keeps growing after every Mark-sweep) or gets cleaned up (resets back to a stable amount after every Mark-sweep).

If you see stuff like this, you have a memory leak:

[52163:0x102800000]      917 ms: Mark-sweep 27.2 (42.1) -> 27.2 (43.1) MB, 20.6 / 0.0 ms [HeapSnapshotGenerator::GenerateSnapshot] [GC in old space requested].
[52163:0x102800000]     6683 ms: Mark-sweep 128.7 (166.1) -> 98.2 (167.1) MB, 24.7 / 0.0 ms (+ 166.0 ms in 1121 steps since start of marking, biggest step 3.9 ms) [GC interrupt] [GC in old space requested].
[52163:0x102800000]    14231 ms: Mark-sweep 255.6 (293.1) -> 193.4 (295.1) MB, 32.3 / 0.0 ms (+ 293.1 ms in 1451 steps since start of marking, biggest step 4.1 ms) [GC interrupt] [GC in old space requested].
[52163:0x102800000]    19932 ms: Mark-sweep 320.2 (380.1) -> 264.1 (381.1) MB, 282.2 / 0.0 ms [HeapSnapshotGenerator::GenerateSnapshot] [GC in old space requested].

However this is probably normal:

[52436:0x102800c00]    10286 ms: Mark-sweep 27.1 (141.3) -> 26.9 (68.3) MB, 24.1 / 0.0 ms [HeapSnapshotGenerator::GenerateSnapshot] [GC in old space requested].
[52436:0x102800c00]    14936 ms: Mark-sweep 27.1 (140.3) -> 26.9 (69.3) MB, 22.3 / 0.0 ms [HeapSnapshotGenerator::GenerateSnapshot] [GC in old space requested].
[52436:0x102800c00]    19768 ms: Mark-sweep 27.4 (142.3) -> 27.1 (69.3) MB, 23.7 / 0.0 ms [HeapSnapshotGenerator::GenerateSnapshot] [GC in old space requested].

7. To debug you have two options.

7.1) First one:

The above script will give you several files heap-0-*.heapsnapshot, heap-100-*.heapsnapshot, etc. The number (0, 100, 200, etc) indicates how many times your component was rendered.

Open up Chrome, go to the developer tools and select "Profile". Click "Load" and open two of the files. E.g. "heap-100" and "heap-300". Then click into one of them and compare with the other. You should see something like this:

The bigger the distance between the files (100 to 300 vs 100 to 2100), the better. If you see a lot of duplicate objects that are a multiple of the distance (200 in this case), you probably have a leak there. If you see any React components hanging around (or 100 of them), you definitely have a leak.

Figure out how to get rid of it. This article can be of help.

7.2) Just start removing elements from your React components and re-run the test. Keep doing this to narrow down the line that leaks. For me the leaks stopped once I removed the line for <Helmet />.

---

Throughout this, I found that react_on_rails itself has a small memory leak. I'm not sure if it's something that only happens in development or what exactly causes it, but apparently all the console messages, props and railsContexts are kept between server renders:

This was true for my application (Apprentus) and for react-webpack-rails-tutorial. I need to investigate more to know for sure if this is just a development issue or also happens with production settings.

In any case finding and fixing the react-helmet issue solved 99% of all my leaks. So I'm already very happy.

I'll post again if/when I find something, however feel free to take a crack at this. (Yes, you who are reading this now! :))

Cheers!

[malonehedges]

FYI the README mentions this issue still

[justin808]

@dzirtusss @robwise @dylangrafmyre Heads up. We need to fix this.

[justin808]

Throughout this, I found that react_on_rails itself has a small memory leak. I'm not sure if it's something that only happens in development or what exactly causes it, but apparently all the console messages, props and railsContexts are kept between server renders

We're keeping the console messages in the context.

We need to clear the console logs at the end of each rendering. We seem to be doing that:

react_on_rails/lib/react_on_rails/server_rendering_pool/exec.rb

Line 71 in 0ca17c9

def eval_js(js_code)

        def eval_js(js_code)
          @js_context_pool.with do |js_context|
            result = js_context.eval(js_code)
            js_context.eval("console.history = []")
            result
          end
        end

        # Reimplement console methods for replaying on the client
        def console_polyfill
          <<-JS
var console = { history: [] };
['error', 'log', 'info', 'warn'].forEach(function (level) {
  console[level] = function () {
    var argArray = Array.prototype.slice.call(arguments);
    if (argArray.length > 0) {
      argArray[0] = '[SERVER] ' + argArray[0];
    }
    console.history.push({level: level, arguments: argArray});
  };
});
          JS
        end

If we need a fix for this.

• Build upon fix in Clear hydrated stores #785
• Create a function to clear the console and call this function at the end of each rendering on the server side.

Code References:

• react_on_rails/node_package/src/buildConsoleReplay.js

  Line 1 in 7ccd603

  // @flow

• react_on_rails/lib/react_on_rails/server_rendering_pool/exec.rb

  Line 155 in 0ca17c9

  var console = { history: [] };

[justin808]

@mariusandra @malonehedges Any idea if we might have a memory leak? I don't think so from looking at the code.

[justin808]

One potential issue is that if a JS library has a memory leak, then server rendering will magnify this leak. We might want an option to delete the context after so X renders.

[mariusandra]

@justin808 Hey, I'm not sure. The code indeed looks like it clears the messages, but those lines were also there when I wrote my long comment in December... and they didn't seem to back then.

I don't know enough about V8 to guess how it stores and discards references to objects between calls that reuse contexts. Someone with more knowledge of the matter should give their opinion here :).

One option to try is "method 3" from this page: https://appendto.com/2016/02/empty-array-javascript/

Basically instead of

js_context.eval("console.history = []")

to do

js_context.eval("console.history.length = 0")

I tried checking if it would make a difference, but my react_on_rails + react-webpack-rails-tutorial builds are all messed up. I can't promise when I'll find time to fix them and test again. So someone else can take over.

However even with this fixed, the issue with a memory leak in a JS library still remains.