Why is my Heroku app memory footprint so big

Question

I have a Rails 4.2 application running on Heroku, Ruby version is 2.2.4

When I restart the application, using Heroku´s log-runtime-metrics the app logs this:

sample#memory_total=102.07MB 
sample#memory_rss=102.06MB 
sample#memory_cache=0.00MB 
sample#memory_swap=0.00MB 
sample#memory_pgpgin=29936pages 
sample#memory_pgpgout=3807pages 
sample#memory_quota=512.00MB

A simple click to a diferent page in the landing of the app reports these details:

sample#memory_total=267.07MB 
sample#memory_rss=265.63MB 
sample#memory_cache=1.43MB 
sample#memory_swap=0.00MB 
sample#memory_pgpgin=109878pages 
sample#memory_pgpgout=41509pages 
sample#memory_quota=512.00MB

Oink reports: Memory usage: 435416

Entering the app I have some datatables with pagination, when moving around the pages the memory keeps increasing:

sample#memory_total=349.68MB 
sample#memory_rss=348.18MB 
sample#memory_cache=1.50MB 
sample#memory_swap=0.00MB 
sample#memory_pgpgin=159122pages 
sample#memory_pgpgout=69604pages 
sample#memory_quota=512.00MB

Oink reporting at this moment: Memory usage: 602352

If I go out to a simpler page on the app Heroku reports:

sample#memory_total=353.05MB 
sample#memory_rss=351.51MB 
sample#memory_cache=1.54MB 
sample#memory_swap=0.00MB 
sample#memory_pgpgin=169306pages 
sample#memory_pgpgout=78924pages 
sample#memory_quota=512.00MB

Oink reports Memory usage: 604744

After 5 minutes moving around Heroku reports for memory total something between 360 and 400+ MB. It doesn't get into Memory Quota errors but if a new web worker would be fired I bet it would.

---

I have also taken some data from ObjectSpace. Navigating around the site (this time in local), first with the simplest pages, then entering the part with pagination with fetches more data, going out and so. These are some of the logs from ObjectSpace.count_objects:

{:TOTAL=>556379, :FREE=>1142, :T_OBJECT=>27740, :T_CLASS=>7356, :T_MODULE=>1563, :T_FLOAT=>9, :T_STRING=>241807, :T_REGEXP=>2481, :T_ARRAY=>92685, :T_HASH=>16081, :T_STRUCT=>1118, :T_BIGNUM=>13, :T_FILE=>117, :T_DATA=>81408, :T_MATCH=>6132, :T_COMPLEX=>1, :T_RATIONAL=>909, :T_SYMBOL=>1691, :T_NODE=>62347, :T_ICLASS=>11779}

{:TOTAL=>556379, :FREE=>1211, :T_OBJECT=>27540, :T_CLASS=>7354, :T_MODULE=>1565, :T_FLOAT=>9, :T_STRING=>241100, :T_REGEXP=>2478, :T_ARRAY=>93344, :T_HASH=>16763, :T_STRUCT=>1078, :T_BIGNUM=>13, :T_FILE=>122, :T_DATA=>81422, :T_MATCH=>6031, :T_COMPLEX=>1, :T_RATIONAL=>911, :T_SYMBOL=>1690, :T_NODE=>61968, :T_ICLASS=>11779}

{:TOTAL=>556379, :FREE=>946, :T_OBJECT=>24257, :T_CLASS=>7523, :T_MODULE=>1565, :T_FLOAT=>9, :T_STRING=>251448, :T_REGEXP=>2362, :T_ARRAY=>83078, :T_HASH=>15272, :T_STRUCT=>1175, :T_BIGNUM=>63, :T_FILE=>128, :T_DATA=>89152, :T_MATCH=>5952, :T_COMPLEX=>1, :T_RATIONAL=>963, :T_SYMBOL=>2028, :T_NODE=>58656, :T_ICLASS=>11801}

ENTERING DATATABLES, WITH PAGINATION, 25 RECORDS PER PAGE, DATA RETRIEVED CONTAINS UNIQUE STRINGS (ADDRESSES IN FACT).

{:TOTAL=>556379, :FREE=>906, :T_OBJECT=>26280, :T_CLASS=>7363, :T_MODULE=>1563, :T_FLOAT=>9, :T_STRING=>252024, :T_REGEXP=>2474, :T_ARRAY=>87445, :T_HASH=>15347, :T_STRUCT=>1144, :T_BIGNUM=>16, :T_FILE=>133, :T_DATA=>80601, :T_MATCH=>6686, :T_COMPLEX=>1, :T_RATIONAL=>985, :T_SYMBOL=>1690, :T_NODE=>59906, :T_ICLASS=>11806}

