Optimize Your Debugging Process With Object-Oriented Tracing and tapping_device

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

1. How Do We Debug Our Program - Path Comparison Debugging
   1. Build Execution Paths
   2. Compare Execution Paths
   3. The Technical Challenge of This Technic
2. Object-Oriented Tracing
   1. What Is It
   2. What Problem Does It Solve
   3. TappingDevice
3. 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:

1. Build the Expected Execution Path
2. Build the Actual Execution Path
3. 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

1. Our experience in the language/framework
2. How well do we understand the codebase
3. 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:

1. We need to collect arguments manually
   

   # super annoying
   def foo(var1, var2)
     puts("var1: #{var1}")
     puts("var2: #{var2}")
     # …
   end
   

2. 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)
   

3. 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:

1. 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.
2. 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.
3. 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:

1. 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.
2. 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:

1. TracePoint now tracks return event, instead of the call event like other 2 examples.
2. 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:

1. 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 would OrderCreationService#perform be called (which is super easy to find).
2. 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:

1. The boilerplate code is quite long (~10 lines). It’s not so easy to remember.
2. 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 ;-)

Comments

[rohit]

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.

[Stan Lo]

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?

gem "tapping_device", github: "st0012/tapping_device"

[Corey Alexander]

This is really cool! I'm definitely adding this to my Ruby tool belt. Thanks for the post and tool!

[Ewan McDougall]

Hi @st0012 hope your well, are you still using this technique for debugging? And have you come across any similar libraries for javascript/typescript?

[Ewan McDougall]

Doing some debugging of a framework in javascript and thought this approach would be useful

[Ewan McDougall]

Very much a work in progress, so has rough edges github.com/mrloop/object-tracer