Merge pull request #3373 from stan-dev/fix/3372-gq-timings

Add timing information to standalone GQ

Author: WardBrian

src/stan/services/sample/standalone_gqs.hpp

@@ -67,6 +67,8 @@ int standalone_generate(const Model &model, const Eigen::MatrixXd &draws,
 
   std::vector<double> unconstrained_params_r;
   std::vector<double> row(draws.cols());
+  auto start = std::chrono::steady_clock::now();
+
   try {
     for (size_t i = 0; i < draws.rows(); ++i) {
       Eigen::Map<Eigen::VectorXd>(&row[0], draws.cols()) = draws.row(i);
@@ -85,6 +87,13 @@ int standalone_generate(const Model &model, const Eigen::MatrixXd &draws,
     logger.error(e.what());
     return error_codes::SOFTWARE;
   }
+  auto end = std::chrono::steady_clock::now();
+  double gq_delta_t
+      = std::chrono::duration_cast<std::chrono::milliseconds>(end - start)
+            .count()
+        / 1000.0;
+  writer.write_timing(gq_delta_t);
+
   return error_codes::OK;
 }
 
@@ -161,6 +170,7 @@ int standalone_generate(const Model &model, const int num_chains,
           std::stringstream msg;
           for (size_t slice_idx = r.begin(); slice_idx != r.end();
                ++slice_idx) {
+            auto start = std::chrono::steady_clock::now();
             for (size_t i = 0; i < draws[slice_idx].rows(); ++i) {
               if (error_any)
                 return;
@@ -178,6 +188,13 @@ int standalone_generate(const Model &model, const int num_chains,
               writers[slice_idx].write_gq_values(model, rngs[slice_idx],
                                                  unconstrained_params_r);
             }
+            auto end = std::chrono::steady_clock::now();
+            double gq_delta_t
+                = std::chrono::duration_cast<std::chrono::milliseconds>(end
+                                                                        - start)
+                      .count()
+                  / 1000.0;
+            writers[slice_idx].write_timing(gq_delta_t);
           }
         },
         tbb::simple_partitioner());

src/stan/services/util/gq_writer.hpp

@@ -16,6 +16,28 @@ namespace stan {
 namespace services {
 namespace util {
 
+namespace internal {
+
+/**
+ * Internal method
+ *
+ * Logs timing information
+ *
+ * @param[in] deltaT time in seconds
+ */
+template <typename F>
+void write_timing(double deltaT, F writer) {
+  std::string title(" Elapsed Time: ");
+  writer("");
+
+  std::stringstream ss1;
+  ss1 << title << deltaT << " seconds (Generated Quantities)";
+  writer(ss1.str());
+
+  writer("");
+}
+}  // namespace internal
+
 /**
  * gq_writer writes out
  *
@@ -128,6 +150,18 @@ class gq_writer {
     }
     sample_writer_(values);
   }
+
+  /**
+   * Print timing information to all streams
+   *
+   * @param[in] deltaT time in seconds
+   */
+  void write_timing(double deltaT) {
+    internal::write_timing(
+        deltaT, [this](const std::string& msg) { this->sample_writer_(msg); });
+    internal::write_timing(
+        deltaT, [this](const std::string& msg) { this->logger_.info(msg); });
+  }
 };
 
 }  // namespace util

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

@@ -48,6 +48,6 @@ TEST_F(ServicesStandaloneGQ4, genDraws_gq_test_vec_len_1) {
       sample_writer);
   EXPECT_EQ(return_code, stan::services::error_codes::OK);
   EXPECT_EQ(count_matches("y_est", sample_ss.str()), 5);
-  EXPECT_EQ(count_matches("\n", sample_ss.str()), 1001);
+  EXPECT_EQ(count_matches("\n", sample_ss.str()), 1004);
   match_csv_columns(multidim_csv.samples, sample_ss.str(), 1000, 0, 6);
 }

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

@@ -55,6 +55,6 @@ TEST_F(ServicesStandaloneGQ2, genDraws_gq_test_multidim) {
       sample_writer);
   EXPECT_EQ(return_code, stan::services::error_codes::OK);
   EXPECT_EQ(count_matches("gq_ar_mat", sample_ss.str()), 120);
-  EXPECT_EQ(count_matches("\n", sample_ss.str()), 1001);
+  EXPECT_EQ(count_matches("\n", sample_ss.str()), 1004);
   match_csv_columns(multidim_csv.samples, sample_ss.str(), 1000, 120, 127);
 }

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

@@ -74,7 +74,7 @@ TEST_F(ServicesStandaloneGQ, genDraws_bernoulli) {
   for (int i = 0; i < num_chains; i++) {
     EXPECT_EQ(count_matches("mu", sample_ss[i].str()), 1);
     EXPECT_EQ(count_matches("y_rep", sample_ss[i].str()), 10);
-    EXPECT_EQ(count_matches("\n", sample_ss[i].str()), 1001);
+    EXPECT_EQ(count_matches("\n", sample_ss[i].str()), 1004);
     match_csv_columns(bern_csv.samples, sample_ss[i].str(), 1000, 1, 8);
   }
 }

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

@@ -55,7 +55,7 @@ TEST_F(ServicesStandaloneGQ, genDraws_bernoulli) {
   EXPECT_EQ(return_code, stan::services::error_codes::OK);
   EXPECT_EQ(count_matches("mu", sample_ss.str()), 1);
   EXPECT_EQ(count_matches("y_rep", sample_ss.str()), 10);
-  EXPECT_EQ(count_matches("\n", sample_ss.str()), 1001);
+  EXPECT_EQ(count_matches("\n", sample_ss.str()), 1004);
   match_csv_columns(bern_csv.samples, sample_ss.str(), 1000, 1, 8);
 }
 

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

@@ -46,6 +46,18 @@ TEST_F(ServicesUtilGQWriter, t2) {
   EXPECT_EQ(count_matches("nan", sample_ss.str()), 0);
 }
 
+TEST_F(ServicesUtilGQWriter, timing) {
+  stan::callbacks::stream_writer sample_writer(sample_ss, "#");
+  stan::callbacks::stream_logger logger(logger_ss, logger_ss, logger_ss,
+                                        logger_ss, logger_ss);
+  stan::services::util::gq_writer writer(sample_writer, logger, 2);
+  writer.write_timing(4.31);
+  // model test_gq.stan generates 4 values, 3 commas
+  EXPECT_EQ(count_matches("4.31 seconds", logger_ss.str()), 1);
+  EXPECT_EQ(count_matches("4.31 seconds", sample_ss.str()), 1)
+      << sample_ss.str();
+}
+
 TEST_F(ServicesUtilGQWriter, TestExceptions) {
   stan::callbacks::stream_writer sample_writer(sample_ss, "");
   stan::callbacks::stream_logger logger(logger_ss, logger_ss, logger_ss,