SQL statements in Rails logs

Sometimes in programming, the smallest things are the most helpful. I remember wowing a co-worker when I hit CTRL+A and my cursor jumped to the beginning of a long terminal command. Since then, I've vowed that no tip is too small to share. Today, my tip is for getting Rails SQL statements and Cache behavior in production logs locally. It's pretty simple. If you're using rails_12factor gem to output your logs to standard out, then all you need to do is boot up your server with LOG_LEVEL=debug, like this:

$ RAILS_ENV=production LOG_LEVEL=debug rails s

Now you'll get all your SQL statements in the output:

[729e4a51-f83c-4862-bc68-a1842e806696] Started GET "/repotag/rjgit" for ::1 at 2015-10-21 11:47:34 -0500
[729e4a51-f83c-4862-bc68-a1842e806696] Processing by ReposController#show as HTML
[729e4a51-f83c-4862-bc68-a1842e806696]   Parameters: {"full_name"=>"repotag/rjgit"}
[729e4a51-f83c-4862-bc68-a1842e806696]   Repo Load (1.0ms)  SELECT  "repos".* FROM "repos" WHERE "repos"."full_name" = $1 LIMIT 1  [["full_name", "repotag/rjgit"]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Issue Load (83.2ms)  SELECT "issues".* FROM "issues" WHERE "issues"."repo_id" IN (988)
[729e4a51-f83c-4862-bc68-a1842e806696]    (2.0ms)  SELECT COUNT(*) FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]   User Load (1.7ms)  SELECT  "users".* FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1 AND ("users"."private" != 't') LIMIT 27  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered subscribers/_avatars.html.slim (7.4ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   CACHE (0.0ms)  SELECT COUNT(*) FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]    (1.6ms)  SELECT COUNT(count_column) FROM (SELECT  1 AS count_column FROM "users" INNER JOIN "repo_subscriptions" ON "users"."id" = "repo_subscriptions"."user_id" WHERE "repo_subscriptions"."repo_id" = $1 AND ("users"."private" != 't') LIMIT 27) subquery_for_count  [["repo_id", 988]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Issue Load (80.4ms)  SELECT  "issues".* FROM "issues" WHERE "issues"."repo_id" = $1 AND "issues"."state" = $2  ORDER BY created_at DESC LIMIT 20 OFFSET 0  [["repo_id", 988], ["state", "open"]]
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered repos/show.html.slim within layouts/application (132.3ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_head.html.slim (6.5ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_flashes.html.slim (3.5ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_logo.html.slim (9.4ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_nav.html.slim (21.1ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_thoughtbot.html.slim (3.2ms)
[729e4a51-f83c-4862-bc68-a1842e806696]   Rendered application/_footer.html.slim (13.3ms)
[729e4a51-f83c-4862-bc68-a1842e806696] Completed 200 OK in 375ms (Views: 121.2ms | ActiveRecord: 178.6ms)

So, what can you do with that? You get the timing information with each SQL call and each partial render, isolate one that is slow and dig in. You can use EXPLAIN ANALYZE on sql queries to see if you're missing indexes (though, note that the syntax at the end isn't valid SQL, you'll need to manually substitute values). You can use noisey SQL calls to find N+1 queries. There's a wealth of speed info right there in your logs. A

You'll even get cache hit information:

[94ff47da-4ce1-4635-a351-1933801e340c] Started GET "/" for ::1 at 2015-10-21 14:10:16 -0500
[94ff47da-4ce1-4635-a351-1933801e340c] Processing by PagesController#index as HTML
[94ff47da-4ce1-4635-a351-1933801e340c]    (2.4ms)  SELECT COUNT(*) FROM "users"
[94ff47da-4ce1-4635-a351-1933801e340c]    (0.9ms)  SELECT COUNT(*) FROM "repos"
[94ff47da-4ce1-4635-a351-1933801e340c]   Rendered application/_github.html.slim (1.9ms)
[94ff47da-4ce1-4635-a351-1933801e340c]   Rendered application/_down.html.slim (3.0ms)
[94ff47da-4ce1-4635-a351-1933801e340c]   Repo Load (1.1ms)  SELECT DISTINCT language FROM "repos"
[94ff47da-4ce1-4635-a351-1933801e340c]   Repo Load (1.3ms)  SELECT  "repos".* FROM "repos" WHERE (issues_count > 0)  ORDER BY issues_count DESC LIMIT 10 OFFSET 0
[94ff47da-4ce1-4635-a351-1933801e340c]    (0.6ms)  SELECT COUNT(*) FROM "repos" WHERE (issues_count > 0)
[94ff47da-4ce1-4635-a351-1933801e340c]   Cache digest for app/views/repos/_repo.html.slim: aa8c513a57bfdcd94630b4f9de18efe2
[94ff47da-4ce1-4635-a351-1933801e340c]   Cache digest for app/views/pages/_repos_with_pagination.html.slim: c5aef60bba7aa653b57beb58f58905ef
[94ff47da-4ce1-4635-a351-1933801e340c] Cache read_multi: ["views/repos/696-20150302152054739843000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/1224-20150302161524469739000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/297-20150302144607625400000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/987-20150302155234667489000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/186-20150302143211298695000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/839-20150302153126399409000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/845-20150302153500118622000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/1240-20150302161400575160000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/28-20150302140547910840000/c5aef60bba7aa653b57beb58f58905ef", "views/repos/47-20150302141042221265000/c5aef60bba7aa653b57beb58f58905ef"]

Remember, if you're debugging speed issues, you should be running in production mode so that all of your caching is enabled. Otherwise you might spend a good amount of time "fixing" something that is already cached. Oh, and while you're at it, add the bullet gem to your project. You'll be glad you did. That's all. Short and sweet.

Debugging a Memory Leak on Heroku

This is one of the most frequent questions I’m asked by Heroku Ruby customers: “How do I debug a memory leak?” Memory is important. If you don’t have enough of it, you’ll end up using swap memory and really slowing down your site. So what do you do when you think you’ve got a memory leak? What you’re most likely seeing is the normal memory behavior of a Ruby app. You probably don’t have a memory leak. We’ll work on fixing your memory problems in a minute, but we have to cover some basics first.

Keep Reading on Codeship Blog

Who Does your Gem Work For?

Have you ever wondered who out there is using a gem? Now there's an easy way.

Rubygems.org has a reverse dependencies API endpoint that's documented here. I wrote a simple Ruby script that finds all the reverse dependencies of a gem, and then weighs them by total downloads.

To get all the gems that depend on Sprockets you could run this:

require 'net/http'
require 'json'

gem_name = "sprockets"

def rubygems_get(gem_name: "", endpoint: "")
  path = File.join("/api/v1/gems/", gem_name, endpoint).chomp("/") + ".json"
  JSON.parse(Net::HTTP.get("rubygems.org", path))

results = rubygems_get(gem_name: gem_name, endpoint: "reverse_dependencies")

weighted_results = {}
results.each do |name|
    weighted_results[name] = rubygems_get(gem_name: name)["downloads"]
  rescue => e
    puts "#{name} #{e.message}"

weighted_results.sort {|(k1, v1), (k2, v2)| v2 <=> v1 }.first(50).each_with_index do |(k, v), i|
  puts "#{i}) #{k}: #{v}"

Why would you want to see what gems depend on a specific gem? I used this technique when the mime-types gem got some huge memory savings. We wanted consumers of the mime-types gem to update their libraries to take advantage of the savings. I opened pull requests for the top few gems.

You could use this to proactively reach out to other libraries to test out a pre-release of a gem. You could ask other library authors for feedback on an issue or a PR. Having a context around the ways that people use a library can help library maintainers to make better decisions and cause less headaches.

In the sprockets case, I was curious in how the major gems consume sprockets. I have some ideas on ways I can refactor sprockets internals to make it easier to work with, but I want to verify no one is using an edge case of one of the existing APIs. If you were wondering here's the list of all the gems that have ever dependend on sprockets:

0) actionpack: 50617186
1) sass-rails: 25637705
2) coffee-rails: 23370104
3) sprockets-rails: 15753940
4) simplecov-html: 11837362
5) compass-rails: 4425410
6) rails_serve_static_assets: 2864702
7) less-rails: 2446260
8) turbo-sprockets-rails3: 1299855
9) mailcatcher: 960752
10) handlebars_assets: 911169
11) sprockets-sass: 835099
12) middleman: 812834
13) roadie: 700814
14) haml_coffee_assets: 579639
15) cells: 571855
16) sprockets-helpers: 548555
17) gmaps4rails: 533378
18) bare_coffee: 531122
19) sidekiq-failures: 522648
20) middleman-sprockets: 504927
21) konacha: 376161
22) jasmine-headless-webkit: 311860
23) angular-rails-templates: 285348
24) middleman-more: 173457
25) hogan_assets: 159946
26) dashing: 143784
27) hamlbars: 137658
28) css_splitter: 133981
29) alchemy_cms: 124143
30) awestruct: 115661
31) bonethug: 88604
32) jekyll-assets: 86496
33) architecture-js: 86376
34) opal: 82256
35) trackman: 81761
36) sprockets-coffee-react: 80704
37) ruby-haml-js: 80659
38) stylus: 76422
39) rails-sass-images: 74455
40) sprockets-commonjs: 73804
41) fanforce-plugin-factory: 73218
42) alula: 66519
43) browserify-rails: 66436
44) sinatra-asset-pipeline: 64899
45) jquery.fileupload-rails: 64737
46) gumdrop: 64294
47) massimo: 63938
48) fanforce-app-factory: 62385
49) smt_rails: 61075

