From 34d019fda92771fb02bcba0ef21d563729372ec5 Mon Sep 17 00:00:00 2001 From: Hadley Wickham Date: Thu, 12 Sep 2024 15:47:10 -0500 Subject: [PATCH 1/3] Clarify the main profvis loop * Ensure that we always terminate `RProf()` even if the expr errors * Make it a bit more clear how expr works (we regenerate the lazy binding on every iteration) * Ensure we always set lines, even if the expr errors. (This is what lead to the mystifying lines is not a character vector error) --- R/profvis.R | 10 +++++----- tests/testthat/_snaps/profvis.md | 9 +++++++++ tests/testthat/test-profvis.R | 13 +++++++++++-- 3 files changed, 25 insertions(+), 7 deletions(-) create mode 100644 tests/testthat/_snaps/profvis.md diff --git a/R/profvis.R b/R/profvis.R index 423cd68..e727e5a 100644 --- a/R/profvis.R +++ b/R/profvis.R @@ -177,19 +177,19 @@ profvis <- function(expr = NULL, on.exit(unlink(prof_output), add = TRUE) } repeat { + eval(substitute(delayedAssign("expr", expr_q, eval.env = env))) + inject(Rprof(prof_output, !!!rprof_args)) cnd <- with_profvis_handlers(expr) - if (!is.null(cnd)) { - break - } Rprof(NULL) lines <- readLines(prof_output) + if (!is.null(cnd)) { + break + } if (prof_matches(zap_header(lines), rerun)) { break } - - env_bind_lazy(current_env(), expr = !!expr_q, .eval_env = env) } # Must be in the same handler context as `expr` above to get the diff --git a/tests/testthat/_snaps/profvis.md b/tests/testthat/_snaps/profvis.md new file mode 100644 index 0000000..551cf85 --- /dev/null +++ b/tests/testthat/_snaps/profvis.md @@ -0,0 +1,9 @@ +# can capture profile of code with error + + Code + out <- profvis(f(), rerun = "pause") + Message + profvis: code exited with error: + error + + diff --git a/tests/testthat/test-profvis.R b/tests/testthat/test-profvis.R index 1706555..d2dde6c 100644 --- a/tests/testthat/test-profvis.R +++ b/tests/testthat/test-profvis.R @@ -1,7 +1,7 @@ test_that("Irrelevant stack is trimmed from profiles (#123)", { skip_on_cran() skip_on_covr() - + f <- function() pause(TEST_PAUSE_TIME) out <- repro_profvis(f(), simplify = FALSE) @@ -18,9 +18,18 @@ test_that("defaults to elapsed timing", { skip_on_cran() skip_on_covr() skip_if_not(has_event()) - + f <- function() Sys.sleep(TEST_PAUSE_TIME) out <- repro_profvis(f(), rerun = "Sys.sleep") expect_equal(profvis_modal_value(out$x$message$prof), "Sys.sleep f") }) + +test_that("can capture profile of code with error", { + f <- function() { + pause(TEST_PAUSE_TIME) + stop("error") + } + expect_snapshot(out <- profvis(f(), rerun = "pause")) + expect_equal(profvis_modal_value(out$x$message$prof), "pause f") +}) From 5064d66bef8dd9669fe604188c88e81fda80d098 Mon Sep 17 00:00:00 2001 From: Hadley Wickham Date: Thu, 12 Sep 2024 15:59:58 -0500 Subject: [PATCH 2/3] Polishing --- R/profvis.R | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/R/profvis.R b/R/profvis.R index e727e5a..d031396 100644 --- a/R/profvis.R +++ b/R/profvis.R @@ -172,11 +172,11 @@ profvis <- function(expr = NULL, filter.callframes = simplify )) - on.exit(Rprof(NULL), add = TRUE) if (remove_on_exit) { on.exit(unlink(prof_output), add = TRUE) } repeat { + # Work around https://github.com/r-lib/rlang/issues/1749 eval(substitute(delayedAssign("expr", expr_q, eval.env = env))) inject(Rprof(prof_output, !!!rprof_args)) From c9e2a0a992c62f547bc8a00062dfd107bc56a50f Mon Sep 17 00:00:00 2001 From: Hadley Wickham Date: Fri, 13 Sep 2024 07:16:31 -0500 Subject: [PATCH 3/3] Update helper name --- tests/testthat/test-profvis.R | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tests/testthat/test-profvis.R b/tests/testthat/test-profvis.R index 04671fb..0229c10 100644 --- a/tests/testthat/test-profvis.R +++ b/tests/testthat/test-profvis.R @@ -35,5 +35,5 @@ test_that("can capture profile of code with error", { stop("error") } expect_snapshot(out <- profvis(f(), rerun = "pause")) - expect_equal(profvis_modal_value(out$x$message$prof), "pause f") + expect_equal(profile_mode(out), "pause f") })