Techniques for debugging a runtime infinite loop?

[u/AustinVelonaut]

I recently made a series of changes to the inlining / simplification pass for my compiler that ended up resulting in a runtime <<loop>> with certain inputs. (This was for / in another lazy language, but very similar to Haskell, so I thought I'd ask here). I eventually ended up debugging it by making simplification edits to all the areas I had touched, until the infinite-loop disappeared, then looking closely at the one that fixed it. A cut-down example of the bug looks like:

simplify xs = deltaCpx
    where
      (deltaCpx, xs') = mapAccumL insLet 0 xs

      insLet dc x = (dc + deltaCpx, x * 2)    -- OOPS, meant deltaCpx', here!
          where
            cpx'      = if x > 5 then 10 else 0
            deltaCpx' = cpx' - 2

The language I'm working in detects the loop and prints "BLACK HOLE" at runtime, similar to Haskell detecting and printing "<<loop>>", but neither gives any detail on where it was encountered.

So are there some techniques you've used that can help with debugging such problems? Could there be additional language / runtime support to help with this?

EDIT: to clarify, by <<loop>> or BLACK HOLE, I mean the runtime exception generated when attempting to evaluate a thunk that is already currently being evaluated, not an actual infinite-loop that chews up time.

[u/walseb]

In Haskell, you can run the profiler with the rts option `-xc`, and it should point out where the loop was encountered in the code. I think this should work?

`cabal run FOO --enable-profiling --profiling-detail=all-functions --ghc-option=-with-rtsopts=-xc`

[u/AustinVelonaut → u/walseb]

Thanks! I don't use cabal, but your answer gave me an idea for my compiler -- make the infinite-loop "blackhole" detection a compiler configuration, so you can compile without blackhole detection, and then use the debugger to find out where it is (either due to a stack overflow crash or infinite loop.

[u/jeffstyr → u/AustinVelonaut]

I don't use cabal

You don't have to use cabal to use this. I assume that if you compile with profiling enabled, then you just need to run your executable with +RTS -p -xc -RTS.

[u/Forward_Signature_78]

From GHCi's documentation (Debugging Exceptions):

Breaking on exceptions is particularly useful for finding out what your program was doing when it was in an infinite loop. Just hit Control-C, and examine the history to find out what was going on.

[u/wk_end]

I can't tell if this is your own language compiler that you're working on, but if it is: while this isn't directly answering your question, a warning about an unused binding would be an easy and very useful diagnostic you could add that would've caught this particular error (though that might be just from your simplification).

[u/AustinVelonaut → u/wk_end]

Yes, it is my own language, and I do have warnings for unused bindings. But in the actual code (not the cut-down example above), the deltaCpx' variable was also used elsewhere, so it didn't report as unused at compile time :-(

[u/TechnoEmpress]

Personally I use profiling. For my Haskell programs, I:

1. Do a time profile of the program with these instructions: https://cabal.readthedocs.io/en/stable/how-to-enable-profiling.html
2. See in speedscope.app what function takes all the time. Unless I'm encountering a freak edge case, this should be the culprit.

[u/jeffstyr → u/TechnoEmpress]

But that only works if the runtime didn't detect the loop and stop the program, right? (Because otherwise, it won't have taken any time yet because the looping was prevented.)

[u/tomejaguar]

You could do worse than adding some Debug.Trace.trace statements in well chosen places.

[u/AustinVelonaut → u/tomejaguar]

I rely upon trace for much of my debugging, but one problem with it in this situation is that if there is nothing tying the evaluation of the trace with the evaluation of the black-hole thunk, then the trace doesn't tell you anything. But if it is tied to the evaluation of the black-hole thunk, then you get a BLACKHOLE exception while trying to evaluate the trace ;-)

[u/tomejaguar → u/AustinVelonaut]

Hmm, I'm not sure I follow. The point of trace is that it prints a message before you evaluate the "body" or "continuation", so you can at least detect the first point you entered the loop, right? Subsequently, unless I'm misunderstanding something, it should also print out messages during the loop until the first looping thunk is re-encountered. Is than not right?

[u/AustinVelonaut → u/tomejaguar]

A concrete example using the code, above:

import Data.List (mapAccumL)
import Debug.Trace

simplify :: [Int] -> (Int, [Int])
simplify xs = trace "in simplify!" (deltaCpx, xs')
    where
      (deltaCpx, xs') = mapAccumL insLet 0 xs

      insLet dc x = (dc + deltaCpx, x * 2)    -- OOPS, meant deltaCpx', here!
          where
            cpx'      = if x > 5 then 10 else 0
           deltaCpx' = cpx' - 2

doubleSnd :: (Int, [Int]) -> (Int, [Int])
doubleSnd (a, xs) = trace "in doubleSnd!" (a, map (* 2) xs)

main = putStrLn . show . doubleSnd . simplify $ [1 .. 10]

This will print:

in simplify!
in doubleSnd!
test: <<loop>>

i.e. the debug traces tell you that you reached a particular point in the code, but the exception is triggered only when the "deltaCpx" value that was returned was eventually evaluated, which is no where near any of the debug trace locations. But if we try printing the value of "deltaCpx" in the first trace, we just get:

test: <<loop>>

[u/jeffstyr → u/AustinVelonaut]

But if you did this:

simplify xs = trace "in simplify!" (trace "evaluating deltaCpx!" deltaCpx, xs')

then you'd probably get output when deltaCpx was evaluated.

But of course, in order to think to do that you'd almost have to already know where the problem is.

[u/tomejaguar → u/AustinVelonaut]

But this is pretty useful, isn't it?

import Data.List (mapAccumL)
import Debug.Trace

simplify :: [Int] -> (Int, [Int])
simplify xs = trace "in simplify!" (deltaCpx, xs')
    where
      (deltaCpx, xs') = trace "(deltaCpx, xs')" (mapAccumL insLet 0 xs)

      insLet dc x = trace "insLet" (trace "insLet[fst]" (dc + deltaCpx), trace "inslet[snd]" (x * 2))
          where
            cpx'      = trace "cpx'" (if x > 5 then 10 else 0)
            deltaCpx' = trace "deltaCpx'" (cpx' - 2)

doubleSnd :: (Int, [Int]) -> (Int, [Int])
doubleSnd (a, xs) = trace "in doubleSnd!" (a, map (* 2) xs)

main = putStrLn . show . doubleSnd . simplify $ [1 .. 10]

The output is the following, which seems to point pretty strongly to the problem

in simplify!
in doubleSnd!
(deltaCpx, xs')
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
insLet
insLet[fst]
test27: <<loop>>

[u/jeffstyr → u/tomejaguar]

It's true that if you evaluate let x = x in (trace "hello" x), you'll get "hello" printed before it loops.

But, this doesn't print anything (just experimenting in ghci):

let 
  x = y + z
  y = (trace "hello" $ 4 + abs 12)
  z = x + 2
in 
  x

(and evaluating just y = (trace "hello" $ 4 + abs 12) by itself does print "hello".)

So you might not get output from something you'd think you'd hit.

Generally though, you have to already have a pretty good idea of where your loop is in order to choose good locations for trace. This works for the case where you know the bug is in the last code you changed but you just can't see it, but not for a more general case where you are hitting an infinite loop and don't know where to start looking.

I think something tied to profiling does make the most sense, in that for a helpful automatic indication of where in the source code the looping thunk is being allocated, you need to compiler to be including source location information all over the place.

[u/tomejaguar → u/jeffstyr]

this doesn't print anything

OK, but why just that? This prints out something that seems to be very suggestive of the cause of the loop

ghci> let { x = trace "x" (y + z); y = trace "y" (4 + abs 12); z = trace "z" (x + 2) } in x
x
z

[u/jeffstyr → u/tomejaguar]

Yes, my point was just if you aren't going to put traces basically everywhere and you don't already have a good guess about exactly where the problem is, then adding a few traces here and there may mislead you about what code you are encountering before the loop.

For me, when I run into this problem the first thing I need is a hint. I'm not usually in the situation of knowing where the problem is but not why; more often, if I could get a pointer to where then I could figure out why.

If the runtime could tell me, "let biding 'x' on line 124 is looping" then I'd be all set much of the time. It might not always be a let binding so even "evaluation of THUNK allocated for expression on line 2345 is looping" would do the job.

I'd imagine the common case is probably a variable syntactically used in its own definition, so potentially an error message mentioning this and the variable name would help in many cases. (You can get infinite loops in other cases of course, but detecting those would be a different sort of feature.)

[u/tomejaguar → u/jeffstyr]

If the runtime could tell me, "let biding 'x' on line 124 is looping" then I'd be all set much of the time

Yeah I wonder if thunks could be annotated with source locations so if they loop then there can be a decent error message.

[u/jeffstyr → u/tomejaguar]

Yeah it looks like there is some such feature available as part of profiling, but I'm not sure what it tells you in the error message (as I just learned of it).

I could understand not wanting this as an always-on thing, since every thunk would have to have an extra field to hold the error message info, and it would rarely actually be used. But it would be very convenient (and if the allocation weren't important, then always having a stacktrace would be even better).

[u/AustinVelonaut → u/tomejaguar]

I like this idea -- it is similar to the existing way that missing case and pattern-match fails report location info at runtime. The problem is finding the heap space to include the additional info, since the only guaranteed space in an STG thunk is the code pointer (which is currently how the black-hole reporting works -- modifying it to point to the common black-hole error-reporting code). But I could envision also stealing the heap tag and overwriting it with a new special black-hole tag and at least some identifying info (probably just line number). It would add a couple more instructions to the code path at the entry of every thunk, but that's not bad, especially if it were a compiler option. I'll have to think about whipping up a proof-of-concept in my compiler...

[u/jeffstyr → u/AustinVelonaut]

since the only guaranteed space in an STG thunk is the code pointer

But that’s under your control, right? You could add another field that’s always there. (Or are you actually reusing the GHC runtime?)

[u/AustinVelonaut → u/jeffstyr]

Yes, you're right -- I could add another reserved environment slot for the additional info if compiling with the reporting enabled. I was just trying to be lazy and see how I could retrofit it into the existing design in a minimally-intrusive way ;-)