It's not perfect, but it's good enough for my needs.

Richard blogs here and tweets @schneems, you should follow him because it's his birthday.

Patching Rails Performance

In a recent patch we improved Rails response time by >10%, our largest improvement to date. I'm going to show you how I did it, and introduce you to the tools I used, because.. who doesn’t want fast apps?

Originally posted on the Heroku Engineering Blog

In addition to a speed increase, we see a 29% decrease in allocated objects. If you haven't already, you can read or watch more about how temporary allocated objects affect total memory use. Decreasing memory pressure on an app may allow it to be run on a smaller dyno type, or spawn more worker processes to handle more throughput. Let's back up though, how did I find these optimizations in Rails in the first place?

A year ago Heroku added metrics to the application dashboard. During the internal beta, one of the employees building the product asked if they could get access to my open source app, codetriage, because it was throwing thousands of R14-out of memory errors a day. This error occurs when you go over your allotted RAM limit on Heroku (512 mb for a hobby dyno). Before metrics, I had no clue. As the feature was made available to customers, they became acutely aware that their apps were slow, used lots of swap memory, and threw errors right and left. What should they do to get their apps back in shape?

Initially we recommended reducing the number of web worker processes. For example if you were running 3 Unicorn workers (our recommended webserver at the time) we might suggest you decrease it to 2. This solved the problem for most people. Exposing the RAM usage helped tremendously. Still, customers reported "memory leaks" and overall they weren’t happy with their memory use. When our largest customers started to ask questions, they landed on my desk.

