Tracking execution paths

Earlier this week, I was trying to figure out the path of execution through a big chunk of code. Once you reach a certain size of codebase, tracking which function gets called when can be tricky.

My first thought for dealing with this was to add a message line at the start of each function that I wanted to track. (Note: message, not cat!)

f <- function(...)
{
  message("In 'f'")
  #the function contents...
}

f()

Of course, I don’t always want to track these functions, so to save commenting and uncommenting lines of code, each function needed a verbose argument, to make it optional.

f <- function(..., verbose = getOption("verbose"))
{
  if(verbose) message("In 'f'")
  #the function contents...
}

f(verbose = TRUE)

This code was still a little painful, because I had to change the name of each the function inside each message. Ideally, the message should just know what function it was inside. To get this, some examination of the call stack by sys.call was required.

function_name <- function(which = -1L)
{
  sc <- sys.call(which);
  as.character(substitute(sc))[1L]
}

entry_message <- function(verbose = getOption("verbose"))
{
  if(verbose)
  {
    fname <- function_name(-2L)
    message("In", dQuote(fname))
  }
}

f <- function(..., verbose = getOption("verbose"))
{
  entry_message(verbose)
  #the function contents...
}

f(verbose = TRUE)

This worked, and was fast and was relatively easy to set up, since it is the same code that is being added to each function, making tracking multiple functions easy, as shown in the more complicated (and convoluted) example below.

f <- function(i = 1L, verbose = getOption("verbose"))
{
  entry_message(verbose)
  if(i > 5) return()
  g(i, verbose)
}

g <- function(i, verbose)
{
  entry_message(verbose)
  if(i < 3L) h(i, verbose) else f(i + 1L, verbose)
}

h <- function(i, verbose)
{
  entry_message(verbose)
  g(i + 1L, verbose)
}

f(verbose = TRUE)

It still bugged me though. The fact that analytical code was being polluted with logging code didn’t seem semantically right. What I really wanted was a way to track these functions without inserting any code into them at all. An hour or so of digging about in the manuals and I discovered that I didn’t want to track the functions. In R parlance, I wanted to trace them. And inevitably, there was a trace function to do just that. trace has two different implementations; which version you get depends upon whether more than one argument is passed.

#Two argument version:
trace(c("f", "g", "h"), {})
f(verbose = FALSE)

#One argument version only works for a single function
#so it needs to be wrapped in lapply
lapply(c("f", "g", "h"), trace)
f(verbose = FALSE)

If you want to trace lots of functions, it may be easier to specify them with a regular expression, via apropos.

library(ggplot2)
trace(apropos("geom_"), {})
p <- ggplot(diamonds, aes(carat, price)) +
  geom_point() +
  geom_smooth()