Tracking chunk execution times in Quarto book

[isaactpetersen]

Description

I'm trying to track chunk execution times (via the terminal/log in GitHub Actions and via a log file) for a Quarto book. Using my setup chunk (see below), I am able to get it to work for the index.qmd chapter (it successfully reports and logs the execution times for that chapter), but it doesn't work for the other chapters. I believe this may be related to Quarto running each chapter independently. I presumably could add the code chunk to the beginning of each chapter, but my hope is that there is a more straightforward way of accomplishing that. I am aware of the section of the R Markdown Cookbook, "Report how much time each chunk takes to run". However, I'm not quite sure how to adapt it to my Quarto book.

Here is my "setup" chunk of the index.qmd file, which is the first chunk of the first chapter:

```{r}
#| label: setup
#| include: false

# Global knitr options
knitr::opts_chunk$set(
  time = TRUE,
  message = NA # Show in console, not in rendered output
)

# Null coalescing operator
`%||%` <- function(a, b) if (!is.null(a)) a else b

# Log file setup
log_file <- "chunk-times.txt"
if (file.exists(log_file)) file.remove(log_file)

# Environment to track start times
.chunk_times_env <- new.env()

# Timing hook
knitr::knit_hooks$set(time = function(before, options) {
  label <- options$label %||% "<unnamed>"
  
  if (before) {
    .chunk_times_env[[label]] <- Sys.time()
  } else {
    start_time <- .chunk_times_env[[label]]
    if (!is.null(start_time)) {
      elapsed <- difftime(Sys.time(), start_time, units = "secs")
      msg <- sprintf("Chunk `%s` ran in %.2f seconds.", label, as.numeric(elapsed))
      
      # Send message to GitHub Actions log
      message(sprintf("::notice title=Chunk Time::%s", msg))
      
      # Also save to file
      cat(msg, file = log_file, append = TRUE, sep = "\n")
    }
  }
})
```

There is already a feature request for tracking chunk execution times in Quarto: #5179. I also had to follow some advice in the thread on getting messages to appear in the log (via message = NA): #7443. I am using the latest stable version of Quarto on the latest version of Ubuntu using GitHub Actions. Any help would be greatly appreciated. Thanks in advance!

[mcanouil]

Did you try the R Markdown Cookbook code on the matter?

• https://bookdown.org/yihui/rmarkdown-cookbook/time-chunk.html

[isaactpetersen]

Yes, I have tried the following code (based on the R Markdown Cookbook section linked to in my original post), and it does not print the chunk execution times in the terminal:

```{r}
#| label: setup
#| include: false

# Global knitr options
knitr::opts_chunk$set(time_it = TRUE)

all_times <- list() # store the time for each chunk

# Timing hook
knitr::knit_hooks$set(time_it = local({
  now <- NULL
  function(before, options) {
    if (before) {
      # record the current time before each chunk
      now <<- Sys.time()
    } else {
      # calculate the time difference after a chunk
      res <- difftime(Sys.time(), now, units = "secs")
      all_times[[options$label]] <<- res
      # return a character string to show the time
      paste("Time for the chunk", options$label, "to run:", res)
    }
  }
}))
```

The code in my original post works, but only for the first chapter—it does not track chunk execution times for subsequent chapters.

[mcanouil]

The code in my original post works, but only for the first chapter—it does not track chunk execution times for subsequent chapters.

Do you have a small reproducible example? (Git repository with the minimal dependencies if not none at all)

[cderv]

Here is the example in Quarto from the Cookbook

---
format: html
---

```{r}
knitr::knit_hooks$set(time_it = local({
  now <- NULL
  function(before, options) {
    if (before) {
      # record the current time before each chunk
      now <<- Sys.time()
    } else {
      # calculate the time difference after a chunk
      res <- difftime(Sys.time(), now, units = "secs")
      # return a character string to show the time
      paste("Time for this code chunk to run:", round(res,
        2), "seconds")
    }
  }
}))
```

