Feature/timer

src/stan/services/sample/fixed_param.hpp

@@ -74,10 +74,13 @@ namespace stan {
         util::generate_transitions(sampler, num_samples, 0, num_samples,
                                    num_thin, refresh, true, false, writer,
                                    s, model, rng, interrupt, logger);
-        clock_t end = clock();
+        if (refresh > 0) {
+          clock_t end = clock();
 
-        double sampleDeltaT = static_cast<double>(end - start) / CLOCKS_PER_SEC;
-        writer.write_timing(0.0, sampleDeltaT);
+          double sampleDeltaT = static_cast<double>(end - start)
+                              / CLOCKS_PER_SEC;
+          writer.write_timing(0.0, sampleDeltaT);
+        }
 
         return error_codes::OK;
       }

src/stan/services/util/generate_transitions.hpp

@@ -5,6 +5,7 @@
 #include <stan/callbacks/interrupt.hpp>
 #include <stan/mcmc/base_mcmc.hpp>
 #include <stan/services/util/mcmc_writer.hpp>
+#include <time.h>
 #include <string>
 
 namespace stan {
@@ -22,8 +23,9 @@ namespace stan {
        * @param[in] finish end iteration number used for printing messages
        * @param[in] num_thin when save is true, a draw will be written to the
        *   mcmc_writer every num_thin iterations
-       * @param[in] refresh number of iterations to print a message. If
-       *   refresh is zero, iteration number messages will not be printed
+       * @param[in] refresh initial number of seconds between progress messages.
+       *   If refresh is zero, no messages will be printed. If refresh is
+       *   positive, then it gets doubled locally after each progres report.
        * @param[in] save if save is true, the transitions will be written
        *   to the mcmc_writer. If false, transitions will not be written
        * @param[in] warmup indicates whether these transitions are warmup. Used
@@ -47,13 +49,16 @@ namespace stan {
                                 Model& model, RNG& base_rng,
                                 callbacks::interrupt& callback,
                                 callbacks::logger& logger) {
+        time_t last_time;
+        time(&last_time);
+        double refresh_local = refresh;
+        int last_iter = 0;
         for (int m = 0; m < num_iterations; ++m) {
           callback();
-
-          if (refresh > 0
-              && (start + m + 1 == finish
-                  || m == 0
-                  || (m + 1) % refresh == 0)) {
+          time_t now;
+          time(&now);
+          int time_diff = difftime(now, last_time);
+          if (refresh > 0 && time_diff > refresh_local) {
             int it_print_width
               = std::ceil(std::log10(static_cast<double>(finish)));
             std::stringstream message;
@@ -64,8 +69,15 @@ namespace stan {
                     << static_cast<int>( (100.0 * (start + m + 1)) / finish )
                     << "%] ";
             message << (warmup ? " (Warmup)" : " (Sampling)");
-
+            message << " Time left: " << std::setw(4)
+                    << (num_iterations - m)
+                     / (60.0 * (m - last_iter) / time_diff)
+                    << " min";
             logger.info(message);
+
+            time(&last_time);
+            last_iter = m;
+            refresh_local *= 2;
           }
 
           init_s = sampler.transition(init_s, logger);

src/stan/services/util/run_adaptive_sampler.hpp

@@ -86,11 +86,13 @@ namespace stan {
                                    writer,
                                    s, model, rng,
                                    interrupt, logger);
-        end = clock();
-        double sample_delta_t
-          = static_cast<double>(end - start) / CLOCKS_PER_SEC;
+        if (refresh > 0) {
+          end = clock();
+          double sample_delta_t
+            = static_cast<double>(end - start) / CLOCKS_PER_SEC;
 
-        writer.write_timing(warm_delta_t, sample_delta_t);
+          writer.write_timing(warm_delta_t, sample_delta_t);
+        }
       }
     }
   }

src/stan/services/util/run_sampler.hpp

@@ -71,11 +71,13 @@ namespace stan {
                                    writer,
                                    s, model, rng,
                                    interrupt, logger);
-        end = clock();
-        double sample_delta_t
-          = static_cast<double>(end - start) / CLOCKS_PER_SEC;
+        if (refresh > 0) {
+          end = clock();
+          double sample_delta_t
+            = static_cast<double>(end - start) / CLOCKS_PER_SEC;
 
-        writer.write_timing(warm_delta_t, sample_delta_t);
+          writer.write_timing(warm_delta_t, sample_delta_t);
+        }
       }
     }
   }

src/test/unit/services/sample/fixed_param_test.cpp

