Print debugging has its place. Sure, it’s not always the best way to debug something, but it can often be the fastest. In this post I describe a useful way to do this in Rust and how we can get similar behaviour in R.
I love the Rust dbg!
macro - it wraps a value or expression and prints the result to help debug
what’s happening in the middle of some function. If we had some complicated
function that combined some values, e.g.
fn f(val1: i32, val2: i32) -> i32 {
// do some things
let otherval: i32 = 10;
// final result
val1 + val2 + otherval
}
fn main() {
println!("final result = {}", f(5, 6))
}Running this gives just the final result, as expected
final result = 21We might want to check on what the intermediate combinations of otherval and val1
or val2 (terrible names, I know). One option is to just print them
fn f(val1: i32, val2: i32) -> i32 {
// do some things
let otherval: i32 = 10;
println!("{}", otherval + val1);
println!("{}", otherval + val2);
// final result
val1 + val2 + otherval
}
fn main() {
println!("final result = {}", f(5, 6))
}Running this shows the values we printed, but with no context
15
16
final result = 21We could add some context manually
fn f(val1: i32, val2: i32) -> i32 {
// do some things
let otherval: i32 = 10;
println!("first temp val = {}", otherval + val1);
println!("second temp val = {}", otherval + val2);
// final result
val1 + val2 + otherval
}
fn main() {
println!("final result = {}", f(5, 6))
}producing
first temp val = 15
second temp val = 16
final result = 21but across an entire codebase, this is going to get messy, fast.
A better option is the dbg! macro, which takes an expression (a value, or
something that produces a value) and prints both the expression itself and the resulting
value
fn f(val1: i32, val2: i32) -> i32 {
// do some things
let otherval: i32 = 10;
dbg!(otherval + val1);
dbg!(otherval + val2);
// final result
val1 + val2 + otherval
}
fn main() {
println!("final result = {}", f(5, 6))
}Running this produces
[src/main.rs:15] otherval + val1 = 15
[src/main.rs:16] otherval + val2 = 16
final result = 21and we see we get the file/linenumber context, the expression we wrapped, and the value.
This is extremely useful, and helps me to figure out what’s going on in the middle of some implementation.
One of the downsides is that even if I make a release build, these statements remain, so I need to go through and remove them all once I’m finished debugging.
A “better” solution is to use a full logging solution like the
log crate which enables using different log
levels, turning off logging outside of some threshold, etc… but that seems
more suited to intentional logging, not debugging something that isn’t
working.
Having played with this in Rust, of course I wanted the same thing in R. I built a minimal viable proof-of-concept which leverages {rlang} to capture the expression
dbg <- function(x) {
ex <- rlang::f_text(rlang::enquos(x)[[1]])
ret <- rlang::eval_bare(x)
message(glue::glue("DEBUG: {ex} = {ret}"))
ret
}This works rather well - it postpones evaluation of the expression and prints the result without affecting any variables
a <- 1
b <- 3
x <- dbg(a + b)## DEBUG: a + b = 4y <- dbg(2*x + 3)## DEBUG: 2 * x + 3 = 11z <- 10 + dbg(y*2)## DEBUG: y * 2 = 22z## [1] 32It lacks one beautiful part of the Rust solution, though - if I include this in some functions sourced from a file, I won’t be able to tell which file the statement came from. Plus, it doesn’t deal so well with large structures
x <- dbg(head(mtcars))## DEBUG: head(mtcars) = c(21, 21, 22.8, 21.4, 18.7, 18.1)DEBUG: head(mtcars) = c(6, 6, 4, 6, 8, 6)DEBUG: head(mtcars) = c(160, 160, 108, 258, 360, 225)DEBUG: head(mtcars) = c(110, 110, 93, 110, 175, 105)DEBUG: head(mtcars) = c(3.9, 3.9, 3.85, 3.08, 3.15, 2.76)DEBUG: head(mtcars) = c(2.62, 2.875, 2.32, 3.215, 3.44, 3.46)DEBUG: head(mtcars) = c(16.46, 17.02, 18.61, 19.44, 17.02, 20.22)DEBUG: head(mtcars) = c(0, 0, 1, 1, 0, 1)DEBUG: head(mtcars) = c(1, 1, 1, 0, 0, 0)DEBUG: head(mtcars) = c(4, 4, 4, 3, 3, 3)DEBUG: head(mtcars) = c(4, 4, 1, 1, 2, 1)At some point I saw a blog
post
about a debug logging package {icecream}
which had this ability of tracing the srcref of a file containing the debug
statement, so I wanted to see if I could extract that to suit my needs. Running
the ic() statement as a print debugger works nicely
f <- function(val1, val2) {
otherval <- 10
icecream::ic(otherval + val1)
icecream::ic(otherval + val2)
val1 + val2 + otherval
}
f(5, 6)## ℹ ic| `otherval + val1`: num 15## ℹ ic| `otherval + val2`: num 16## [1] 21it indeed wraps the expression and shows the result. After poking around at the internals, I realised it actually does everything that I wanted, I just needed to change some of the defaults
options(icecream.peeking.function = utils::head,
icecream.max.lines = 5,
icecream.prefix = "dbg:",
icecream.always.include.context = TRUE)Now it prints like the dbg! macro
f <- function(val1, val2) {
otherval <- 10
icecream::ic(otherval + val1)
icecream::ic(otherval + val2)
val1 + val2 + otherval
}
f(5, 6)## ℹ dbg: `f()` in <env: global> | `otherval + val1`: [1] 15## ℹ dbg: `f()` in <env: global> | `otherval + val2`: [1] 16## [1] 21To make it even more like the Rust macro, I made a similar binding of .dbg (so
that it doesn’t appear in my workspace by default) and added the following to my
.Rprofile
# install.packages("icecream")
if (requireNamespace("icecream", quietly = TRUE)) {
.dbg <- icecream::ic
options(icecream.peeking.function = utils::head,
icecream.max.lines = 5,
icecream.prefix = "dbg:",
icecream.always.include.context = TRUE)
}so now I can add debug statements
f <- function(val1, val2) {
otherval <- 10
.dbg(otherval + val1)
.dbg(otherval + val2)
val1 + val2 + otherval
}
f(5, 6)## ℹ dbg: `f()` in <env: global> | `otherval + val1`: [1] 15## ℹ dbg: `f()` in <env: global> | `otherval + val2`: [1] 16## [1] 21Better yet, I can turn them off if I don’t need them
icecream::ic_disable()
f(5, 6)## [1] 21This works as I had hoped; I can even debug partway through an expression
icecream::ic_enable()
3 + .dbg(4 + 6)## ℹ dbg: <env: global> | `4 + 6`: [1] 10## [1] 13and if I source a file, I get the context
## test_dbg.R:
f <- function() {
x <- 7
.dbg(x + 3)
7
}source("test_dbg.R")
f()ℹ dbg: `f()` in test_dbg.R:3:2 | `x + 3`: [1] 10[1] 7It even deals with printing larger objects, given the “peeking_function” and “max lines” options above
.dbg(mtcars)## ℹ dbg: <env: global> | `mtcars`:
## mpg cyl disp hp drat wt qsec vs am gear carb
## Mazda RX4 21.0 6 160 110 3.90 2.620 16.46 0 1 4 4
## Mazda RX4 Wag 21.0 6 160 110 3.90 2.875 17.02 0 1 4 4
## Datsun 710 22.8 4 108 93 3.85 2.320 18.61 1 1 4 1
## Hornet 4 Drive 21.4 6 258 110 3.08 3.215 19.44 1 0 3 1That seems to be feature-equivalent to the Rust dbg! macro, plus the ability to
turn off the messages, so I’m very happy with this result.
Do you have a better solution? I can be found on Mastodon or use the comments below.
devtools::session_info()
## ─ Session info ───────────────────────────────────────────────────────────────
## setting value
## version R version 4.1.2 (2021-11-01)
## os Pop!_OS 22.04 LTS
## system x86_64, linux-gnu
## ui X11
## language (EN)
## collate en_AU.UTF-8
## ctype en_AU.UTF-8
## tz Australia/Adelaide
## date 2023-11-07
## pandoc 3.1.8 @ /usr/lib/rstudio/resources/app/bin/quarto/bin/tools/x86_64/ (via rmarkdown)
##
## ─ Packages ───────────────────────────────────────────────────────────────────
## package * version date (UTC) lib source
## blogdown 1.17 2023-05-16 [1] CRAN (R 4.1.2)
## bookdown 0.29 2022-09-12 [1] CRAN (R 4.1.2)
## bslib 0.5.1 2023-08-11 [3] CRAN (R 4.3.1)
## cachem 1.0.8 2023-05-01 [3] CRAN (R 4.3.0)
## callr 3.7.3 2022-11-02 [3] CRAN (R 4.2.2)
## cli 3.6.1 2023-03-23 [3] CRAN (R 4.2.3)
## crayon 1.5.2 2022-09-29 [3] CRAN (R 4.2.1)
## devtools 2.4.5 2022-10-11 [1] CRAN (R 4.1.2)
## digest 0.6.33 2023-07-07 [3] CRAN (R 4.3.1)
## ellipsis 0.3.2 2021-04-29 [3] CRAN (R 4.1.1)
## evaluate 0.21 2023-05-05 [3] CRAN (R 4.3.0)
## fansi 1.0.4 2023-01-22 [3] CRAN (R 4.2.2)
## fastmap 1.1.1 2023-02-24 [3] CRAN (R 4.2.2)
## fs 1.6.3 2023-07-20 [3] CRAN (R 4.3.1)
## glue 1.6.2 2022-02-24 [3] CRAN (R 4.2.0)
## htmltools 0.5.6 2023-08-10 [3] CRAN (R 4.3.1)
## htmlwidgets 1.5.4 2021-09-08 [1] CRAN (R 4.1.2)
## httpuv 1.6.6 2022-09-08 [1] CRAN (R 4.1.2)
## icecream 0.2.1 2023-09-27 [1] CRAN (R 4.1.2)
## jquerylib 0.1.4 2021-04-26 [3] CRAN (R 4.1.2)
## jsonlite 1.8.7 2023-06-29 [3] CRAN (R 4.3.1)
## knitr 1.43 2023-05-25 [3] CRAN (R 4.3.0)
## later 1.3.0 2021-08-18 [1] CRAN (R 4.1.2)
## lifecycle 1.0.3 2022-10-07 [3] CRAN (R 4.2.1)
## magrittr 2.0.3 2022-03-30 [3] CRAN (R 4.2.0)
## memoise 2.0.1 2021-11-26 [3] CRAN (R 4.2.0)
## mime 0.12 2021-09-28 [3] CRAN (R 4.2.0)
## miniUI 0.1.1.1 2018-05-18 [1] CRAN (R 4.1.2)
## pillar 1.9.0 2023-03-22 [3] CRAN (R 4.2.3)
## pkgbuild 1.4.0 2022-11-27 [1] CRAN (R 4.1.2)
## pkgload 1.3.0 2022-06-27 [1] CRAN (R 4.1.2)
## prettyunits 1.1.1 2020-01-24 [3] CRAN (R 4.0.1)
## processx 3.8.2 2023-06-30 [3] CRAN (R 4.3.1)
## profvis 0.3.7 2020-11-02 [1] CRAN (R 4.1.2)
## promises 1.2.0.1 2021-02-11 [1] CRAN (R 4.1.2)
## ps 1.7.5 2023-04-18 [3] CRAN (R 4.3.0)
## purrr 1.0.1 2023-01-10 [1] CRAN (R 4.1.2)
## R6 2.5.1 2021-08-19 [3] CRAN (R 4.2.0)
## Rcpp 1.0.9 2022-07-08 [1] CRAN (R 4.1.2)
## remotes 2.4.2 2021-11-30 [1] CRAN (R 4.1.2)
## rlang 1.1.1 2023-04-28 [1] CRAN (R 4.1.2)
## rmarkdown 2.24 2023-08-14 [3] CRAN (R 4.3.1)
## rstudioapi 0.15.0 2023-07-07 [3] CRAN (R 4.3.1)
## sass 0.4.7 2023-07-15 [3] CRAN (R 4.3.1)
## sessioninfo 1.2.2 2021-12-06 [1] CRAN (R 4.1.2)
## shiny 1.7.2 2022-07-19 [1] CRAN (R 4.1.2)
## stringi 1.7.12 2023-01-11 [3] CRAN (R 4.2.2)
## stringr 1.5.0 2022-12-02 [1] CRAN (R 4.1.2)
## urlchecker 1.0.1 2021-11-30 [1] CRAN (R 4.1.2)
## usethis 2.1.6 2022-05-25 [1] CRAN (R 4.1.2)
## utf8 1.2.3 2023-01-31 [3] CRAN (R 4.2.2)
## vctrs 0.6.3 2023-06-14 [1] CRAN (R 4.1.2)
## xfun 0.40 2023-08-09 [3] CRAN (R 4.3.1)
## xtable 1.8-4 2019-04-21 [1] CRAN (R 4.1.2)
## yaml 2.3.7 2023-01-23 [3] CRAN (R 4.2.2)
##
## [1] /home/jono/R/x86_64-pc-linux-gnu-library/4.1
## [2] /usr/local/lib/R/site-library
## [3] /usr/lib/R/site-library
## [4] /usr/lib/R/library
##
## ──────────────────────────────────────────────────────────────────────────────