As programmers, debugging is one of our daily tasks. And it’s important to sharpen our debugging skills along with other programming skills. But have you ever noticed that, when we’re getting better and better at refactoring, testing, and other coding skills, our debugging skill doesn’t grow as fast as them? In fact, I found myself still using the same debugging tool and process I used 2, 3 years ago.
In the past few weeks, I tried to find a way to debug more effectively. In this post, I will share the reason why it is so hard to improve our debugging skills and how I come up with another approach to tackle this issue.
(To make it easier to explain, the “Bug” here only refers to a piece of code that breaks a previously working program.)
Table of Content
- How Do We Debug Our Program - Path Comparison Debugging
- Build Execution Paths
- Compare Execution Paths
- The Technical Challenge of This Technic
- Object-Oriented Tracing
- What Is It
- What Problem Does It Solve
- TappingDevice
- Conclusion
How Do We Debug Our Program
The way we usually debug our program is actually very primitive: “Compare”. We do it by comparing how the program should work with how it actually works, and find the places that act differently during the program execution. Most of the time, those places are the keys to finding the bug, if not the bug itself. It’s a 3-steps process:
- Build the Expected Execution Path
- Build the Actual Execution Path
- Compare Both Paths
For example,
Build the Execution Paths
The “Execution Path” of a program can somehow be thought of as its path of method/function calls, or simply call it "call path". But depends on the size of the program, it might perform many method calls. So usually, we only mean “the call path of business logic related methods”. For example, during a request to OrdersController#create
, there can be many method calls like, Array#[]
, Object#inspect
…etc. But when we’re building the execution paths, we only care about those related to Order’s creation and ignore others.
Compare Execution Paths
Under most conditions, the bug of the program can be found in the first place that acts differently (returning a different value, calls different methods…etc.). So in the following case, the bug is probably inside the bar
method or its dependencies.
The Challenge of This Technique
I believe most people debug like this approach, but not exactly the same. Ideally, we should build the execution paths as detailed as possible, so we can have enough information to make an accurate comparison. However, in reality, for reasons like the limit amount of time, or laziness..etc., we usually just pick some methods that we “guess” are related to the bug, and hope we made the right guess. 🤞
It means that the effectiveness of our debugging practices are determined by the method we pick to build the paths. And that can be affected by
- Our experience in the language/framework
- How well do we understand the codebase
- Luck?
This is why we still debug faster over time, even though we don’t put too much attention on our debugging skills.
In my opinion, the root cause of this phenomenon is that we don’t have an efficient tool to work with our debugging strategy. Whether you’re a puts
debugger or a pry
-debugger. For most of the time, inspecting the program’s behavior is an overwhelming job, for several reasons:
-
We need to collect arguments manually
# super annoying def foo(var1, var2) puts("var1: #{var1}") puts("var2: #{var2}") # … end
-
We need to collect return values manually
# eithr def new_cart(attributes) Cart.new(attributes).tap { |c| puts(c) } end # or cart = new_cart(attributes) puts(cart)
We need to jump between different methods, or even files to place the
puts
or breakpoints.
The more manual job it needs to collect information, the more likely we’ll just make a guess and take a chance. Despite being annoying, manually collecting these different kinds of information also creates other problems:
- To collect the information we need effectively (e.g., at the right place, call the right method), we need to understand the program well enough. So the less experienced you are, the harder you can understand the program.
- Adding breakpoints or tracing methods is a kind of code pollution. For example, if a method changes an object’s state and you call it when tracing the code (to get its return value or something), it’d change the program’s behavior.
- In my personal experience, when messing around with the code, it’s easy to forget my original purpose is just to inspect the method call and start digging deeper.
Object-Oriented Tracing
But if we look at our debugging behavior close enough, we can find some patterns that we might take advantage of. For example:
- If you’re debugging a web application’s feature, we can start from a specific endpoint’s logic (e.g., particular controller action). Which gives us a perfect position to start the debugging process.
- In an object-oriented programming language like Ruby, a feature can usually be linked to 1 or a few classes. For example, you know you should look for something like
OrderCreationService
when there’s a bug about orders. So you can build the most of the execution paths by observing one or a few object’s method calls.
And the concept “Object-Oriented Tracing” is built upon the above assumptions and Ruby’s powerful TracePoint
feature. Let me explain it with examples.
Assume we have an OrdersController#create
endpoint for creating orders
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
@order = OrderCreationService.new.perform(@cart, promotion)
……
end
And we want to build the execution path of Order’s creation. We can write
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
TracePoint.new(:call) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
end
end.enable do
@order = OrderCreationService.new.perform(@cart, promotion)
end
Which would print
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:2
Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:6
Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:17
Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:23
Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:27
Now we know what the OrderCreationService
does to create an Order, we have a pretty clear execution path immediately. But with some of Ruby’s meta-programming tricks, we can get more information, like each method call’s arguments!
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
TracePoint.new(:call) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
tp.binding.local_variables.each do |name|
value = tp.binding.local_variable_get(name)
puts(" Arg #{name}: #{value.inspect}")
end
end
end.enable do
@order = OrderCreationService.new.perform(@cart, promotion)
end
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:2
Arg options: {}
Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:6
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:17
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:23
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:27
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:41:51", updated_at: "2020-01-19 08:41:51">
Isn’t this super cool? Now we know what method got called and what arguments they took. Let’s add the last piece of information: the return value.
class OrdersController < ApplicationController
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
TracePoint.new(:return) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
tp.binding.local_variables.each do |name|
value = tp.binding.local_variable_get(name)
puts(" Arg #{name}: #{value.inspect}")
end
puts(" => #{tp.return_value}")
end
end.enable do
@order = OrderCreationService.new.perform(@cart, promotion)
end
Called :initialize from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:4
Arg options: {}
=> {}
Called :validate_cart from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:21
Arg cart: #<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=>
Called :apply_discount from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:25
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=> true
Called :create_order from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:29
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=> #<Order:0x00007f91455ebd10>
Called :perform from /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:13
Arg cart: #<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
Arg promotion: #<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-19 08:59:13", updated_at: "2020-01-19 08:59:13">
=> #<Order:0x00007f91455ebd10>
If you read the above example carefully, you’ll notice that there are other changes in the code and output, except for the return value:
-
TracePoint
now tracksreturn
event, instead of thecall
event like other 2 examples. - The output’s order is somewhat different from the previous ones.
This is because we need to wait for a method call to finish (return) before we can retrieve its return value. So the output is ordered by the time the method is returned, instead of called. For example:
def perform
# …
create_order
end
# call order: perform -> create_order
# return order: create_order -> perform
Once we understand this small difference, this small change in the output won’t confuse us that much. In fact, I sometimes find it more useful in some instances. e.g., when I want to observe how different methods update and return the same value, ordering them with return value makes more sense.
With Object-Oriented Tracing, now we can know the program’s call path, each call’s arguments, and even their return values in a glance. Other than being super-efficient, object-oriented tracing also avoids some problems I mentioned earlier:
- In the past, we need to understand what
OrderCreationService
would call, in order to get inside those methods and collect the information we need. Now we only need to know where wouldOrderCreationService#perform
be called (which is super easy to find). - Unless we need more detailed information or perform some tests on the logic of
OrderCreationService
, we don’t need to touch any line of its code. So we can keep it clean even while debugging.
TappingDevice
Although TracePoint
is already capable of doing what we want, there still are things we can do to make it easier:
- The boilerplate code is quite long (~10 lines). It’s not so easy to remember.
- If you’re not familiar with
TracePoint
, it could take you some time to deal with some edge cases (trust me, I’ve been there before). This means the boilerplate code might end up getting longer to work around those cases.
This is why I created tapping_device to make this easier for you! Do you still remember the code we wrote in the last example? Well, I don’t. And I don’t want to remember it! How about making that piece of code into just one method call? Instead of
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
service = OrderCreationService.new
TracePoint.new(:return) do |tp|
if tp.self.class.name == "OrderCreationService"
puts("Called :#{tp.callee_id} from #{tp.path}:#{tp.lineno}")
tp.binding.local_variables.each do |name|
value = tp.binding.local_variable_get(name)
puts(" Arg #{name}: #{value.inspect}")
end
puts(" => #{tp.return_value}")
end
end.enable do
@order = service.perform(@cart, promotion)
end
# …
end
We only need to add 2 lines now:
include TappingDevice::Trackable # include this
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
service = OrderCreationService.new
print_calls(service) # <— and you only need this now
@order = service.perform(@cart, promotion)
# …
end
And we can get the same information!
:validate_cart # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:8
<= {:cart=>#<Cart id: 1, total: 10, customer_id: 1, promotion_id: nil, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> nil
:apply_discount # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:10
<= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">, :promotion=>#<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> true
:create_order # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:11
<= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> #<Order id: 1, number: nil, total: 5, customer_id: 1, promotion_id: 1, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">
:perform # OrderCreationService
from: /Users/st0012/projects/tapping_device-demo/app/controllers/orders_controller.rb:10
<= {:cart=>#<Cart id: 1, total: 5, customer_id: 1, promotion_id: 1, reserved_until: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">, :promotion=>#<Promotion id: 1, amount: 0.5e1, customer_id: nil, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">}
=> #<Order id: 1, number: nil, total: 5, customer_id: 1, promotion_id: 1, created_at: "2020-01-20 07:09:22", updated_at: "2020-01-20 07:09:22">
In addition to print_calls
, tapping_device also provides different level’s of APIs for different kind of information, like print_traces
Assume we don’t find anything wrong on the OrderCreationService
’s method calls. And we suspect it’s something wrong on the @cart
object. We can use print_traces
to see how it interacts with other parts of the program.
include TappingDevice::Trackable
def create
@cart = Cart.find(order_params[:cart_id])
promotion = Promotion.find_by(id: order_params[:promotion_id])
service = OrderCreationService.new
print_traces(@cart, exclude_by_paths: [/gems/]) # exclude gems so we don’t see ActiveRecord’s internal method calls
@order = service.perform(@cart, promotion)
Passed as 'cart' in 'OrderCreationService#perform' at /Users/st0012/projects/tapping_device-demo/app/controllers/orders_controller.rb:9
Passed as 'cart' in 'OrderCreationService#validate_cart' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:8
Called :reserved_until from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:18
Called :errors from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:9
Passed as 'cart' in 'OrderCreationService#apply_discount' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:10
Called :apply_discount from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:24
Called :total from: /Users/st0012/projects/tapping_device-demo/app/models/cart.rb:6
Called :update! from: /Users/st0012/projects/tapping_device-demo/app/models/cart.rb:6
Passed as 'cart' in 'OrderCreationService#create_order' at /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:11
Called :total from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
Called :customer from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
Called :promotion from: /Users/st0012/projects/tapping_device-demo/app/services/order_creation_service.rb:28
We can not only see what’s been called on @cart
, but we can also see what methods took it as its arguments! This can save you some time when debugging. 😉
If you want to know more about how to use tapping_device to optimize your debugging workflow, you can read its readme to explore different types of useful helpers! You can also see how I used it to address the cause of a Rails issue in Debug Rails issues effectively with tapping_device.
Conclusion
Debugging is mostly about collecting information about how our program works (or used to work). And doing this manually is pretty overwhelming. So as humans, it’s tempting to cheat by guessing how it works in our head and ends up spending more time on the issue.
But with the help of Object-Oriented Tracing, we can take advantage of the paradigm of OOP, and Ruby’s super powerful TracePoint
to enhance our efficiency on inspecting our programs. I believe this can reduce debugging’s painfulness for junior developers, while allows experienced developers to speed up their debugging process largely.
If you have any opinions on this post or tapping_device, please feel free to leave a comment below, I’d love to discuss them with you! Also, if you have a different or better strategy on debugging, please let me know as well ;-)
Top comments (6)
Hi Stan,
This is really a nice article and will help many in debugging.
I was just curious to know if there is a possibility to print only part of the object like few attributes and not entire object. It will help make the trace more readable in cases when objects are huge.
Hello, thanks for the feedback! I guess you were using
print_calls_in_detail
? I've pushed a commit to address that issue. Can you try it by installing the gem with the master branch?This is really cool! I'm definitely adding this to my Ruby tool belt. Thanks for the post and tool!
Hi @st0012 hope your well, are you still using this technique for debugging? And have you come across any similar libraries for javascript/typescript?
Doing some debugging of a framework in javascript and thought this approach would be useful
Very much a work in progress, so has rough edges github.com/mrloop/object-tracer