From b8a0c839fc1d5f3778583a0b26f3aefcea7de474 Mon Sep 17 00:00:00 2001 From: Thomas Lin Pedersen Date: Wed, 22 Jan 2025 09:51:29 +0100 Subject: [PATCH 1/4] Add log_elapsed() --- NAMESPACE | 2 ++ NEWS.md | 1 + R/helpers.R | 58 +++++++++++++++++++++++++++++++++++ R/utils.R | 1 + man/log_elapsed.Rd | 32 +++++++++++++++++++ tests/testthat/test-helpers.R | 26 ++++++++++++++++ 6 files changed, 120 insertions(+) create mode 100644 man/log_elapsed.Rd diff --git a/NAMESPACE b/NAMESPACE index 8b1d5bc..e873fb3 100644 --- a/NAMESPACE +++ b/NAMESPACE @@ -53,6 +53,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 5edf5e7..d46660f 100644 --- a/NEWS.md +++ b/NEWS.md @@ -7,6 +7,7 @@ * `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) +* Added `log_elapsed()` to show cumulative elapsed running time (@thomasp85) ## Fixes diff --git a/R/helpers.R b/R/helpers.R index 223fb41..d27e33d 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 <- 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..2ee0bc0 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/man/log_elapsed.Rd b/man/log_elapsed.Rd new file mode 100644 index 0000000..f96787d --- /dev/null +++ b/man/log_elapsed.Rd @@ -0,0 +1,32 @@ +% 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_) +} +\arguments{ +\item{...}{passed to \code{\link[=log_level]{log_level()}}} + +\item{level}{see \code{\link[=log_levels]{log_levels()}}} + +\item{namespace}{x} +} +\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), "===") From 1fdeb1680ff8456be67714839d887253bab526c8 Mon Sep 17 00:00:00 2001 From: Thomas Lin Pedersen Date: Fri, 24 Jan 2025 22:23:02 +0100 Subject: [PATCH 2/4] fix docs and lint --- R/utils.R | 2 +- man/log_elapsed.Rd | 4 +++- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/R/utils.R b/R/utils.R index 2ee0bc0..6d95615 100644 --- a/R/utils.R +++ b/R/utils.R @@ -119,4 +119,4 @@ needs_stdout <- function() { # allow mocking Sys.time <- NULL # nolint -proc.time <- NULL #nolint +proc.time <- NULL # nolint diff --git a/man/log_elapsed.Rd b/man/log_elapsed.Rd index f96787d..8ac47c0 100644 --- a/man/log_elapsed.Rd +++ b/man/log_elapsed.Rd @@ -7,7 +7,7 @@ \usage{ log_elapsed(..., level = INFO, namespace = NA_character_) -log_elapsed_start(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()}}} @@ -15,6 +15,8 @@ log_elapsed_start(level = INFO, namespace = NA_character_) \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 From bb768bf082fe3f1d37b3b25f55855f3ed49643e9 Mon Sep 17 00:00:00 2001 From: Thomas Lin Pedersen Date: Fri, 24 Jan 2025 22:49:12 +0100 Subject: [PATCH 3/4] fix unit tests on old systems --- R/helpers.R | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/R/helpers.R b/R/helpers.R index d27e33d..df5c7b6 100644 --- a/R/helpers.R +++ b/R/helpers.R @@ -250,7 +250,7 @@ log_elapsed <- function(..., level = INFO, namespace = NA_character_) { start <- get0(ns, envir = elapsed, ifnotfound = 0) - time_elapsed <- difftime(proc.time()["elapsed"], start, units = "secs") + time_elapsed <- as.difftime(proc.time()["elapsed"] - start, units = "secs") log_level( paste( From 96c03d28c59ceecb90f51956541b2eddef75313c Mon Sep 17 00:00:00 2001 From: Thomas Lin Pedersen Date: Mon, 27 Jan 2025 15:16:02 +0100 Subject: [PATCH 4/4] add entry to pkgdown --- _pkgdown.yml | 1 + 1 file changed, 1 insertion(+) 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