Implement simulation-scoped log levels

NEWS.md

@@ -4,6 +4,7 @@
 
 * The C++ core has been refactorised into a header-only library under `inst/include` (#147 closing #145). Therefore, from now on it is possible to extend the C++ API from another package by listing `simmer` under the `LinkingTo` field in the DESCRIPTION file.
 * New generic `monitor` constructor enables the development of new monitoring backends in other packages (179f656, as part of #147).
+* New simulation-scoped logging levels. The `log_` activity has a new argument `level` which determines whether the message is printed depending on a global `log_level` defined in the `simmer` constructor (#152).
 
 ## Minor changes and fixes:
 

R/RcppExports.R

@@ -257,12 +257,12 @@ Wait__new <- function() {
     .Call(`_simmer_Wait__new`)
 }
 
-Log__new <- function(message) {
-    .Call(`_simmer_Log__new`, message)
+Log__new <- function(message, level) {
+    .Call(`_simmer_Log__new`, message, level)
 }
 
-Log__new_func <- function(message) {
-    .Call(`_simmer_Log__new_func`, message)
+Log__new_func <- function(message, level) {
+    .Call(`_simmer_Log__new_func`, message, level)
 }
 
 activity_get_count_ <- function(activity_) {
@@ -357,8 +357,8 @@ get_queue_count_selected_ <- function(sim_, id) {
     .Call(`_simmer_get_queue_count_selected_`, sim_, id)
 }
 
-Simulator__new <- function(name, verbose, mon) {
-    .Call(`_simmer_Simulator__new`, name, verbose, mon)
+Simulator__new <- function(name, verbose, mon, log_level) {
+    .Call(`_simmer_Simulator__new`, name, verbose, mon, log_level)
 }
 
 reset_ <- function(sim_) {

R/simmer-class.R

@@ -2,11 +2,11 @@ Simmer <- R6Class("simmer",
   public = list(
     name = NA,
 
-    initialize = function(name="anonymous", verbose=FALSE, mon=monitor_mem()) {
-      check_args(name="string", verbose="flag", mon="monitor")
+    initialize = function(name="anonymous", verbose=FALSE, mon=monitor_mem(), log_level=0) {
+      check_args(name="string", verbose="flag", mon="monitor", log_level="number")
       self$name <- name
       private$mon <- mon
-      private$sim_obj <- Simulator__new(name, verbose, mon$get_xptr())
+      private$sim_obj <- Simulator__new(name, verbose, mon$get_xptr(), log_level)
       self
     },
 

R/simmer-methods.R

@@ -6,6 +6,7 @@
 #' @param verbose enable showing activity information.
 #' @param mon monitor (in memory by default); see \code{\link{monitor}} for
 #' other options.
+#' @param log_level debugging level (see \code{\link{log_}}).
 #'
 #' @return Returns a simulation environment.
 #' @seealso
@@ -49,8 +50,8 @@
 #' env %>% peek()          # time for the next event
 #' env %>% stepn()         # execute next event
 #'
-simmer <- function(name="anonymous", verbose=FALSE, mon=monitor_mem())
-  Simmer$new(name, verbose, mon)
+simmer <- function(name="anonymous", verbose=FALSE, mon=monitor_mem(), log_level=0)
+  Simmer$new(name, verbose, mon, log_level)
 
 #' Reset a Simulator
 #'

R/trajectory-activities.R

@@ -483,10 +483,13 @@ wait.trajectory <- function(.trj) .trj$wait()
 #' @inheritParams seize
 #' @param message the message to display, accepts either a string or a callable object
 #' (a function) which must return a string.
+#' @param level debugging level. The \code{message} will be printed if, and only if,
+#' the \code{level} provided is less or equal to the \code{log_level} defined in the
+#' simulation environment (see \code{\link{simmer}}).
 #'
 #' @return Returns the trajectory object.
 #' @export
-log_ <- function(.trj, message) UseMethod("log_")
+log_ <- function(.trj, message, level=0) UseMethod("log_")
 
 #' @export
-log_.trajectory <- function(.trj, message) .trj$log(message)
+log_.trajectory <- function(.trj, message, level=0) .trj$log(message, level)

R/trajectory-class.R

@@ -346,12 +346,12 @@ Trajectory <- R6Class("trajectory",
 
     wait = function() { private$add_activity(Wait__new()) },
 
-    log = function(message) {
-      check_args(message=c("string", "function"))
+    log = function(message, level=0) {
+      check_args(message=c("string", "function"), level="number")
       switch(
         binarise(is.function(message)),
-        private$add_activity(Log__new(message)),
-        private$add_activity(Log__new_func(message))
+        private$add_activity(Log__new(message, level)),
+        private$add_activity(Log__new_func(message, level))
       )
     }
   ),

inst/include/simmer/activity/log.h

@@ -14,21 +14,25 @@ namespace simmer {
   public:
     CLONEABLE(Log<T>)
 
-    Log(const T& message) : Activity("Log"), message(message) {}
+    Log(const T& message, int level)
+      : Activity("Log"), message(message), level(level) {}
 
     void print(unsigned int indent = 0, bool verbose = false, bool brief = false) {
       Activity::print(indent, verbose, brief);
-      internal::print(brief, true, "message", "");
+      internal::print(brief, true, "message", "message", ARG(level));
     }
 
     double run(Arrival* arrival) {
-      Rcpp::Rcout << arrival->sim->now() << ": " << arrival->name << ": " <<
-        get<std::string>(message, arrival) << std::endl;
+      int log_level = arrival->sim->log_level;
+      if (log_level < 0 || (level >= 0 && log_level >= level))
+        Rcpp::Rcout << arrival->sim->now() << ": " << arrival->name << ": " <<
+          get<std::string>(message, arrival) << std::endl;
       return 0;
     }
 
   protected:
     T message;
+    int level;
   };
 
 } // namespace simmer

inst/include/simmer/simulator.h

@@ -50,15 +50,18 @@ namespace simmer {
     std::string name;
     bool verbose;
     Monitor* mon;
+    int log_level;
 
     /**
      * Constructor.
-     * @param name    simulator name
-     * @param verbose verbose flag
-     * @param mon     monitoring object
+     * @param name      simulator name
+     * @param verbose   verbose flag
+     * @param mon       monitoring object
+     * @param log_level debugging level (for activities)
      */
-    Simulator(const std::string& name, bool verbose, Monitor* mon)
-      : name(name), verbose(verbose), mon(mon), now_(0), process_(NULL), b_count(0) {}
+    Simulator(const std::string& name, bool verbose, Monitor* mon, int log_level)
+      : name(name), verbose(verbose), mon(mon), log_level(log_level), now_(0),
+        process_(NULL), b_count(0) {}
 
     ~Simulator();
 

src/RcppExports.cpp

@@ -802,24 +802,26 @@ BEGIN_RCPP
 END_RCPP
 }
 // Log__new
-SEXP Log__new(const std::string& message);
-RcppExport SEXP _simmer_Log__new(SEXP messageSEXP) {
+SEXP Log__new(const std::string& message, int level);
+RcppExport SEXP _simmer_Log__new(SEXP messageSEXP, SEXP levelSEXP) {
 BEGIN_RCPP
     Rcpp::RObject rcpp_result_gen;
     Rcpp::RNGScope rcpp_rngScope_gen;
     Rcpp::traits::input_parameter< const std::string& >::type message(messageSEXP);
-    rcpp_result_gen = Rcpp::wrap(Log__new(message));
+    Rcpp::traits::input_parameter< int >::type level(levelSEXP);
+    rcpp_result_gen = Rcpp::wrap(Log__new(message, level));
     return rcpp_result_gen;
 END_RCPP
 }
 // Log__new_func
-SEXP Log__new_func(const Function& message);
-RcppExport SEXP _simmer_Log__new_func(SEXP messageSEXP) {
+SEXP Log__new_func(const Function& message, int level);
+RcppExport SEXP _simmer_Log__new_func(SEXP messageSEXP, SEXP levelSEXP) {
 BEGIN_RCPP
     Rcpp::RObject rcpp_result_gen;
     Rcpp::RNGScope rcpp_rngScope_gen;
     Rcpp::traits::input_parameter< const Function& >::type message(messageSEXP);
-    rcpp_result_gen = Rcpp::wrap(Log__new_func(message));
+    Rcpp::traits::input_parameter< int >::type level(levelSEXP);
+    rcpp_result_gen = Rcpp::wrap(Log__new_func(message, level));
     return rcpp_result_gen;
 END_RCPP
 }
@@ -1093,15 +1095,16 @@ BEGIN_RCPP
 END_RCPP
 }
 // Simulator__new
-SEXP Simulator__new(const std::string& name, bool verbose, SEXP mon);
-RcppExport SEXP _simmer_Simulator__new(SEXP nameSEXP, SEXP verboseSEXP, SEXP monSEXP) {
+SEXP Simulator__new(const std::string& name, bool verbose, SEXP mon, int log_level);
+RcppExport SEXP _simmer_Simulator__new(SEXP nameSEXP, SEXP verboseSEXP, SEXP monSEXP, SEXP log_levelSEXP) {
 BEGIN_RCPP
     Rcpp::RObject rcpp_result_gen;
     Rcpp::RNGScope rcpp_rngScope_gen;
     Rcpp::traits::input_parameter< const std::string& >::type name(nameSEXP);
     Rcpp::traits::input_parameter< bool >::type verbose(verboseSEXP);
     Rcpp::traits::input_parameter< SEXP >::type mon(monSEXP);
-    rcpp_result_gen = Rcpp::wrap(Simulator__new(name, verbose, mon));
+    Rcpp::traits::input_parameter< int >::type log_level(log_levelSEXP);
+    rcpp_result_gen = Rcpp::wrap(Simulator__new(name, verbose, mon, log_level));
     return rcpp_result_gen;
 END_RCPP
 }
@@ -1310,8 +1313,8 @@ static const R_CallMethodDef CallEntries[] = {
     {"_simmer_UnTrap__new", (DL_FUNC) &_simmer_UnTrap__new, 1},
     {"_simmer_UnTrap__new_func", (DL_FUNC) &_simmer_UnTrap__new_func, 1},
     {"_simmer_Wait__new", (DL_FUNC) &_simmer_Wait__new, 0},
-    {"_simmer_Log__new", (DL_FUNC) &_simmer_Log__new, 1},
-    {"_simmer_Log__new_func", (DL_FUNC) &_simmer_Log__new_func, 1},
+    {"_simmer_Log__new", (DL_FUNC) &_simmer_Log__new, 2},
+    {"_simmer_Log__new_func", (DL_FUNC) &_simmer_Log__new_func, 2},
     {"_simmer_activity_get_count_", (DL_FUNC) &_simmer_activity_get_count_, 1},
     {"_simmer_activity_print_", (DL_FUNC) &_simmer_activity_print_, 3},
     {"_simmer_activity_get_next_", (DL_FUNC) &_simmer_activity_get_next_, 1},
@@ -1335,7 +1338,7 @@ static const R_CallMethodDef CallEntries[] = {
     {"_simmer_get_server_count_selected_", (DL_FUNC) &_simmer_get_server_count_selected_, 2},
     {"_simmer_get_queue_count_", (DL_FUNC) &_simmer_get_queue_count_, 2},
     {"_simmer_get_queue_count_selected_", (DL_FUNC) &_simmer_get_queue_count_selected_, 2},
-    {"_simmer_Simulator__new", (DL_FUNC) &_simmer_Simulator__new, 3},
+    {"_simmer_Simulator__new", (DL_FUNC) &_simmer_Simulator__new, 4},
     {"_simmer_reset_", (DL_FUNC) &_simmer_reset_, 1},
     {"_simmer_now_", (DL_FUNC) &_simmer_now_, 1},
     {"_simmer_peek_", (DL_FUNC) &_simmer_peek_, 2},

src/activity.cpp

@@ -357,13 +357,13 @@ SEXP UnTrap__new_func(const Function& signals) {
 SEXP Wait__new() { return XPtr<Wait>(new Wait()); }
 
 //[[Rcpp::export]]
-SEXP Log__new(const std::string& message) {
-  return XPtr<Log<std::string> >(new Log<std::string>(message));
+SEXP Log__new(const std::string& message, int level) {
+  return XPtr<Log<std::string> >(new Log<std::string>(message, level));
 }
 
 //[[Rcpp::export]]
-SEXP Log__new_func(const Function& message) {
-  return XPtr<Log<Function> >(new Log<Function>(message));
+SEXP Log__new_func(const Function& message, int level) {
+  return XPtr<Log<Function> >(new Log<Function>(message, level));
 }
 
 //[[Rcpp::export]]

src/simulator.cpp

@@ -4,8 +4,8 @@ using namespace Rcpp;
 using namespace simmer;
 
 //[[Rcpp::export]]
-SEXP Simulator__new(const std::string& name, bool verbose, SEXP mon) {
-  return XPtr<Simulator>(new Simulator(name, verbose, XPtr<Monitor>(mon)));
+SEXP Simulator__new(const std::string& name, bool verbose, SEXP mon, int log_level) {
+  return XPtr<Simulator>(new Simulator(name, verbose, XPtr<Monitor>(mon), log_level));
 }
 
 //[[Rcpp::export]]

tests/testthat/test-trajectory-log.R

@@ -1,21 +1,37 @@
 context("log")
 
-test_that("a message is correctly printed (1)", {
+test_that("messages are correctly printed depending on the log_level", {
   t <- trajectory() %>%
-    log_("hello world!")
+    log_(function() "Message 0") %>%
+    log_("Message 1", level=1) %>%
+    log_("Message 2", level=2) %>%
+    log_("Message 3", level=Inf)
 
-  env <- simmer(verbose = TRUE) %>%
-    add_generator("entity", t, at(5))
+  expect_output(
+    simmer(verbose=TRUE) %>%
+      add_generator("dummy", t, at(5)) %>%
+      run(),
+    "5: dummy0: Message 0"
+  )
 
-  expect_output(run(env), "5: entity0: hello world!")
-})
-
-test_that("a message is correctly printed (2)", {
-  t <- trajectory() %>%
-    log_(function() "hello world!")
+  expect_output(
+    simmer(verbose=TRUE, log_level=1) %>%
+      add_generator("dummy", t, at(5)) %>%
+      run(),
+    "5: dummy0: Message 0.*5: dummy0: Message 1"
+  )
 
-  env <- simmer(verbose = TRUE) %>%
-    add_generator("entity", t, at(5))
+  expect_output(
+    simmer(verbose=TRUE, log_level=5) %>%
+      add_generator("dummy", t, at(5)) %>%
+      run(),
+    "5: dummy0: Message 0.*5: dummy0: Message 1.*5: dummy0: Message 2"
+  )
 
-  expect_output(run(env), "5: entity0: hello world!")
+  expect_output(
+    simmer(verbose=TRUE, log_level=Inf) %>%
+      add_generator("dummy", t, at(5)) %>%
+      run(),
+    "5: dummy0: Message 0.*5: dummy0: Message 1.*5: dummy0: Message 2.*5: dummy0: Message 3"
+  )
 })

vignettes/simmer-03-trajectories.Rmd

@@ -86,17 +86,25 @@ Additionally, you may want to try the `simmer.bricks` package, a plugin for `sim
 
 ### `log_()`
 
-The `log_(., message`) method just prints a given message preceded by the simulation time and the name of the arrival, for debugging purposes:
+The `log_(., message, level`) method just prints a given message preceded by the simulation time and the name of the arrival, for debugging purposes. The logging level is defined in the simulation environment:
 
 ```{r}
-set.seed(1234)
-
 t <- trajectory() %>%
-  log_("hello world!")
+  log_("this is always printed") %>% # level = 0 by default
+  log_("this is printed if `log_level>=1`", level = 1) %>%
+  log_("this is printed if `log_level>=2`", level = 2)
 
 simmer() %>%
-  add_generator("dummy", t, function() rexp(1, 1)) %>%
-  run(5) %>% invisible
+  add_generator("dummy", t, at(0)) %>%
+  run() %>% invisible
+
+simmer(log_level = 1) %>%
+  add_generator("dummy", t, at(0)) %>%
+  run() %>% invisible
+
+simmer(log_level = Inf) %>%
+  add_generator("dummy", t, at(0)) %>%
+  run() %>% invisible
 ```
 
 ### `set_attribute()`