puma: High memory usage Heroku (v5)

We’ve repro’d as well on codetriage, will start bisecting soon to figure out which commit it is

Good news everyone! It’s not a bug. It’s a feature! Before I say more. Let’s talk about debugging technique.

Debug process

My web app https://www.codetriage.com was running a beta version of Puma 5 for some time. When Nate put out a call for people who had seen this issue in the wild I asked if it showed up on CodeTriage. Nate deployed v436 and we saw memory use go way down. We’ve got a reproduction!

I then made a list of all the commits between the beta version we were previously on, and a known “low memory” commit. I then manually bisected the list. I deployed, waited ~30 minutes to see if the issue was present and then went higher or lower to zero in on the problem.

• https://github.com/codetriage/CodeTriage/pull/1381
• https://github.com/codetriage/CodeTriage/pull/1382
• https://github.com/codetriage/CodeTriage/pull/1383
• https://github.com/codetriage/CodeTriage/pull/1384
• https://github.com/codetriage/CodeTriage/pull/1385
• https://github.com/codetriage/CodeTriage/pull/1386
• https://github.com/codetriage/CodeTriage/pull/1387
• https://github.com/codetriage/CodeTriage/pull/1388

Towards the end I started posting pictures of memory graphs. In the last one, https://github.com/codetriage/CodeTriage/pull/1388, I describe exactly what I expect to see when I deploy if my theory holds, then I deployed and my theory held.

Here’s a graph:

Look at the right side of the graph. Memory drops a bunch that’s me deploying ae3522cb. When it climbs dramatically, that’s me deploying dc3b9b89.

So what happened in that commit range? It’s only one commit, and it was pretty minor, but it did include this line: https://github.com/puma/puma/blob/bb61c7b151c1610e107f914509cac8bb2a9a8b01/lib/puma/configuration.rb#L188

        :workers => Integer(ENV['WEB_CONCURRENCY'] || 0),

What happened in CodeTriage is that even though I’ve set WEB_CONCURRENCY on my app:

$ heroku run "env | grep WEB_CONCURRENCY"
Running env | grep WEB_CONCURRENCY on ⬢ issuetriage... up, run.3307 (Standard-1X)
WEB_CONCURRENCY=2

I never modified my config to read it in https://github.com/codetriage/CodeTriage/blob/54dddf119a2f81f7e628bfbd09ff678afe782bd7/config/puma.rb. Note the lack of a workers configuration in that file.

So essentially: I had been accidentally running in puma’s “single” mode for the last few years even though I had intended to use processes and modify it via WEB_CONCURRENCY env var. With this commit, now my application is honoring my wishes and is booting two processes.

Good news

The good news is that this increased memory use comes with increased performance. If you look at my graph above, when memory goes down…response time goes up, and the rails autoscale add-on kicks in to scale the app up. When memory goes back up due to more processes, response time goes down and auto-scaling goes down.

So basically: I wasn’t getting the perf I could have gotten out of this dyno if I had utlizing the config that I was setting.

TLDR;

Puma now knows about WEB_CONCURRENCY env var and is honoring the value set on your system. If you’re going above your memory limit’s you’ll need to adjust your WEB_CONCURRENCY value down. If you’re under your memory limits, you likely got increased performance from increased CPU usage that comes with multiple processes that you weren’t getting before. You’ll likely also want to modify your config/puma.rb to be a bit more clear about where the workers value is coming from. Rails generates the config file with this line commented out by default:

# workers ENV.fetch("WEB_CONCURRENCY") { 2 }

I recommend uncommenting this line.

@schneems has narrowed it down to a range of about 4 commits. Should have an idea of the issue soon.

Also, after you’ve got that memory data, what’s the output of heroku logs -n 10000 --app <your app name> | grep --context=8 "Puma starting". You may need to restart your app to get output. I want to see the lines logged when Puma starts.

@markets yes, https://devcenter.heroku.com/articles/usage-and-billing, “Heroku calculates billing based on wall-clock usage”, “All costs are prorated to the second”

Sorry @nateberkopec, I only have access to 24h timeframe (Hobby dyno). I’m going to downgrade to Puma v4.3.6 and tomorrow will post the difference.

Some extra background, in case it’s useful:

• whilst the Ruby buildpack doesn’t (at least currently) set a default WEB_CONCURRENCY value, the Python, Nodejs and PHP Heroku buildpacks do
• they set it via a profile script at .profile.d/WEB_CONCURRENCY.sh in the app’s slug (example)
• the original idea was that users could order their buildpacks such that the “main” language is last, and so the last buildpack’s .profile.d/WEB_CONCURRENCY.sh would win (since it overwrites the versions from earlier buildpacks) - similar to how the buildpacks API uses the bin/release output from only the last buildpack

Sorry for not including that one in the upgrade guide! I had no idea Heroku buildpacks other than Ruby would set WEB_CONCURRENCY. If I did, I definitely would have made this change more obvious in the changelog.

@schneems @dentarg thanks!

yes, I can confirm this comes from the Python buildpack (settings for Gunicorn server):

~ $ grep -r WEB_CONCURRENCY ./.profile.d/*
./.profile.d/WEB_CONCURRENCY.sh:  export WEB_CONCURRENCY=${WEB_CONCURRENCY:-2}
./.profile.d/WEB_CONCURRENCY.sh:  export WEB_CONCURRENCY=${WEB_CONCURRENCY:-4}
./.profile.d/WEB_CONCURRENCY.sh:  export WEB_CONCURRENCY=${WEB_CONCURRENCY:-8}
./.profile.d/WEB_CONCURRENCY.sh:  export WEB_CONCURRENCY=${WEB_CONCURRENCY:-11}
~ $ more ./.profile.d/WEB_CONCURRENCY.sh
case $(ulimit -u) in

# Automatic configuration for Gunicorn's Workers setting.

# Standard-1X (+Free, +Hobby) Dyno
256)
  export DYNO_RAM=512
  export WEB_CONCURRENCY=${WEB_CONCURRENCY:-2}
  ;;

...

Great idea @edmorley. On it!

While this might not have been expected. I think it’s not a bug to be fixed. I think we should keep the current behavior and honor WEB_CONCURRENCY.

@nateberkopec about 12 hours of both versions visible 👇🏼

Hi there, I’m seeing similar spike patterns in memory with Heroku.

With 5.0.0 on Friday 18th:

Then with 5.0.2:

These env vars are not set: WEB_CONCURRENCY, PUMA_MIN_THREADS, PUMA_MAX_THREADS, MIN_THREADS MAX_THREADS

And the logs:

Starting process with command `PROC_TYPE=web bin/start-stunnel bin/puma -C config/puma.rb`
Puma starting in single mode...

We’re on Rails 6.0.3.3, Ruby 2.6.6 if that helps.

Thank you for the amazing work, and I appreciate you’re investigating this bug. Let me know how I can help you further.

Works for me - about 12 hours of both versions visible would really help.