@@ -149,7 +149,7 @@ TEST_F(ServicesSamplesFixedParam, output_regression) {
   double init_radius = 0;
   int num_iterations = 10;
 
-  int refresh = 0;
+  int refresh = 5;
   stan::test::unit::instrumented_interrupt interrupt;
   EXPECT_EQ(interrupt.call_count(), 0);
 

src/test/unit/services/sample/hmc_nuts_dense_e_adapt_test.cpp

@@ -160,7 +160,7 @@ TEST_F(ServicesSampleHmcNutsDenseEAdapt, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   int max_depth = 8;

src/test/unit/services/sample/hmc_nuts_dense_e_test.cpp

@@ -148,7 +148,7 @@ TEST_F(ServicesSampleHmcNutsDenseE, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   int max_depth = 8;

src/test/unit/services/sample/hmc_nuts_diag_e_adapt_test.cpp

@@ -171,7 +171,7 @@ TEST_F(ServicesSampleHmcNutsDiagEAdapt, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   int max_depth = 8;

src/test/unit/services/sample/hmc_nuts_diag_e_test.cpp

@@ -150,7 +150,7 @@ TEST_F(ServicesSampleHmcNutsDiagE, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   int max_depth = 8;

src/test/unit/services/sample/hmc_nuts_unit_e_adapt_test.cpp

@@ -158,7 +158,7 @@ TEST_F(ServicesSampleHmcNutsUnitEAdapt, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   int max_depth = 8;

src/test/unit/services/sample/hmc_nuts_unit_e_test.cpp

@@ -146,7 +146,7 @@ TEST_F(ServicesSampleHmcNutsUnitE, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   int max_depth = 8;

src/test/unit/services/sample/hmc_static_dense_e_adapt_test.cpp

@@ -168,7 +168,7 @@ TEST_F(ServicesSampleHmcStaticDenseEAdapt, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   double int_time = 8;

src/test/unit/services/sample/hmc_static_dense_e_test.cpp

@@ -144,7 +144,7 @@ TEST_F(ServicesSampleHmcStaticDenseE, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   double int_time = 8;

src/test/unit/services/sample/hmc_static_diag_e_adapt_test.cpp

@@ -168,7 +168,7 @@ TEST_F(ServicesSampleHmcStaticDiagEAdapt, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   double int_time = 8;

src/test/unit/services/sample/hmc_static_diag_e_test.cpp

@@ -145,7 +145,7 @@ TEST_F(ServicesSampleHmcStaticDiagE, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   double int_time = 8;

src/test/unit/services/sample/hmc_static_unit_e_adapt_test.cpp

@@ -168,7 +168,7 @@ TEST_F(ServicesSampleHmcStaticUnitEAdapt, output_regression) {
   int num_samples = 400;
   int num_thin = 5;
   bool save_warmup = true;
-  int refresh = 0;
+  int refresh = 5;
   double stepsize = 0.1;
   double stepsize_jitter = 0;
   double int_time = 8;

src/test/unit/services/util/run_adaptive_sampler_test.cpp

@@ -16,7 +16,7 @@ class ServicesUtil : public testing::Test {
       num_warmup(0),
       num_samples(0),
       num_thin(1),
-      refresh(0),
+      refresh(5),
       save_warmup(false) {
     cont_vector.push_back(0);
     cont_vector.push_back(0);
@@ -239,12 +239,6 @@ TEST_F(ServicesUtil, num_warmup_num_samples_refresh) {
                                              sample_writer, diagnostic_writer);
   EXPECT_EQ(num_warmup + num_samples, interrupt.call_count());
 
-  EXPECT_EQ((num_warmup + num_samples) / refresh + 2 + 3 + 2, logger.call_count())
-    << "Writes 1 to start warmup, 1 to start post-warmup, and "
-    << "(num_warmup + num_samples) / refresh, then the elapsed time";
-  EXPECT_EQ(logger.call_count(), logger.call_count_info())
-    << "No other calls to logger";
-
   EXPECT_EQ(num_samples + 8,
             sample_writer.call_count());
   EXPECT_EQ(1, sample_writer.call_count("vector_string"))

src/test/unit/services/util/run_sampler_test.cpp

@@ -66,7 +66,7 @@ class ServicesUtil : public testing::Test {
       num_warmup(0),
       num_samples(0),
       num_thin(1),
-      refresh(0),
+      refresh(5),
       save_warmup(false) {
     cont_vector.push_back(0);
     cont_vector.push_back(0);
@@ -286,12 +286,6 @@ TEST_F(ServicesUtil, num_warmup_num_samples_refresh) {
                                     sample_writer, diagnostic_writer);
   EXPECT_EQ(num_warmup + num_samples, interrupt.call_count());
 
-  EXPECT_EQ((num_warmup + num_samples) / refresh + 2 + 3 + 2, logger.call_count())
-    << "Writes 1 to start warmup, 1 to start post-warmup, and "
-    << "(num_warmup + num_samples) / refresh, then the elapsed time";
-  EXPECT_EQ(logger.call_count(), logger.call_count_info())
-    << "No other calls to logger";
-
   EXPECT_EQ(num_samples + 7,
             sample_writer.call_count());
   EXPECT_EQ(1, sample_writer.call_count("vector_string"))