diff --git a/NAMESPACE b/NAMESPACE index 0918871..646f03d 100644 --- a/NAMESPACE +++ b/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) diff --git a/NEWS.md b/NEWS.md index 07721af..913de9d 100644 --- a/NEWS.md +++ b/NEWS.md @@ -1,5 +1,7 @@ # logger (development version) +* 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) @@ -13,7 +15,6 @@ improved documentations, modernized tests, performance speedups. * `log_appender()`, `log_layout()` and `log_formatter()` now check that you are calling them with a function, and return the previously set value (#170, @hadley) * new function to return number of log indices (#194, @WurmPeter) * `appender_async` is now using `mirai` instead of a custom background process and queue system (#214, @hadley @shikokuchuo) -* New `formatter_cli()` allows you to use the syntax from the cli package to create log messages (#210, @thomasp85) ## Fixes diff --git a/R/helpers.R b/R/helpers.R index 223fb41..df5c7b6 100644 --- a/R/helpers.R +++ b/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 diff --git a/R/utils.R b/R/utils.R index 0fe42b3..6d95615 100644 --- a/R/utils.R +++ b/R/utils.R @@ -119,3 +119,4 @@ needs_stdout <- function() { # allow mocking Sys.time <- NULL # nolint +proc.time <- NULL # nolint diff --git a/_pkgdown.yml b/_pkgdown.yml index 05e5044..2c05fa6 100644 --- a/_pkgdown.yml +++ b/_pkgdown.yml @@ -23,6 +23,7 @@ reference: - log_eval - log_failure - log_tictoc + - log_elapsed - log_separator - log_with_separator - with_log_threshold diff --git a/man/log_elapsed.Rd b/man/log_elapsed.Rd new file mode 100644 index 0000000..8ac47c0 --- /dev/null +++ b/man/log_elapsed.Rd @@ -0,0 +1,34 @@ +% Generated by roxygen2: do not edit by hand +% Please edit documentation in R/helpers.R +\name{log_elapsed} +\alias{log_elapsed} +\alias{log_elapsed_start} +\title{Log cumulative running time} +\usage{ +log_elapsed(..., level = INFO, namespace = NA_character_) + +log_elapsed_start(level = INFO, namespace = NA_character_, quiet = FALSE) +} +\arguments{ +\item{...}{passed to \code{\link[=log_level]{log_level()}}} + +\item{level}{see \code{\link[=log_levels]{log_levels()}}} + +\item{namespace}{x} + +\item{quiet}{Should starting the time emit a log message} +} +\description{ +This function is working like \code{\link[=log_tictoc]{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 \code{log_elapsed_start()}, but if that hasn't been called it +will show the time since the R session started. +} +\examples{ +log_elapsed_start() +Sys.sleep(0.4) +log_elapsed("Tast 1") +Sys.sleep(0.2) +log_elapsed("Task 2") + +} diff --git a/tests/testthat/test-helpers.R b/tests/testthat/test-helpers.R index 85bbc0f..7b9827a 100644 --- a/tests/testthat/test-helpers.R +++ b/tests/testthat/test-helpers.R @@ -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), "===")