Merge branch 'main' into issue110-location-log

Author: thomasp85

NAMESPACE

@@ -54,6 +54,8 @@ export(layout_simple)
 export(layout_syslognet)
 export(log_appender)
 export(log_debug)
+export(log_elapsed)
+export(log_elapsed_start)
 export(log_error)
 export(log_errors)
 export(log_eval)

NEWS.md

@@ -1,6 +1,7 @@
 # logger (development version)
 
 * File and line location of the log call is now available to the layouts (#110, @thomasp85)
+* Added `log_elapsed()` to show cumulative elapsed running time (@thomasp85)
 * New `formatter_cli()` allows you to use the syntax from the cli package to create log messages (#210, @thomasp85)
 
 # logger 0.4.0 (2024-10-19)

R/helpers.R

@@ -227,6 +227,64 @@ log_tictoc <- function(..., level = INFO, namespace = NA_character_) {
 }
 tictocs <- new.env(parent = emptyenv())
 
+#' Log cumulative running time
+#'
+#' This function is working like [log_tictoc()] but differs in that it continues
+#' to count up rather than resetting the timer at every call. You can set the
+#' start time using `log_elapsed_start()`, but if that hasn't been called it
+#' will show the time since the R session started.
+#'
+#' @inheritParams log_tictoc
+#'
+#' @export
+#'
+#' @examples
+#' log_elapsed_start()
+#' Sys.sleep(0.4)
+#' log_elapsed("Tast 1")
+#' Sys.sleep(0.2)
+#' log_elapsed("Task 2")
+#'
+log_elapsed <- function(..., level = INFO, namespace = NA_character_) {
+  ns <- fallback_namespace(namespace)
+
+  start <- get0(ns, envir = elapsed, ifnotfound = 0)
+
+  time_elapsed <- as.difftime(proc.time()["elapsed"] - start, units = "secs")
+
+  log_level(
+    paste(
+      ns, "timer",
+      round(time_elapsed, 2), attr(time_elapsed, "units"), "elapsed -- "
+    ),
+    ...,
+    level = level, namespace = namespace,
+    .logcall = sys.call(),
+    .topcall = sys.call(-1),
+    .topenv = parent.frame()
+  )
+}
+#' @rdname log_elapsed
+#' @param quiet Should starting the time emit a log message
+#' @export
+log_elapsed_start <- function(level = INFO, namespace = NA_character_, quiet = FALSE) {
+  ns <- fallback_namespace(namespace)
+
+  assign(ns, proc.time()["elapsed"], envir = elapsed)
+
+  if (!quiet) {
+    log_level(
+      paste(
+        "starting", ns, "timer"
+      ),
+      level = level, namespace = namespace,
+      .logcall = sys.call(),
+      .topcall = sys.call(-1),
+      .topenv = parent.frame()
+    )
+  }
+}
+elapsed <- new.env(parent = emptyenv())
 
 #' Logs the error message to console before failing
 #' @param expression call

R/utils.R

@@ -142,3 +142,4 @@ needs_stdout <- function() {
 
 # allow mocking
 Sys.time <- NULL # nolint
+proc.time <- NULL # nolint

_pkgdown.yml

@@ -23,6 +23,7 @@ reference:
   - log_eval
   - log_failure
   - log_tictoc
+  - log_elapsed
   - log_separator
   - log_with_separator
   - with_log_threshold

man/log_elapsed.Rd

@@ -17,6 +17,32 @@ test_that("tictoc", {
   expect_output(log_tictoc(), "timer toc 1 mins")
 })
 
+test_that("elapsed", {
+  local_test_logger()
+
+  proc_null <- proc.time() * 0
+
+  with_mocked_bindings(
+    expect_output(log_elapsed(), "timer 2 secs elapsed"),
+    proc.time = function() proc_null + 2
+  )
+
+  with_mocked_bindings(
+    expect_output(log_elapsed_start(), "starting global timer"),
+    proc.time = function() proc_null + 1
+  )
+
+  with_mocked_bindings(
+    expect_output(log_elapsed(), "timer 1 secs elapsed"),
+    proc.time = function() proc_null + 2
+  )
+
+  with_mocked_bindings(
+    expect_silent(log_elapsed_start(quiet = TRUE)),
+    proc.time = function() proc_null
+  )
+})
+
 test_that("log with separator", {
   local_test_logger()
   expect_output(log_with_separator(42), "===")