Chapter 8 | Debugging and Profiling

print and cat

Both print() and cat() print a string, but several differences exist between these functions:

• print() is a generic method which looks at the class of its first argument and dispatches a different method depending on which class the first argument is. If no method is found, R uses print.default. Cat simply returns any object as it is. As an example we can consider any object belonging to a class with a print method related to that class:

• print() requires paste() to concatenate strings, while cat() concatenates strings before outputting any result:

• cat() interprets character strings that it gets.

Browsing

Function browser() is usually called from within an other function. When the evaluator encounters this function it opens a browsing session on the evaluated frame so that the active environment can be explored.

All R commands can be used within the evaluated frame. Moreover, the interpreter, sets up special functions to be called uniquely within the browser() environment:

• n advances to the next step;
• c continues to the end of the current section of code (e.g., to the end of a for loop, or the end of the function itself);
• where prints a stack trace of all active function calls;
• Q exits the browser and the current evaluation and return to the top-level prompt.

As an example, consider the function below. It ouputs the sum of a given parameter plus two random numbers. In order to see the value of the two random numbers: rn and ru prior summing them up, the function evaluated frame is inspected by inserting a call to function browser within the function body.

The use of browser() finds its best application when called by function debug().

Post Mortem Debugging

Classical debugging is named Post Mortem as the error function is debugged after the evaluator returns a critical error so that the execution of the function is interrupted. Function debug() is the most used debugging tool.

Function debug() allows stepping through the execution of a function, line by line. At any step a browser() is opened on the evaluation frame.

As an example, consider this simple function:

This function simply prints “Hello” or “Goodbye” depending on whether x is greater than or less than 0. In principle, this function should never fail; nevertheless:

this function returns an error and the execution is halted. As a first step, a call to traceback() is always worth:

In this case, traceback() does not help a lot. It simply says that the error occurs within the call to msg(). Not a big surprise as, msg() was the only function called.

The use of functions debug() or debugonce() returns interesting results:

As it can be observed, log(-1) produces a simple warning and returns NaN but, passing the resulting value of x into msg() ended in a fatal error as the comparison between NaN and 0 is clearly undefined and returns NA that, in tur, returns an error like the following:

Finally, debugonce() is clearly used to debug a function at its next call. When using debug(), the function passed as an argument is set into “debug mode” and it is kept in the same mode until undebug() is called on the same function. Function isdebugged() is used to query the debugging flag on a function.

In more complex situation, the use of traceback() after a call stack may result into a very useful debugging tool. Suppose we define functions f(), g() and h() as:

when calling the outer function f():

The error seems to be generated within function f(). And this is partially true as the error is actually generated within function h() as f() calls g() that calls h(). All this mechanism is not always transparent to the end user as the inner mechanism of a function is not necessarily known. A simple call to traceback may quickly put the truth into evidence:

The output of traceback() is to be read bottom-up or by following the output row number. In this case, traceback() says that the error occurs within function h(). As a result, function h() can be put into debug mode and f(-1) be called again:

The error clearly occurs in function h() as NA within an if statement returns error.

In case we simply put f() directly into debug mode instead of running traceback() first, the result would be useless:

Debugging on error

When the evaluator encounters an error, it looks for an error action. The error action, a function or an expression to be evaluated, is determined by the error argument of the options, by default set to NULL:

By setting:

the evaluator stops whenever an error occurs and calls function recover() which, in turn, offers a selection of available frames for browsing. By selecting 0, recovering is exited and the normal prompt is returned.

Debugging on error is clearly a useful techniques when running R in interactive mode. When calling R in BATCH mode, interactive debugging is of no use. In this case a call to dump.frames() provides the right solutions as the evaluated frame is dumped into a file, last.dump by default, to be lately inspected by function debugger(). Again, dump.frame() is set as the error argument to function options().

The error can now be inspected, as in interactive mode. The whole working environment has been dumped to file fdump that can be loaded, at any time, by function debugger():

Finally, during development, setting options("error") as:

could help to take advantage of both solutions.

Rprof

As a main tool for profiling R code we make use of function Rprof().

As a basic example to demonstrate Rprof() capabilities we consider a trivial function f1() written a inefficient for() loop fashion:

When running f1() on a large vector x it may require a significant amount of computing time:

In order to understand if any bottle neck exists within f1() we may want to profile function f1() by using function Rprof().

Function Rprof() is used to control profiling. Profiling works by recording at fixed intervals, by default every 20 msecs, which line in which R function is being used and records the results in a file passed as argument to Rprof(). Function summaryRprof() can then be used to summarize the activity.

We can observe that function c() takes 25.52 seconds corresponding to 96.67 per cent of the total execution time. This is because of the wrong usage we are making of function c() within f1() when computing y <- c(y, tmp). At each iteration R is forced to copy vector y in a larger memory space to allocate the longer vector.

We can avoid this multiple copying of y by simply defining in advanced the length of vector y:

and, if we run Rprof() again:

we can observe that the execution time is now down to 0.74 seconds and that rnorm() is taking a sensible amount or time.

In case we want to evaluate the gain in efficiency by using lapply() instead of a for() loop we could rewrite f2() as:

and profile this functions as usual by:

Note that in this case, function f2() takes 0.74 seconds while function f3() requires 0 seconds.

We can make full use of R vectorized capabilities and write:

We can now profile this functions as usual by:

We see can see no specific bottle necks and a very fast function:

Finally, as a whole, function summaryRprof() returns a list of four components:

Table $by.self lists the time spent by functions alone, while the table $by.total lists the time spent by functions and all the functions they call. In the f2() simple case, function f2() itself just takes 0.22 seconds to do things like:

• initialize its own execution environment
• filling it up with promises arguments
• starting the execution of its body

while the same function remains active until the end of the execution: 0.74 seconds. The lines marked with .External refer to calls to external C or Fortran code.

rbenchmark

Library rbenchmark is intended to facilitate benchmarking of arbitrary R code.

The library consists of just one function, benchmark(), which is a simple wrapper around system.time().

Given a specification of the benchmarking process: counts of replications, evaluation environment and an arbitrary number of expressions, benchmark evaluates each of the expressions in the specified environment, replicating the evaluation as many times as specified, and returning the results conveniently wrapped into a data frame.

As a first case we can compare the differece in performaces between sapply() and vapply() when applied to a simple mathematical function:

and observe the gain in performances of vapply() compared with sapply()

As a second example, we can consider the calculation of the 95% quantile of the distribution of the correlation coefficient between two N(0,1) vectors of given sizes n=10.

As a first case we define a function f_loop() by using a simple for loop over k iterations.

As a second case we develop the same function using a functional approach based on replicate()

As a third case we introduce a function matrix() within replicate():

Once the three functions have been defined we can compare them by using rbenchmark()

We can see that all functions, despite the different programming styles, have very similar performances.