Merge pull request #469 from dirac-institute/debug_timer

Add DebugTimer to the pybind bindings

src/kbmod/run_search.py

@@ -64,6 +64,7 @@ def do_gpu_search(self, config, search):
         width = search.get_image_width()
         height = search.get_image_height()
         ang_lim = self.get_angle_limits(config)
+        debug = config["debug"]
 
         # Set the search bounds.
         if config["x_pixel_bounds"] and len(config["x_pixel_bounds"]) == 2:
@@ -76,16 +77,16 @@ def do_gpu_search(self, config, search):
         elif config["y_pixel_buffer"] and config["y_pixel_buffer"] > 0:
             search.set_start_bounds_y(-config["y_pixel_buffer"], height + config["y_pixel_buffer"])
 
-        search_start = time.time()
-        print("Starting Search")
-        print("---------------------------------------")
-        print(f"Average Angle = {config['average_angle']}")
-        print(f"Search Angle Limits = {ang_lim}")
-        print(f"Velocity Limits = {config['v_arr']}")
+        search_timer = kb.DebugTimer("Grid Search", debug)
+        if debug:
+            print(f"Average Angle = {config['average_angle']}")
+            print(f"Search Angle Limits = {ang_lim}")
+            print(f"Velocity Limits = {config['v_arr']}")
 
         # If we are using gpu_filtering, enable it and set the parameters.
         if config["gpu_filter"]:
-            print("Using in-line GPU sigmaG filtering methods", flush=True)
+            if debug:
+                print("Using in-line GPU sigmaG filtering methods", flush=True)
             coeff = SigmaGClipping.find_sigma_g_coeff(
                 config["sigmaG_lims"][0],
                 config["sigmaG_lims"][1],
@@ -115,7 +116,7 @@ def do_gpu_search(self, config, search):
             int(config["num_obs"]),
         )
 
-        print("Search finished in {0:.3f}s".format(time.time() - search_start), flush=True)
+        search_timer.stop()
         return search
 
     def run_search(self, config, stack):
