From 9f58cfc589e8cf57b2265a6e0a4c2ba64ef17b89 Mon Sep 17 00:00:00 2001 From: Andrew Johnson Date: Thu, 23 Mar 2023 14:20:28 +0200 Subject: [PATCH 1/6] Align handling of messages and errors --- R/model.R | 8 ++++++-- R/run.R | 56 ++++++++++++++++++++++++++++++++++++------------------- 2 files changed, 43 insertions(+), 21 deletions(-) diff --git a/R/model.R b/R/model.R index 1de220b69..d2def4003 100644 --- a/R/model.R +++ b/R/model.R @@ -1054,6 +1054,7 @@ sample <- function(data = NULL, window = NULL, fixed_param = FALSE, show_messages = TRUE, + show_errors = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), # deprecated cores = NULL, @@ -1123,7 +1124,8 @@ sample <- function(data = NULL, num_procs = checkmate::assert_integerish(chains, lower = 1, len = 1), parallel_procs = checkmate::assert_integerish(parallel_chains, lower = 1, null.ok = TRUE), threads_per_proc = assert_valid_threads(threads_per_chain, self$cpp_options(), multiple_chains = TRUE), - show_stderr_messages = show_messages + show_stderr_messages = show_errors, + show_stdout_messages = show_messages ) model_variables <- NULL if (is_variables_method_supported(self)) { @@ -1260,6 +1262,7 @@ sample_mpi <- function(data = NULL, fixed_param = FALSE, sig_figs = NULL, show_messages = TRUE, + show_errors = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), # deprecated validate_csv = TRUE) { @@ -1282,7 +1285,8 @@ sample_mpi <- function(data = NULL, procs <- CmdStanMCMCProcs$new( num_procs = checkmate::assert_integerish(chains, lower = 1, len = 1), parallel_procs = 1, - show_stderr_messages = show_messages + show_stderr_messages = show_errors, + show_stdout_messages = show_messages ) model_variables <- NULL if (is_variables_method_supported(self)) { diff --git a/R/run.R b/R/run.R index 6f401e695..bdc5315eb 100644 --- a/R/run.R +++ b/R/run.R @@ -361,14 +361,16 @@ check_target_exe <- function(exe) { start_msg <- paste0("Running MCMC with ", procs$num_procs(), " chains, at most ", procs$parallel_procs(), " in parallel") } } - if (is.null(procs$threads_per_proc())) { - cat(paste0(start_msg, "...\n\n")) - } else { - cat(paste0(start_msg, ", with ", procs$threads_per_proc(), " thread(s) per chain...\n\n")) - Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) - # Windows environment variables have to be explicitly exported to WSL - if (os_is_wsl()) { - Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") + if (procs$show_stdout_messages()) { + if (is.null(procs$threads_per_proc())) { + cat(paste0(start_msg, "...\n\n")) + } else { + cat(paste0(start_msg, ", with ", procs$threads_per_proc(), " thread(s) per chain...\n\n")) + Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) + # Windows environment variables have to be explicitly exported to WSL + if (os_is_wsl()) { + Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") + } } } start_time <- Sys.time() @@ -424,14 +426,16 @@ CmdStanRun$set("private", name = "run_sample_", value = .run_sample) start_msg <- paste0("Running standalone generated quantities after ", procs$num_procs(), " MCMC chains, ", procs$parallel_procs(), " chains at a time ") } } - if (is.null(procs$threads_per_proc())) { - cat(paste0(start_msg, "...\n\n")) - } else { - cat(paste0(start_msg, ", with ", procs$threads_per_proc(), " thread(s) per chain...\n\n")) - Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) - # Windows environment variables have to be explicitly exported to WSL - if (os_is_wsl()) { - Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") + if (procs$show_stdout_messages()) { + if (is.null(procs$threads_per_proc())) { + cat(paste0(start_msg, "...\n\n")) + } else { + cat(paste0(start_msg, ", with ", procs$threads_per_proc(), " thread(s) per chain...\n\n")) + Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) + # Windows environment variables have to be explicitly exported to WSL + if (os_is_wsl()) { + Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") + } } } start_time <- Sys.time() @@ -612,6 +616,12 @@ CmdStanProcs <- R6::R6Class( private$show_stdout_messages_ <- show_stdout_messages invisible(self) }, + show_stdout_messages = function () { + private$show_stdout_messages_ + }, + show_stderr_messages = function () { + private$show_stderr_messages_ + }, num_procs = function() { private$num_procs_ }, @@ -927,7 +937,7 @@ CmdStanMCMCProcs <- R6::R6Class( || grepl("stancflags", line, fixed = TRUE)) { ignore_line <- TRUE } - if ((state > 1.5 && state < 5 && !ignore_line) || is_verbose_mode()) { + if ((state > 1.5 && state < 5 && !ignore_line && private$show_stdout_messages_) || is_verbose_mode()) { if (state == 2) { message("Chain ", id, " ", line) } else { @@ -939,7 +949,9 @@ CmdStanMCMCProcs <- R6::R6Class( if (state == 1) { state <- 2; } - message("Chain ", id, " ", line) + if (private$show_stderr_messages_) { + message("Chain ", id, " ", line) + } } private$proc_state_[[id]] <- next_state } else { @@ -951,6 +963,9 @@ CmdStanMCMCProcs <- R6::R6Class( invisible(self) }, report_time = function(id = NULL) { + if (!private$show_stdout_messages_) { + return(invisible(NULL)) + } if (!is.null(id)) { if (self$proc_state(id) == 7) { warning("Chain ", id, " finished unexpectedly!\n", immediate. = TRUE, call. = FALSE) @@ -1030,7 +1045,7 @@ CmdStanGQProcs <- R6::R6Class( if (nzchar(line)) { if (self$proc_state(id) == 1 && grepl("refresh = ", line, perl = TRUE)) { self$set_proc_state(id, new_state = 1.5) - } else if (self$proc_state(id) >= 2) { + } else if (self$proc_state(id) >= 2 && private$show_stdout_messages_) { cat("Chain", id, line, "\n") } } else { @@ -1044,6 +1059,9 @@ CmdStanGQProcs <- R6::R6Class( invisible(self) }, report_time = function(id = NULL) { + if (!private$show_stdout_messages_) { + return(invisible(NULL)) + } if (!is.null(id)) { if (self$proc_state(id) == 7) { warning("Chain ", id, " finished unexpectedly!\n", immediate. = TRUE, call. = FALSE) From 50f48f80d02bc2fe14bef39b1bfdd0bf7cfcf237 Mon Sep 17 00:00:00 2001 From: Andrew Johnson Date: Thu, 23 Mar 2023 14:38:06 +0200 Subject: [PATCH 2/6] Fix threads --- R/run.R | 36 +++++++++++++++++++--------------- man/model-method-sample.Rd | 1 + man/model-method-sample_mpi.Rd | 1 + 3 files changed, 22 insertions(+), 16 deletions(-) diff --git a/R/run.R b/R/run.R index bdc5315eb..556477e43 100644 --- a/R/run.R +++ b/R/run.R @@ -361,16 +361,18 @@ check_target_exe <- function(exe) { start_msg <- paste0("Running MCMC with ", procs$num_procs(), " chains, at most ", procs$parallel_procs(), " in parallel") } } - if (procs$show_stdout_messages()) { - if (is.null(procs$threads_per_proc())) { + if (is.null(procs$threads_per_proc())) { + if (procs$show_stdout_messages()) { cat(paste0(start_msg, "...\n\n")) - } else { + } + } else { + if (procs$show_stdout_messages()) { cat(paste0(start_msg, ", with ", procs$threads_per_proc(), " thread(s) per chain...\n\n")) - Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) - # Windows environment variables have to be explicitly exported to WSL - if (os_is_wsl()) { - Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") - } + } + Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) + # Windows environment variables have to be explicitly exported to WSL + if (os_is_wsl()) { + Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") } } start_time <- Sys.time() @@ -426,16 +428,18 @@ CmdStanRun$set("private", name = "run_sample_", value = .run_sample) start_msg <- paste0("Running standalone generated quantities after ", procs$num_procs(), " MCMC chains, ", procs$parallel_procs(), " chains at a time ") } } - if (procs$show_stdout_messages()) { - if (is.null(procs$threads_per_proc())) { + if (is.null(procs$threads_per_proc())) { + if (procs$show_stdout_messages()) { cat(paste0(start_msg, "...\n\n")) - } else { + } + } else { + if (procs$show_stdout_messages()) { cat(paste0(start_msg, ", with ", procs$threads_per_proc(), " thread(s) per chain...\n\n")) - Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) - # Windows environment variables have to be explicitly exported to WSL - if (os_is_wsl()) { - Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") - } + } + Sys.setenv("STAN_NUM_THREADS" = as.integer(procs$threads_per_proc())) + # Windows environment variables have to be explicitly exported to WSL + if (os_is_wsl()) { + Sys.setenv("WSLENV"="STAN_NUM_THREADS/u") } } start_time <- Sys.time() diff --git a/man/model-method-sample.Rd b/man/model-method-sample.Rd index a133008ff..d57b0663d 100644 --- a/man/model-method-sample.Rd +++ b/man/model-method-sample.Rd @@ -35,6 +35,7 @@ sample( window = NULL, fixed_param = FALSE, show_messages = TRUE, + show_errors = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), cores = NULL, num_cores = NULL, diff --git a/man/model-method-sample_mpi.Rd b/man/model-method-sample_mpi.Rd index 12dbc47e6..c686a7f06 100644 --- a/man/model-method-sample_mpi.Rd +++ b/man/model-method-sample_mpi.Rd @@ -34,6 +34,7 @@ sample_mpi( fixed_param = FALSE, sig_figs = NULL, show_messages = TRUE, + show_errors = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), validate_csv = TRUE ) From ff20381ae1ef3ed159fb8a31e56e97e40c6ccf05 Mon Sep 17 00:00:00 2001 From: Andrew Johnson Date: Thu, 23 Mar 2023 14:50:05 +0200 Subject: [PATCH 3/6] Add tests --- tests/testthat/test-model-sample.R | 40 ++++++++++++++++++++++++++++++ 1 file changed, 40 insertions(+) diff --git a/tests/testthat/test-model-sample.R b/tests/testthat/test-model-sample.R index ee6098ce9..92bf08d22 100644 --- a/tests/testthat/test-model-sample.R +++ b/tests/testthat/test-model-sample.R @@ -321,3 +321,43 @@ test_that("sig_figs warning if version less than 2.25", { ) reset_cmdstan_version() }) + +test_that("Errors are suppressed with show_errors", { + errmodcode <- " + data { + real y_mean; + } + transformed data { + vector[1] small; + small[2] = 1.0; + } + parameters { + real y; + } + model { + y ~ normal(y_mean, 1); + } + " + errmod <- cmdstan_model(write_stan_file(errmodcode), force_recompile = TRUE) + + expect_message( + suppressWarnings(errmod$sample(data = list(y_mean = 1), chains = 1)), + "Chain 1 Exception: vector[uni] assign: accessing element out of range", + fixed = TRUE + ) + + expect_no_message( + suppressWarnings(errmod$sample(data = list(y_mean = 1), chains = 1, show_errors = FALSE)) + ) +}) + +test_that("All output can be suppressed by show_messages", { + stan_program <- testing_stan_file("bernoulli") + data_list <- testing_data("bernoulli") + mod <- cmdstan_model(stan_program, force_recompile = TRUE) + output <- capture.output( + fit <- mod$sample(data = data_list, show_messages = FALSE) + ) + + expect_length(output, 0) +}) From 7da634ccf4f46173dad19740b5679bf4087c16b8 Mon Sep 17 00:00:00 2001 From: Andrew Johnson Date: Thu, 23 Mar 2023 18:16:49 +0200 Subject: [PATCH 4/6] Update to show_exceptions --- R/model.R | 8 ++++---- man/model-method-sample.Rd | 2 +- man/model-method-sample_mpi.Rd | 2 +- tests/testthat/test-model-sample.R | 8 ++++---- 4 files changed, 10 insertions(+), 10 deletions(-) diff --git a/R/model.R b/R/model.R index d2def4003..2a2b9dcc7 100644 --- a/R/model.R +++ b/R/model.R @@ -1054,7 +1054,7 @@ sample <- function(data = NULL, window = NULL, fixed_param = FALSE, show_messages = TRUE, - show_errors = TRUE, + show_exceptions = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), # deprecated cores = NULL, @@ -1124,7 +1124,7 @@ sample <- function(data = NULL, num_procs = checkmate::assert_integerish(chains, lower = 1, len = 1), parallel_procs = checkmate::assert_integerish(parallel_chains, lower = 1, null.ok = TRUE), threads_per_proc = assert_valid_threads(threads_per_chain, self$cpp_options(), multiple_chains = TRUE), - show_stderr_messages = show_errors, + show_stderr_messages = show_exceptions, show_stdout_messages = show_messages ) model_variables <- NULL @@ -1262,7 +1262,7 @@ sample_mpi <- function(data = NULL, fixed_param = FALSE, sig_figs = NULL, show_messages = TRUE, - show_errors = TRUE, + show_exceptions = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), # deprecated validate_csv = TRUE) { @@ -1285,7 +1285,7 @@ sample_mpi <- function(data = NULL, procs <- CmdStanMCMCProcs$new( num_procs = checkmate::assert_integerish(chains, lower = 1, len = 1), parallel_procs = 1, - show_stderr_messages = show_errors, + show_stderr_messages = show_exceptions, show_stdout_messages = show_messages ) model_variables <- NULL diff --git a/man/model-method-sample.Rd b/man/model-method-sample.Rd index d57b0663d..99fa3a41e 100644 --- a/man/model-method-sample.Rd +++ b/man/model-method-sample.Rd @@ -35,7 +35,7 @@ sample( window = NULL, fixed_param = FALSE, show_messages = TRUE, - show_errors = TRUE, + show_exceptions = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), cores = NULL, num_cores = NULL, diff --git a/man/model-method-sample_mpi.Rd b/man/model-method-sample_mpi.Rd index c686a7f06..c015a1e9e 100644 --- a/man/model-method-sample_mpi.Rd +++ b/man/model-method-sample_mpi.Rd @@ -34,7 +34,7 @@ sample_mpi( fixed_param = FALSE, sig_figs = NULL, show_messages = TRUE, - show_errors = TRUE, + show_exceptions = TRUE, diagnostics = c("divergences", "treedepth", "ebfmi"), validate_csv = TRUE ) diff --git a/tests/testthat/test-model-sample.R b/tests/testthat/test-model-sample.R index 92bf08d22..1bc3fc2b4 100644 --- a/tests/testthat/test-model-sample.R +++ b/tests/testthat/test-model-sample.R @@ -118,7 +118,7 @@ test_that("sample() method runs when the stan file is removed", { ) }) -test_that("sample() prints informational messages depening on show_messages", { +test_that("sample() prints informational messages depening on show_exceptions", { mod_info_msg <- testing_model("info_message") expect_sample_output( expect_message( @@ -127,7 +127,7 @@ test_that("sample() prints informational messages depening on show_messages", { ) ) expect_sample_output( - expect_message(mod_info_msg$sample(show_messages = FALSE), regexp = NA) + expect_message(mod_info_msg$sample(show_exceptions = FALSE), regexp = NA) ) }) @@ -322,7 +322,7 @@ test_that("sig_figs warning if version less than 2.25", { reset_cmdstan_version() }) -test_that("Errors are suppressed with show_errors", { +test_that("Errors are suppressed with show_exceptions", { errmodcode <- " data { real y_mean; @@ -347,7 +347,7 @@ test_that("Errors are suppressed with show_errors", { ) expect_no_message( - suppressWarnings(errmod$sample(data = list(y_mean = 1), chains = 1, show_errors = FALSE)) + suppressWarnings(errmod$sample(data = list(y_mean = 1), chains = 1, show_exceptions = FALSE)) ) }) From 4e859799dfe27636992eea1e8df1f95aaa9a57b6 Mon Sep 17 00:00:00 2001 From: Andrew Johnson Date: Thu, 23 Mar 2023 20:43:00 +0200 Subject: [PATCH 5/6] Unset cmdstanr_verbose in test --- tests/testthat/test-model-sample.R | 1 + 1 file changed, 1 insertion(+) diff --git a/tests/testthat/test-model-sample.R b/tests/testthat/test-model-sample.R index 1bc3fc2b4..dbb691d06 100644 --- a/tests/testthat/test-model-sample.R +++ b/tests/testthat/test-model-sample.R @@ -355,6 +355,7 @@ test_that("All output can be suppressed by show_messages", { stan_program <- testing_stan_file("bernoulli") data_list <- testing_data("bernoulli") mod <- cmdstan_model(stan_program, force_recompile = TRUE) + options("cmdstanr_verbose" = FALSE) output <- capture.output( fit <- mod$sample(data = data_list, show_messages = FALSE) ) From d24a3594a280d097b432784962145ddda02ac6f5 Mon Sep 17 00:00:00 2001 From: Andrew Johnson Date: Thu, 23 Mar 2023 21:43:40 +0200 Subject: [PATCH 6/6] Update sample roxygen doc --- man-roxygen/model-sample-args.R | 4 ++++ man/model-method-sample.Rd | 5 +++++ man/model-method-sample_mpi.Rd | 5 +++++ 3 files changed, 14 insertions(+) diff --git a/man-roxygen/model-sample-args.R b/man-roxygen/model-sample-args.R index bbaa0ef3d..2c8c0e26f 100644 --- a/man-roxygen/model-sample-args.R +++ b/man-roxygen/model-sample-args.R @@ -75,6 +75,10 @@ #' `fixed_param=TRUE` is mandatory. When `fixed_param=TRUE` the `chains` and #' `parallel_chains` arguments will be set to `1`. #' @param show_messages (logical) When `TRUE` (the default), prints all +#' output during the sampling process, such as iteration numbers and elapsed times. +#' If the output is silenced then the [`$output()`][fit-method-output] method of +#' the resulting fit object can be used to display the silenced messages. +#' @param show_exceptions (logical) When `TRUE` (the default), prints all #' informational messages, for example rejection of the current proposal. #' Disable if you wish to silence these messages, but this is not usually #' recommended unless you are very confident that the model is correct up to diff --git a/man/model-method-sample.Rd b/man/model-method-sample.Rd index 99fa3a41e..2c6b693db 100644 --- a/man/model-method-sample.Rd +++ b/man/model-method-sample.Rd @@ -237,6 +237,11 @@ quantities block. If the parameters block is empty then using \code{parallel_chains} arguments will be set to \code{1}.} \item{show_messages}{(logical) When \code{TRUE} (the default), prints all +output during the sampling process, such as iteration numbers and elapsed times. +If the output is silenced then the \code{\link[=fit-method-output]{$output()}} method of +the resulting fit object can be used to display the silenced messages.} + +\item{show_exceptions}{(logical) When \code{TRUE} (the default), prints all informational messages, for example rejection of the current proposal. Disable if you wish to silence these messages, but this is not usually recommended unless you are very confident that the model is correct up to diff --git a/man/model-method-sample_mpi.Rd b/man/model-method-sample_mpi.Rd index c015a1e9e..a99b96952 100644 --- a/man/model-method-sample_mpi.Rd +++ b/man/model-method-sample_mpi.Rd @@ -215,6 +215,11 @@ Increasing this value will result in larger output CSV files and thus an increased usage of disk space.} \item{show_messages}{(logical) When \code{TRUE} (the default), prints all +output during the sampling process, such as iteration numbers and elapsed times. +If the output is silenced then the \code{\link[=fit-method-output]{$output()}} method of +the resulting fit object can be used to display the silenced messages.} + +\item{show_exceptions}{(logical) When \code{TRUE} (the default), prints all informational messages, for example rejection of the current proposal. Disable if you wish to silence these messages, but this is not usually recommended unless you are very confident that the model is correct up to