Tip: Debugging slow Heroku builds
Tiny Tips
It’s always best to follow a systematic approach when trying to speed up slow code.
First, measure the current performance.
Next, make the change that you think will help.
Lastly, measure again to see if the change worked.
It’s no different when it comes to debugging slow test suites or deploys.
I recently noticed that my Heroku deploys were taking nearly 10 minutes to build.
Thanks to a tip from my friend Anthony, I was able to quickly measure, diagnose, and deploy a fix that shaved nearly 4 minutes off every Heroku build. Big win!
Usage
Heroku uses “buildpacks”, which are essentially shell scripts that run to install and configure your server.
You can add multiple buildpacks: it’s common for a Ruby on Rails app to have a Ruby buildpack (for running the Rails app) and a Node buildpack (for building Javascript assets).
But even if you watch the build log as your code changes deploy, there aren’t many affordances for knowing what parts of the process are slow.
Enter the heroku-buildpack-timestamps buildpack!
You can add this buildpack to your Heroku app and it will output timestamps of each step in the process.
2021-05-10 19:30:59
2021-05-10 19:30:59 -----> Creating runtime environment
2021-05-10 19:30:59
2021-05-10 19:30:59 NPM_CONFIG_LOGLEVEL=error
2021-05-10 19:30:59 YARN_PRODUCTION=true
2021-05-10 19:30:59 NODE_ENV=production
2021-05-10 19:30:59 NODE_MODULES_CACHE=true
2021-05-10 19:30:59 NODE_VERBOSE=false
2021-05-10 19:30:59
2021-05-10 19:30:59 -----> Installing binaries
2021-05-10 19:30:59 engines.node (package.json): unspecified (use default)
2021-05-10 19:30:59 engines.npm (package.json): unspecified (use default)
2021-05-10 19:30:59 engines.yarn (package.json): unspecified (use default)
2021-05-10 19:30:59
2021-05-10 19:30:59 Resolving node version 14.x...
2021-05-10 19:31:00 Downloading and installing node 14.17.0...
2021-05-10 19:31:01 Using default npm version: 6.14.13
2021-05-10 19:31:01 Resolving yarn version 1.22.x...
2021-05-10 19:31:01 Downloading and installing yarn (1.22.10)
2021-05-10 19:31:02 Installed yarn 1.22.10
2021-05-10 19:31:03
2021-05-10 19:31:03 -----> Restoring cache
2021-05-10 19:31:03 - node_modules
2021-05-10 19:31:05
2021-05-10 19:31:05 -----> Building dependencies
2021-05-10 19:31:06 Installing node modules (yarn.lock)
2021-05-10 19:31:07 yarn install v1.22.10
2021-05-10 19:34:10 Done in 191.01s.
2021-05-10 19:34:10
2021-05-10 19:34:10 -----> Caching build
2021-05-10 19:34:10 - node_modules
2021-05-10 19:34:17
2021-05-10 19:34:17 -----> Pruning devDependencies
2021-05-10 19:34:17 Skipping because YARN_PRODUCTION is 'true'
I added this buildpack to my staging Heroku app and was able to pinpoint the hot spots in the process. My findings showed that running yarn install was taking 4 minutes, even when there were no Javascript changes between builds.
After identifying the troublesome build step, I decided to turn on the --verbose flag for yarn to see why things were so slow. The official nodejs buildpack is supposed to automatically cache npm packages so it was strange that every build was spending 4 minutes installing.
The --verbose flag generated a huge amount of extra detail to help me find the problem – over 23k lines of logging…
Downloading binary from https://github.com/sass/node-sass/releases/download/v4.13.1/linux-x64-83_binding.node
Cannot download "https://github.com/sass/node-sass/releases/download/v4.13.1/linux-x64-83_binding.node":
HTTP error 404 Not Found
Hint: If github.com is not accessible in your location
try setting a proxy via HTTP_PROXY, e.g.
export HTTP_PROXY=http://example.com:1234
or configure npm proxy via
npm config set proxy http://example.com:8080
Building: /tmp/build_496d129f/.heroku/node/bin/node /tmp/build_496d129f/node_modules/node-gyp/bin/node-gyp.js rebuild --verbose --libsass_ext= --libsass_cflags= --libsass_ldflags= --libsass_library=
Buried deep in the logs was the culprit. We were trying to download a pre-compiled node-sass binary, but it wasn’t found (because Heroku was running Node 14 and the version we asked for was only built for Node 10). After timing out, we then built the native package manually. Aha!
(The fix was to update webpacker).
While this fix was specific to my project, the process is generalizable: measure your Heroku build to find the slow parts, then dig deeper until you can find the underlying problem.
If you find yourself waiting and waiting for your Heroku builds to finish, try adding this buildpack so you can debug why it’s slow.