@@ -135,7 +136,7 @@ def run_search(self, config, stack):
         keep : ResultList
             The results.
         """
-        start = time.time()
+        full_timer = kb.DebugTimer("KBMOD", config["debug"])
 
         # Collect the MJDs.
         mjds = []
@@ -153,34 +154,39 @@ def run_search(self, config, stack):
         search = kb.StackSearch(stack)
         search = self.do_gpu_search(config, search)
 
-        # Load the KBMOD results into Python and apply a filter based on
-        # 'filter_type'.
+        # Load the KBMOD results into Python and apply a filter based on 'filter_type'.
         keep = kb_post_process.load_and_filter_results(
             search,
             config["lh_level"],
             chunk_size=config["chunk_size"],
             max_lh=config["max_lh"],
         )
         if config["do_stamp_filter"]:
+            stamp_timer = kb.DebugTimer("stamp filtering", config["debug"])
             get_coadds_and_filter(
                 keep,
                 search.get_imagestack(),
                 config,
                 debug=config["debug"],
             )
+            stamp_timer.stop()
 
         if config["do_clustering"]:
+            cluster_timer = kb.DebugTimer("clustering", config["debug"])
             cluster_params = {}
             cluster_params["x_size"] = stack.get_width()
             cluster_params["y_size"] = stack.get_height()
             cluster_params["vel_lims"] = config["v_arr"]
             cluster_params["ang_lims"] = self.get_angle_limits(config)
             cluster_params["mjd"] = np.array(mjds)
             kb_post_process.apply_clustering(keep, cluster_params)
+            cluster_timer.stop()
 
         # Extract all the stamps for all time steps and append them onto the result rows.
         if config["save_all_stamps"]:
+            stamp_timer = kb.DebugTimer("computing all stamps", config["debug"])
             append_all_stamps(keep, search.get_imagestack(), config["stamp_radius"])
+            stamp_timer.stop()
 
         # TODO - Re-enable the known object counting once we have a way to pass
         # A WCS into the WorkUnit.
@@ -198,8 +204,7 @@ def run_search(self, config, stack):
         if config["result_filename"] is not None:
             keep.write_table(config["result_filename"])
 
-        end = time.time()
-        print("Time taken for patch: ", end - start)
+        full_timer.stop()
 
         return keep
 

src/kbmod/search/bindings.cpp

@@ -17,6 +17,7 @@ namespace py = pybind11;
 #include "stamp_creator.cpp"
 #include "kernel_testing_helpers.cpp"
 #include "psi_phi_array.cpp"
+#include "debug_timer.cpp"
 
 PYBIND11_MODULE(search, m) {
     m.attr("KB_NO_DATA") = pybind11::float_(search::NO_DATA);
@@ -40,6 +41,7 @@ PYBIND11_MODULE(search, m) {
     search::image_moments_bindings(m);
     search::stamp_parameters_bindings(m);
     search::psi_phi_array_binding(m);
+    search::debug_timer_binding(m);
     // Functions from raw_image.cpp
     m.def("create_median_image", &search::create_median_image);
     m.def("create_summed_image", &search::create_summed_image);

src/kbmod/search/debug_timer.cpp

@@ -0,0 +1,64 @@
+/* A very simple class that wraps debug output with timing. Used for
+   providing status updates as the system is running if in verbose
+   mode and nothing otherwise.
+
+   This is *not* a high precision timer meant to be used for benchmarking.
+*/
+
+#include "debug_timer.h"
+#include "pydocs/debug_timer_docs.h"
+
+namespace search {
+
+DebugTimer::DebugTimer(std::string name, bool verbose) {
+    name_ = name;
+    verbose_ = verbose;
+    start();
+}
+
+void DebugTimer::start() {
+    running_ = true;
+    t_start_ = std::chrono::system_clock::now();
+    if (verbose_) {
+        std::cout << "Starting " << name_ << "...\n" << std::flush;
+    }
+}
+
+void DebugTimer::stop() {
+    t_end_ = std::chrono::system_clock::now();
+    running_ = false;
+
+    if (verbose_) {
+        auto t_delta = std::chrono::duration_cast<std::chrono::milliseconds>(t_end_ - t_start_);
+        std::cout << name_ << " finished in " << t_delta.count() / 1000.0 << " seconds.\n" << std::flush;
+    }
+}
+
+double DebugTimer::read() {
+    std::chrono::milliseconds t_delta;
+    if (running_) {
+        std::chrono::time_point<std::chrono::system_clock> t_current_ = std::chrono::system_clock::now();
+        t_delta = std::chrono::duration_cast<std::chrono::milliseconds>(t_current_ - t_start_);
+    } else {
+        t_delta = std::chrono::duration_cast<std::chrono::milliseconds>(t_end_ - t_start_);
+    }
+
+    double result = t_delta.count() / 1000.0;
+    if (verbose_) {
+        std::cout << name_ << " at " << result << " seconds.\n" << std::flush;
+    }
+    return result;
+}
+
+#ifdef Py_PYTHON_H
+static void debug_timer_binding(py::module& m) {
+    using dbt = search::DebugTimer;
+    py::class_<dbt>(m, "DebugTimer", pydocs::DOC_DEBUG_TIMER)
+            .def(py::init<std::string, bool>())
+            .def("start", &dbt::start, pydocs::DOC_DEBUG_TIMER_start)
+            .def("stop", &dbt::stop, pydocs::DOC_DEBUG_TIMER_stop)
+            .def("read", &dbt::read, pydocs::DOC_DEBUG_TIMER_read);
+}
+#endif /* Py_PYTHON_H */
+
+} /* namespace search */

src/kbmod/search/debug_timer.h

@@ -13,31 +13,21 @@
 namespace search {
 class DebugTimer {
 public:
-    DebugTimer(std::string name, bool verbose) {
-        name_ = name;
-        verbose_ = verbose;
-        start();
-    }
-
-    void start() {
-        t_start_ = std::chrono::system_clock::now();
-        if (verbose_) {
-            std::cout << "Starting " << name_ << "...\n" << std::flush;
-        }
-    }
-
-    void stop() {
-        if (verbose_) {
-            std::chrono::time_point<std::chrono::system_clock> t_end = std::chrono::system_clock::now();
-            auto t_delta = std::chrono::duration_cast<std::chrono::milliseconds>(t_end - t_start_);
-            std::cout << name_ << " took " << t_delta.count() / 1000.0 << " seconds.\n" << std::flush;
-        }
-    }
+    DebugTimer(std::string name, bool verbose);
+
+    void start();
+    void stop();
+
+    // Read the time in decimal seconds without stopping the timer.
+    // If the timer is already stopped, read the duration from end time.
+    double read();
 
 private:
     std::chrono::time_point<std::chrono::system_clock> t_start_;
+    std::chrono::time_point<std::chrono::system_clock> t_end_;
     std::string name_;
     bool verbose_;
+    bool running_;
 };
 
 } /* namespace search */

src/kbmod/search/pydocs/debug_timer_docs.h

@@ -0,0 +1,36 @@
+#ifndef DEBUG_TIMER_DOCS_
+#define DEBUG_TIMER_DOCS_
+
+namespace pydocs {
+static const auto DOC_DEBUG_TIMER = R"doc(
+  A simple timer used for consistent outputing of timing results in verbose mode.
+  Timer automatically starts when it is created.
+
+  Parameters
+  ----------
+  name : `str`
+      The name string of the timer. Used for ouput.
+  verbose : `bool`
+      Output the timing information to the standard output.
+  )doc";
+
+static const auto DOC_DEBUG_TIMER_start = R"doc(
+  Start (or restart) the timer. If verbose outputs a message.
+  )doc";
+
+static const auto DOC_DEBUG_TIMER_stop = R"doc(
+  Stop the timer. If verbose outputs the duration.
+  )doc";
+
+static const auto DOC_DEBUG_TIMER_read = R"doc(
+  Read the timer duration as decimal seconds.
+
+  Returns
+  -------
+  duration : `float`
+      The duration of the timer.
+  )doc";
+
+}  // namespace pydocs
+
+#endif /* #define DEBUG_TIMER_DOCS_ */

tests/test_debug_timer.py

@@ -0,0 +1,26 @@
+import time
+import unittest
+
+from kbmod.search import DebugTimer
+
+
+class test_debug_timer(unittest.TestCase):
+    def test_create(self):
+        my_timer = DebugTimer("hi", False)
+        time1 = my_timer.read()
+
+        # We use sleep (100ms) because we are only interested in
+        # wall clock time having increased.
+        time.sleep(0.1)
+        time2 = my_timer.read()
+        self.assertGreater(time2, time1)
+
+        my_timer.stop()
+        time3 = my_timer.read()
+        time.sleep(0.1)
+        time4 = my_timer.read()
+        self.assertAlmostEqual(time3, time4)
+
+
+if __name__ == "__main__":
+    unittest.main()