diff --git a/src/kbmod/run_search.py b/src/kbmod/run_search.py index 9ca49f1ec..ce93821af 100644 --- a/src/kbmod/run_search.py +++ b/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,8 +154,7 @@ 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"], @@ -162,14 +162,17 @@ def run_search(self, config, stack): 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() @@ -177,10 +180,13 @@ def run_search(self, config, stack): 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 diff --git a/src/kbmod/search/bindings.cpp b/src/kbmod/search/bindings.cpp index 225bf477b..5e9962d77 100644 --- a/src/kbmod/search/bindings.cpp +++ b/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); diff --git a/src/kbmod/search/debug_timer.cpp b/src/kbmod/search/debug_timer.cpp new file mode 100644 index 000000000..e3606df2d --- /dev/null +++ b/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(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 t_current_ = std::chrono::system_clock::now(); + t_delta = std::chrono::duration_cast(t_current_ - t_start_); + } else { + t_delta = std::chrono::duration_cast(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_(m, "DebugTimer", pydocs::DOC_DEBUG_TIMER) + .def(py::init()) + .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 */ diff --git a/src/kbmod/search/debug_timer.h b/src/kbmod/search/debug_timer.h index a184bc0db..9eb094c2c 100644 --- a/src/kbmod/search/debug_timer.h +++ b/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 t_end = std::chrono::system_clock::now(); - auto t_delta = std::chrono::duration_cast(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 t_start_; + std::chrono::time_point t_end_; std::string name_; bool verbose_; + bool running_; }; } /* namespace search */ diff --git a/src/kbmod/search/pydocs/debug_timer_docs.h b/src/kbmod/search/pydocs/debug_timer_docs.h new file mode 100644 index 000000000..cbedbbb07 --- /dev/null +++ b/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_ */ diff --git a/tests/test_debug_timer.py b/tests/test_debug_timer.py new file mode 100644 index 000000000..41b3d831d --- /dev/null +++ b/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()