```{r}
#| time_it: true
Sys.sleep(2)
```

So it is working, and I think it is working for you too

The code in my original post works, but only for the first chapter—it does not track chunk execution times for subsequent chapters.

All chapters in a Quarto Book are rendered invidually, which means that a new R session and new knitr context will be used for each.

The setup chunk you have needs to be inserted into each chapter, for example using an include

{{< _setup-knitr-timing.qmd >}}

Each R session will be used for each document is independant. So to share content you need to use what is available through Quarto (include shortcode for example), or through knitr (sourcing a R file in in setup chunk that you have in all your document).

There are several discussions opened about sharing / loading content for each chapter. You can look at discussion there.

I also had to follow some advice in the thread on getting messages to appear in the log (via message = NA):

You are printing value here, not outputing a message. So message: NA won't change anything.
You need to use message

```{r}
knitr::knit_hooks$set(time_it = local({
  now <- NULL
  function(before, options) {
    if (before) {
      # record the current time before each chunk
      now <<- Sys.time()
    } else {
      # calculate the time difference after a chunk
      res <- difftime(Sys.time(), now, units = "secs")
      # return a character string to show the time
      message("Time for this code chunk to run:", round(res,
        2), "seconds")
    }
  }
}))
```

```{r}
#| time_it: true
#| message: NA
Sys.sleep(2)
```

and now it is in the terminal log

processing file: index.qmd
1/4                  
2/4 [unnamed-chunk-1]
3/4                  
4/4 [unnamed-chunk-2]
Time for this code chunk to run:2.08seconds
output file: index.knit.md

pandoc 
  to: html
  output-file: index.html
  standalone: true
  section-divs: true
  html-math-method: mathjax
  wrap: none
  default-image-extension: png
  variables: {}
  
metadata
  document-css: false
  link-citations: true
  date-format: long
  lang: en
  
Output created: index.html

Hope it helps.

[isaactpetersen]

This was very helpful--thank you! I didn't look closely to see what differed between our code blocks, but the code worked for me. I was able to use it to revise my code (which also saves the execution times in a .txt file). For future people who come upon this thread, below is my solution:

I created a _chunk-timing.qmd file with the following contents:

```{r}
#| label: setup-timing
#| include: false

# Set knitr options globally for all chunks
knitr::opts_chunk$set(time_it = TRUE)

# Get chapter-specific log file name
current_file <- knitr::current_input()
log_file <- sprintf("chunk-times-%s.txt", tools::file_path_sans_ext(basename(current_file)))

# Clear previous log
if (file.exists(log_file)) file.remove(log_file)

# Create timing hook
knitr::knit_hooks$set(time_it = local({
  now <- NULL
  function(before, options) {
    label <- if (!is.null(options$label)) options$label else "<unnamed>"
    if (before) {
      now <<- Sys.time()
    } else {
      elapsed <- difftime(Sys.time(), now, units = "secs")
      msg <- sprintf("This chunk (`%s`) ran in %.2f seconds.", label, as.numeric(elapsed))
      
      # Print to GitHub Actions log
      message(msg)
      
      # Save to chapter-specific log file
      cat(msg, file = log_file, append = TRUE, sep = "\n")
    }
  }
}))
```

Then, in each chapter, I added the following to the top of each:

{{< include _chunk-timing.qmd >}}

[mcanouil]

FYI, If the goal is to display the running time in the log/console, another way is to use the progress bar option from knitr.

• https://yihui.org/knitr/options/#global-r-options
  i

[cderv]

I don't think we should timing on those, but they indeed show the rendering progress. I think it is also possible to set custom progress function - maybe that is what you have in mind. Good idea !

[mcanouil]

Yes, my idea was to set a custom progress bar that does the timing part in addition to progress.
There are already R packages doing custom progress bar for knitr.

For instance, there is one with a progress bar that already has the total computing time: https://rmflight.github.io/knitrProgressBar/reference/progress_estimated.html