In Progress
Unit 1, Lesson 21
In Progress

Stack Overflow

Video transcript & code

I meant to cover this in the previous episode, but then I realized that I needed to introduce the TracePoint API first. Now that we're familiar with TracePoint, let's talk about stack overflows.

Ordinarily, Ruby adds a frame to the system stack for every method called or block entered. If you're not familiar with memory stacks and heaps, you can think of the stack as a trail of breadcrumbs the VM leaves behind. Every time it executes a method call, it needs to know what state and instruction to go back to when that method returns.

We can always see the full current stack by calling the caller method with an argument of 0. Here's some code where one method calls another, which calls another, which prints out the current stack trace.

def hello
  greet
end

def greet
  salute
end

def salute
  puts "Salutations from:"
  puts caller(0)
end

hello

# >> Salutations from:
# >> xmptmp-in27856D8J.rb:11:in `salute'
# >> xmptmp-in27856D8J.rb:6:in `greet'
# >> xmptmp-in27856D8J.rb:2:in `hello'
# >> xmptmp-in27856D8J.rb:14:in `<main>'

So every time a method is called, new breadcrumbs are dropped on the system stack. And eventually, if methods keep calling each other without returning, the stack runs out of space. The easiest way to see a stack overflow is to write a method which simply calls itself.

def foo
  foo # ~> SystemStackError: stack level too deep
end

foo

# ~> SystemStackError
# ~> stack level too deep
# ~>
# ~> xmptmp-in278560aZ.rb:2

This code will never return, but it will continually add stack frames. Until eventually, the stack "overflows", which Ruby indicates with a SystemStackError.

It's quite obvious why this method causes a stack overflow. But it's often not nearly so obvious.

Here's one of my favorite sources of non-obvious stack overflows. Here we define method_missing, in order handle messages for which there is no defined method. This code ought to just print out the name of the message that was sent.

But we've made a mistake: there's an extra 's' at the end of putss. As a result, this is now an unknown message send. Which will trigger method_missing, which will call the broken putss, which will trigger method_missing… and so on, until the stack overflows.

def method_missing(method_name, *args)
  putss method_name
end

hello

# !> xmptmp-in27856nXH.rb:2: stack level too deep (SystemStackError)
# !> xmptmp-in27856nXH.rb:2: stack level too deep (SystemStackError)

Other times, stack overflows occur because a long sequence of method calls eventually wraps around and calls itself.

def foo
  bar
end

def bar
  baz
end

def baz
  buz
end

def buz
  faz
end

def faz
  foo
end

foo

# ~> SystemStackError
# ~> stack level too deep
# ~>
# ~> xmptmp-in27856O2Z.rb:14

In this case the error points, somewhat arbitrarily, to line 14. But line 14 doesn't really spell out the full circular sequence of calls that lead to the stack overflow.

This is in Ruby 1.9. Thankfully, Ruby 2.2 improves matters considerably, by capturing the entire stack trace. Although when we see the error dumped to standard out, it elides most of the trace. If the circular sequence of calls is longer than the information shown here, we still may have trouble figuring out what went wrong.

$ ruby circular.rb
circular.rb:22:in `buz': stack level too deep (SystemStackError)
    from circular.rb:18:in `baz'
    from circular.rb:14:in `bar'
    from circular.rb:10:in `foo'
    from circular.rb:26:in `faz'
    from circular.rb:22:in `buz'
    from circular.rb:18:in `baz'
    from circular.rb:14:in `bar'
    from circular.rb:10:in `foo'
     ... 10067 levels...
    from circular.rb:18:in `baz'
    from circular.rb:14:in `bar'
    from circular.rb:10:in `foo'
    from circular.rb:29:in `<main>'

One thing we can do is manually surround the problematic code in a block that explicitly rescues SystemStackError-s. Then we can interrogate the error for its backtrace attribute, which in Ruby 2 contains the full stack trace at the point Ruby ran out of stack.

def foo
  bar
end

def bar
  baz
end

def baz
  buz
end

def buz
  faz
end

def faz
  foo
end

error = begin
          foo
        rescue SystemStackError => e
          e
        end
error.backtrace.size            # => 8736
error.backtrace[87]             # => "xmptmp-in27856pgJ.rb:10:in `baz'"
error.backtrace[1024]           # => "xmptmp-in27856pgJ.rb:2:in `foo'"

The trouble with allowing a stack overflow to play out to the bitter end before debugging it, is that often this isn't an instantaneous process. If the code being infinitely repeated is processor-intensive and/or allocates a lot of objects along the way, executing an infinitely recursive method call may bring our system to a slow, grinding halt before eventually failing with a SystemStackError.

To make it easier to debug stack overflows, here's a snippet of code I learned from Myron Marston. It uses the TracePoint API to hook itself into every method call, and then immediately enable tracing. The hook itself checks the current stack size against a max with every call, and raises a special exception if the max is exceeded.

Because traces can be enabled for the whole program, we don't have to enclose the code causing problems in a special block. We can just insert this tracing code somewhere in system startup, and then wait for the stack size max to be exceeded. Ruby then takes the raised exception and automatically dumps its full stack trace.

By the way, for the sake of example I'm using a pretty small max here. In large applications the stack may normally exceed 100 frames, so you may need to increase this. The original version of this code that I saw from Myron Marston used a max stack size of 500.

def foo
  bar
end

def bar
  baz
end

def baz
  buz
end

def buz
  faz
end

def faz
  foo
end

max_stack_frames = 100
TooManyStackFrames = Class.new(StandardError)

TracePoint.new(:call) do |tp|
  if caller.size >= max_stack_frames
    raise TooManyStackFrames, "Stack has exceeded #{max_stack_frames} frames"
  end
end.enable

foo

# ~> TooManyStackFrames
# ~> Stack has exceeded 100 frames
# ~>
# ~> xmptmp-in27856E2c.rb:26:in `block in <main>'
# ~> xmptmp-in27856E2c.rb:13:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:18:in `faz'
# ~> xmptmp-in27856E2c.rb:14:in `buz'
# ~> xmptmp-in27856E2c.rb:10:in `baz'
# ~> xmptmp-in27856E2c.rb:6:in `bar'
# ~> xmptmp-in27856E2c.rb:2:in `foo'
# ~> xmptmp-in27856E2c.rb:30:in `<main>'

This is a great example of how we can put the TracePoint API to very practical use, to build little tools that help us with our Ruby development. If you've used TracePoint to build any little tools of your own, I'd love to hear about it.

Happy hacking!

Responses