It wasn't long before a customer came forward with an app that performed normally on the surface but started to swap quickly. With the owner's permission I was able to use their Gemfile locally, and started to write a series of re-useable benchmarks to reproduce the problem. A concept similar to my benchmarking rack middleware article, since Rails is a Rack app. I worked on the original concept with Koichi. We were able to isolate that particular issue to a few problematic gems that retained a large amount of memory on boot. Meanwhile Sam Saffron was writing some amazing posts about debugging memory in discourse which eventually spawned memory_profiler. I added the memory_profiler to derailed benchmarks, this is eventually what I used to find hot spots for this performance patch.

I'm responsible for maximizing Ruby developer happiness on Heroku. This can mean writing documentation, patching the buildpack to stop pain points before they happen, or working upstream with popular open source libraries to resolve problems before they hit production. The longer I look at slow code or code with a large memory footprint, the more I see these things as reproducible and ultimately fixable bugs. As I was seeing issues in customer's reported apps and in some of my own, I went to the source to try to fix the issues.

$ derailed exec perf:objects

I ran this benchmark against my Rails app, identified a line that was allocating a large amount of memory, and refactored. In some cases we were using arrays only to join them into strings in the same method, other times we were duplicating a hash before it was merged. I slowly whittled down the allocated object count. Allocating objects takes time. If we modify an object in place without creating a duplicate, we can speed up program execution. Alternatively, we can use a pooled object like a frozen string that never needs to be re-allocated. The test app, codetriage.com, uses github style routes which requires constraints and a "catch all" glob route. Applying these optimizations resulted in a 31% speed increase in url generation for a route with a constraint:

require 'benchmark/ips'
repo = Repo.first

Benchmark.ips do |x|
  x.report("link_to speed") {
    helper.link_to("foo", app.repo_path(repo))

The routing improvements combined with all the other savings gives us a speed boost of more than 10%. The best part is, we don't have to change the way we write our Rails app, you get these improvements for free by upgrading to the next version of Rails. If you're interested in where the savings came from, look at the individual commits which have the methodology and object allocation savings for my test app recorded.

Working with Rails has made me a better developer, more capable of debugging library internals, and helped our Ruby experience on the platform. Likewise having a huge number of diverse Rails apps running on the platform helps us be aware of actual pain points developers are hitting in production. It feels good when we can take these insights and contribute back to the community. Be on the lookout for the Rails 5 pre-release to give some of these changes a try. Thanks for reading, enjoy the speed.

If you like hording RAM, maximizing iterations per second, or just going plain fast follow @schneems.

Adventures in Paternity Leave

It started screaming for life. Sucking in air and yelling out with a beautiful pain. I couldn't stop smiling.

I didn't know what paternity leave was until I was already there. We spent months taking classes about labour and raising a newborn. We read books, and grilled friends for tips and product recommendations. Rarely if ever, did conversation turn towards paternity leave. Of everyone I talked to, I was the only one that actually had an official "paternity leave", everyone else had "vacation". All the fathers I spoke with took at least a little time off, though most seemed to only be able to muster 1 week out of their accrued bucket. In comparison, my company offered me 4 weeks of paternity at 80% pay.

Most people can conceptualize a maternity leave. We understand that it is necessary for the Mother's body to heal, and for nursing a baby. What exactly does one do during a paternity leave? It's basically vacation for the Dad, right?

We've got a system set up where my wife is in charge of feeding the baby, and healing. I try to tackle everything else in the baby realm. This means dressing, changing, swaddling, and cleaning. Before we go out, I pack the diaper bag, and strap the baby into the carrier. I try to anticipate things our baby needs and accomplish them before they're too urgent. I started doing this for my wife, in order to take the load and worry off her, but it had an unexpected benefit - a closer bond with my son. I've always thought newborns were boring, but having one changed my mind. Every day is a small, if hardly noticeable growth, that is only visible through constant vigilance.

My schedule looks like this: I usually go to bed at around 10 depending on how much sleep I got the night before, but sometimes as early as 8. We swaddle, change, and nurse the baby, and put him in a bassinet by our bed. Every 1~2 hours he'll wake up to be fed. My wife feeds him, I change him, burp him a little, and do any necessary clothing changes. I try to see to any needs my wife has if I can. The biggest one is refilling water (I highly recommend a thermally insulated spill-proof water bottle like camelbak podium). Best case scenario: we go back to sleep for a few hours. Worst case: a few minutes. I try to combat the fatigue by napping during the day, or by going to bed earlier and not getting out of bed until later. Once I get "up" I make coffee and bring my wife food when she's ready. We are lucky enough to have family staying with us, so I don't have to prepare meals or clean.

It's hard to say what I do during the day. We still go through the same changing-feeding schedule, but it doesn't seem as bad as when you're not having to wake up. Even with naps and and early bedtime, I often find myself so drained that I can't really focus on a task for too long. I had anticipated more downtime during paternity leave. We purposefully didn't watch season 3 of "House of Cards" so we could binge it during this time, but we've not even watched the first episode. The best way I could describe life when we're awake, is things seem to take 4x as long. Before, leaving the house took 15 minutes. Now it takes 1 hour. I've taken the opportunity to do some basic handy-person tasks in my backlog, such as changing my car's cabin air filter, and doing some work on my bedroom vents so the baby won't be cold at night. Even so, I find it difficult to heavily focus on one task for very long. Even after a good night, when I'm not exhausted, my attention is always split. I always have to be ready to drop what I'm doing and switch to baby gear. While I could imagine myself already back at work for a week, I can't imagine it being healthy for me, my relationship with my wife, or my employer. In an industry chalk full of burnout, I can't imagine anything more burnout inducing than showing up at work sleep deprived, and worrying about your little one when someone is demanding you to stay late to file your TPS report. My time away has been no vacation, but the ability to focus my life's energy on a single undivided task has been greatly rewarding.

One of the hardest things about taking time off has been acknowledging that I can be replaced in my company, and taking active steps to make that replacement easier. I think this is a large reason many men don't take a long break after a child's birth even when they can. They think, "How will this place run without me? I'm really needed here". It feels great to be needed by a team, or a department, or a company. It can be hard to feel needed when you're deep in a diaper full of shit. Don't make your partner pull unnecessary double duty if they don't have to.

Since pregnancy, I've started looking at "job security" a little differently. If you're so irreplaceable, how could someone ever promote you? The most critical members of the team aren't those that single-handedly hold up the keystone, but those that lay down pillars of brick to help prop up their teammates.

A large portion of my job is supporting customers, so during the months before I left, I took deliberate time to document problems and fixes so others on my team would know how to handle them. The kind of things you don't bother writing down because you know them so well. After publishing several documents and sharing with support, I was surprised to find it helped me even before going on leave by decreasing ticket count. With a hard deadline and a clear set of handoffs it's hard to fudge things. I think my wife did a much better job preparing for the leave. She hired 2 employees and successfully delegated most of her job to 4 separate employees. She frequently says to me, "Getting pregnant was the best thing that ever happened to me professionally." Even if you're not going to have a kid, I think it's a good thought experiment the next time you request a pay raise. Talk about all the ways you've made yourself redundant. If you got promoted today, could someone take over your job? Why, or why not?

P.S. I've only ever had one person ask me if I was going to go back to work after the baby (yes), versus the countless numbers that asked my wife (yes). If you want to ask maybe try "Are both of you going back to work?" or "what's your child care plan after leave?" The best intended questions come with some of the worst pre-defined judgments.

Honestly there are too many things to share to make this a very focused post. I really wanted to talk about what it's like to have some time to spend bonding with your partner and a new child. For me it's been incredibly empowering. I can't imagine coming home from an 8 hour day, then having to wake up every hour, change a 'poopy' diaper, and not feel any resentment. My time off came with the opportunity to grow with my family instead of us falling apart. If you've taken paternity leave or know someone who has, please encourage them to share their story-both good and bad. If you're a male who is planning to have kids, ask your company if they have paternity leave or if they would consider adding the benefit. I think that men should take pride in being involved with their family. We can be incredibly involved in raising a child, even from an early age.