{:TOTAL=>556379, :FREE=>146, :T_OBJECT=>18752, :T_CLASS=>7359, :T_MODULE=>1563, :T_FLOAT=>9, :T_STRING=>295002, :T_REGEXP=>2304, :T_ARRAY=>81885, :T_HASH=>13791, :T_STRUCT=>867, :T_BIGNUM=>15, :T_FILE=>11, :T_DATA=>77634, :T_MATCH=>847, :T_COMPLEX=>1, :T_RATIONAL=>1251, :T_SYMBOL=>1679, :T_NODE=>41463, :T_ICLASS=>11800}

{:TOTAL=>571870, :FREE=>433, :T_OBJECT=>19352, :T_CLASS=>7369, :T_MODULE=>1565, :T_FLOAT=>9, :T_STRING=>294098, :T_REGEXP=>2358, :T_ARRAY=>91079, :T_HASH=>14983, :T_STRUCT=>879, :T_BIGNUM=>15, :T_FILE=>16, :T_DATA=>77945, :T_MATCH=>1128, :T_COMPLEX=>1, :T_RATIONAL=>1591, :T_SYMBOL=>2028, :T_NODE=>45197, :T_ICLASS=>11824}

{:TOTAL=>628109, :FREE=>343, :T_OBJECT=>20647, :T_CLASS=>7360, :T_MODULE=>1563, :T_FLOAT=>9, :T_STRING=>318169, :T_REGEXP=>2346, :T_ARRAY=>115854, :T_HASH=>17767, :T_STRUCT=>949, :T_BIGNUM=>15, :T_FILE=>10, :T_DATA=>79152, :T_MATCH=>1243, :T_COMPLEX=>1, :T_RATIONAL=>1789, :T_SYMBOL=>1685, :T_NODE=>47405, :T_ICLASS=>11802}

{:TOTAL=>727564, :FREE=>470, :T_OBJECT=>22820, :T_CLASS=>7361, :T_MODULE=>1563, :T_FLOAT=>9, :T_STRING=>362350, :T_REGEXP=>2390, :T_ARRAY=>152959, :T_HASH=>22342, :T_STRUCT=>1035, :T_BIGNUM=>33, :T_FILE=>11, :T_DATA=>81286, :T_MATCH=>2167, :T_COMPLEX=>1, :T_RATIONAL=>2497, :T_SYMBOL=>1686, :T_NODE=>54779, :T_ICLASS=>11805}

{:TOTAL=>811122, :FREE=>392, :T_OBJECT=>24361, :T_CLASS=>7362, :T_MODULE=>1563, :T_FLOAT=>9, :T_STRING=>409740, :T_REGEXP=>2434, :T_ARRAY=>176571, :T_HASH=>25118, :T_STRUCT=>1076, :T_BIGNUM=>51, :T_FILE=>13, :T_DATA=>82701, :T_MATCH=>2858, :T_COMPLEX=>1, :T_RATIONAL=>3093, :T_SYMBOL=>1686, :T_NODE=>60285, :T_ICLASS=>11808}

LEAVING NOW DATATABLES AND PAGINATION TO A SIMPLER PAGE ON THE APP

{:TOTAL=>819681, :FREE=>494, :T_OBJECT=>24601, :T_CLASS=>7374, :T_MODULE=>1563, :T_FLOAT=>9, :T_STRING=>413540, :T_REGEXP=>2437, :T_ARRAY=>178899, :T_HASH=>25953, :T_STRUCT=>1118, :T_BIGNUM=>93, :T_FILE=>14, :T_DATA=>83043, :T_MATCH=>2924, :T_COMPLEX=>1, :T_RATIONAL=>3121, :T_SYMBOL=>1688, :T_NODE=>60999, :T_ICLASS=>11810}

---

I also can get gc profiler data. But what worries me there is that most of the reported data and allocated stuff if from gems that are required and I need anyway.

---

So...

I'm on my way trying to detect memory leaks, or the reason why memory footprint is so high, and reduce it as much as I can. Any advices how to proceed from here are welcome.

It would be nice to understand why after a first click - after restarting - the reported memory by Heroku doubles, though I imagine that it is after that when most of the objects get constructed and memory allocated.

But then the difference between what Oink reports and what Heroku reports is huge, I guess Oink reports in Bytes. And again I imagine that they are reporting different things, or at least Heroku is reporting about much more stuff.

Any good hints how to interpret all this data? Isn't it a 300-400 MB memory footprint too much for a Heroku app?

Thanks.

Answer 1

I got some comments from Heroku support:

It's not unusual for a Unicorn-based Rails app to take about 400MB of RAM. In fact that's probably average for a Unicorn master with preload and two Unicorn request workers. That's three Ruby processes running in the dyno, so you need to be careful about the tool you use to measure it. The log-runtime-metrics will be for the whole dyno, e.g. all three Ruby processes.

So it looks its not that strange for my case. Anyway I'm now paying extra attention to memory allocation and see where I can improve from my side.