In Progress
Unit 1, Lesson 21
In Progress

Optional Logging

Video transcript & code

It is an inconvenient truth about the world that we can't observe an object or phenomenon without also having an effect on the thing being observed. Nowhere is this more true than in software, where attempts to get a better idea of what is going on inside a program often result in the program behaving differently.

Here's an example. Let's say we have a web application. Every request is accompanied by a user ID. Here we're illustrating that fact by including the user ID in the HTTP output.

get "/" do
  "Hello, user %3d!" % env[:user_id]
end

This application processes requests quite quickly, as we can see if we benchmark it.

$ ab -n 1000 http://localhost:4567/ | grep "Requests per second"
Requests per second:    1478.01 [#/sec] (mean)

As we're developing this application, we start to run into situations where having only a user ID isn't convenient. Sometimes when we are testing out a new feature, or debugging a problem, we really want to be able to see which user is associated with each request.

In order to make this possible, we add a logging line, using the debug log level, which outputs the user associated with the current request.

get "/" do
  logger.debug "Request from user: #{current_user[:name]}"
  "Hello, user %3d!" % env[:user_id]
end

Now when we hit the app with a request for a page, each request dumps out a user's full name.

D, [2015-08-26T13:17:43.510172 #14458] DEBUG -- : Request from user: Miss Serena Bergnaum
D, [2015-08-26T13:17:43.515676 #14458] DEBUG -- : Request from user: Pearlie Auer
D, [2015-08-26T13:17:43.521198 #14458] DEBUG -- : Request from user: Christina Stoltenberg I
...

Of course, as we might expect, this debugging code has terrible implications for the application's performance. Our benchmark results have dropped by an order of magnitude.

 $ ab -n 1000 http://localhost:4567/ | grep "Requests per second"
Requests per second:    135.66 [#/sec] (mean)

But that's OK, this is only for development use. When we're in production, we'll just set the logging level to INFO. (We learned about how to set up a program to use environment variables to control logging in episode #340).

$ LOG_LEVEL=INFO ruby app2.rb

But when we benchmark the app with debug logging turned off, we discover that it is still super slow!

$ ab -n 1000 http://localhost:4567/ | grep "Requests per second"
Requests per second:    153.13 [#/sec] (mean)

What's the problem here?

It turns out, the slowdown isn't caused by dumping text to the console. Our log line slows down each request because it does a database look-up every time, in order to get the attributes of the current user!

logger.debug "Request from user: #{current_user[:name]}"

And it doesn't matter if the debug-level output is suppressed. The log string is still built, which means that the user lookup is still performed.

What do we do about this? Do we have to put some kind of conditional code around our debug logging lines?

As it happens, the writers of the Logger library have anticipated this situation. One of the lesser-known features of logger objects is that instead of passing a string as an argument to logging methods, we can pass a block. This block should return the string to be logged.

How does this make a difference? Well, the string argument was evaluated and interpolated before it ever got to the Logger. But when we pass a block, the Logger does not immediately execute it. Instead, it checks to see if the specified log level is enabled. If so, it evaluates the block and outputs the result. But if not, it throws the block away without ever running it.

get "/" do
  logger.debug { "Request from user: #{current_user[:name]}" }
  "Hello, user %3d!" % env[:user_id]
end

First let's run this new code with all logging levels enabled.

As we can see, every request dumps a user name, and the resulting benchmark is quite slow.

$ ruby app3.rb
Listening on localhost:4567, CTRL+C to stop
D, [2015-08-26T13:32:25.849895 #14696] DEBUG -- : Request from user: Alfonzo Luettgen
D, [2015-08-26T13:32:25.874514 #14696] DEBUG -- : Request from user: Paul Boyle
D, [2015-08-26T13:32:25.886370 #14696] DEBUG -- : Request from user: Jean Wolf DVM
...
$ ab -n 1000 http://localhost:4567/ | grep "Requests per second"
Requests per second:    132.40 [#/sec] (mean)

But when we disable debug logging and run the benchmark again, we see a very different outcome.

$ LOG_LEVEL=INFO ruby app3.rb
Listening on localhost:4567, CTRL+C to stop
$ ab -n 1000 http://localhost:4567/ | grep "Requests per second"
Requests per second:    1345.93 [#/sec] (mean)

Now we are back up in our old performance territory.

One reason developers sometimes shy away from adding lots of informative logging to their applications is that they are afraid of the logs affecting performance. But with optional logging blocks, we can choose we want at runtime. We can have copious output, or we can have maximum speed, all at the flick of a switch.

Happy hacking!

Responses