Slow test reporter

CLAUDE.md

@@ -18,10 +18,13 @@ General advice:
 - `devtools::test_file("tests/testthat/test-filename.R")` - Run tests in a specific file
 - DO NOT USE `devtools::test_active_file()`
 - `devtools::load_all()` - Load package for development
-- `devtools::document()` - Generate documentation
 - `devtools::check()` - Run R CMD check
 - `devtools::install()` - Install package locally
 
+### Documentation
+
+- Always run `devtools::document()` after changing any roxygen2 docs.
+
 ## Core Architecture
 
 ### Main Components

NAMESPACE

@@ -45,6 +45,7 @@ export(ProgressReporter)
 export(RStudioReporter)
 export(Reporter)
 export(SilentReporter)
+export(SlowReporter)
 export(StopReporter)
 export(SummaryReporter)
 export(TapReporter)

NEWS.md

@@ -1,5 +1,6 @@
 # testthat (development version)
 
+* New `SlowReporter` makes it easier to find the slowest tests in your package. The easiest way to run it is with `devtools::test(reporter = "slow")` (#1466).
 * Parallel testthat now does not ignore test files with syntax errors (#1360).
 * `expect_lt()`, `expect_gt()`, and friends have a refined display that is more likely to display the correct number of digits and shows you the actual values compared.
 * `describe()`, `it()`, and `test_that()` now have a shared stack of descriptions so that if you nest any inside of each other, any resulting failures will show you the full path.

R/reporter-slow.R

@@ -0,0 +1,106 @@
+#' Test reporter: show timings for slow tests
+#'
+#' @description
+#' `SlowReporter` is designed to identify slow tests. It reports the
+#' execution time for each test and can optionally filter out tests that
+#' run faster than a specified threshold (default: 1 second). This reporter
+#' is useful for performance optimization and identifying tests that may
+#' benefit from optimization or parallelization.
+#'
+#' @export
+#' @family reporters
+SlowReporter <- R6::R6Class(
+  "SlowReporter",
+  inherit = Reporter,
+  public = list(
+    min_time = 0.5,
+    test_timings = NULL,
+    current_test_start = NULL,
+    current_file = NULL,
+
+    initialize = function(min_time = 0.5, ...) {
+      super$initialize(...)
+      self$min_time <- min_time
+      self$test_timings <- list()
+    },
+
+    start_reporter = function(context) {
+      self$cat_line(
+        cli::style_bold("Slow tests"),
+        " (showing tests >= ",
+        self$min_time,
+        "s)"
+      )
+      self$cat_line()
+    },
+
+    start_file = function(file) {
+      self$current_file <- file
+    },
+
+    start_test = function(context, test) {
+      self$current_test_start <- proc.time()[[3]]
+    },
+
+    end_test = function(context, test) {
+      if (is.null(self$current_test_start)) {
+        return()
+      }
+
+      time_taken <- proc.time()[[3]] - self$current_test_start
+
+      # Store timing information
+      timing <- list(
+        file = self$current_file,
+        test = test,
+        time = time_taken
+      )
+      self$test_timings[[length(self$test_timings) + 1]] <- timing
+
+      if (time_taken >= self$min_time) {
+        self$show_timing(timing)
+      }
+
+      self$current_test_start <- NULL
+    },
+
+    end_reporter = function() {
+      if (length(self$test_timings) == 0) {
+        return()
+      }
+
+      all_times <- map_dbl(self$test_timings, \(x) x$time)
+      is_slow <- all_times >= self$min_time
+
+      self$cat_line()
+      self$rule(cli::style_bold("Summary"), line = 2)
+      self$cat_line("All tests:  ", sprintf("%.2fs", sum(all_times)))
+      self$cat_line("Slow tests: ", sprintf("%.2fs", sum(all_times[is_slow])))
+
+      if (sum(is_slow) <= 10) {
+        return()
+      }
+
+      # Sort by time descending for summary
+      slowest <- self$test_timings[order(all_times, decreasing = TRUE)]
+
+      self$cat_line()
+      self$rule(cli::style_bold("Slowest tests:"), line = 1)
+
+      # Show top 10 slowest tests
+      for (i in 1:10) {
+        self$show_timing(slowest[[i]])
+      }
+
+      if (length(slowest) > 10) {
+        self$cat_line("... and ", length(slowest) - 10, " more slow tests")
+      }
+
+      self$cat_line()
+    },
+    show_timing = function(timing) {
+      time <- sprintf("%.2fs", timing$time)
+      self$cat_line("[", time, "] ", time, " ", timing$file, ": ", timing$test)
+    }
+  )
+)

R/reporter-timing.R

@@ -0,0 +1,99 @@
+#' Test reporter: show timings for slow tests
+#'
+#' @description
+#' `SlowReporter` is designed to identify slow tests. It reports the
+#' execution time for each test, ignoring tests faster than a specified
+#' threshold (default: 0.5s).
+#'
+#' The easiest way to run it over your package is with
+#' `devtools::test(reporter = "slow")`.
+#'
+#' @export
+#' @family reporters
+SlowReporter <- R6::R6Class(
+  "SlowReporter",
+  inherit = Reporter,
+  public = list(
+    min_time = NA_real_,
+    test_timings = NULL,
+    current_test_start = NULL,
+    current_file = NULL,
+
+    initialize = function(min_time = 0.5, ...) {
+      check_number_decimal(min_time, min = 0)
+
+      super$initialize(...)
+      self$min_time <- min_time
+      self$test_timings <- list()
+    },
+
+    start_file = function(file) {
+      self$current_file <- file
+    },
+
+    start_test = function(context, test) {
+      self$current_test_start <- proc.time()[[3]]
+    },
+
+    end_test = function(context, test) {
+      if (is.null(self$current_test_start)) {
+        return()
+      }
+
+      time_taken <- proc.time()[[3]] - self$current_test_start
+
+      # Store timing information
+      timing <- list(
+        file = self$current_file,
+        test = test,
+        time = time_taken
+      )
+      self$test_timings[[length(self$test_timings) + 1]] <- timing
+
+      if (time_taken >= self$min_time) {
+        self$show_timing(timing)
+      }
+
+      self$current_test_start <- NULL
+    },
+
+    end_reporter = function() {
+      if (length(self$test_timings) == 0) {
+        return()
+      }
+
+      all_times <- map_dbl(self$test_timings, \(x) x$time)
+      is_slow <- all_times >= self$min_time
+
+      self$cat_line()
+      self$rule(cli::style_bold("Summary"), line = 2)
+      self$cat_line("All tests:  ", sprintf("%.2fs", sum(all_times)))
+      self$cat_line("Slow tests: ", sprintf("%.2fs", sum(all_times[is_slow])))
+
+      if (sum(is_slow) <= 10) {
+        return()
+      }
+
+      # Sort by time descending for summary
+      slowest <- self$test_timings[order(all_times, decreasing = TRUE)]
+
+      self$cat_line()
+      self$rule(cli::style_bold("Slowest tests:"), line = 1)
+
+      # Show top 10 slowest tests
+      for (i in 1:10) {
+        self$show_timing(slowest[[i]])
+      }
+
+      if (length(slowest) > 10) {
+        self$cat_line("... and ", length(slowest) - 10, " more slow tests")
+      }
+
+      self$cat_line()
+    },
+    show_timing = function(timing) {
+      time <- sprintf("%.2fs", timing$time)
+      self$cat_line("[", time, "] ", timing$file, ": ", timing$test)
+    }
+  )
+)