Merge pull request #1237 from KrisThielemans/timings

add utility to perform timings and some performance improvements

documentation/STIR-UsersGuide.tex

@@ -3699,6 +3699,13 @@ \subsubsection{
 a popular Monte Carlo simulator for PET and SPECT. This
 is all preliminary. Check out the \texttt{README.txt} in the \textbf{STIR/SimSET} directory.
 
+\subsubsection{
+Performing timings of certain operations}
+The \textbf{stir\_timings} utility  is mostly useful for developers,
+but you could use it to optimise the number of OpenMP threads to use for your data.
+
+Run the utility without any arguments to get a help message.
+If you want to know what is actually timed, you will have to look at the source code.
 
 \subsection{
 User-selectable components}

documentation/release_5.2.htm

@@ -55,6 +55,11 @@ <h3>New functionality</h3>
     (still somewhat preliminary).
     <br /><a href="https://github.com/UCL/STIR/pull/1182/">PR #1182</a>.
   </li>
+  <li>
+    The new <tt>stir_timings</tt> utility  is mostly useful for developers,
+    but you could use it to optimise the number of OpenMP threads to use for your data.
+    <br /><a href="https://github.com/UCL/STIR/pull/1237/">PR #1237</a>.
+  </li>
 </ul>
 
 <h3>New examples</h3>

src/analytic/FBP3DRP/FBP3DRPReconstruction.cxx

@@ -396,7 +396,6 @@ actual_reconstruct(shared_ptr<DiscretisedDensity<3,float> > const& target_image_
   alpha_fit = 1.0F;
   beta_fit = 0.0F;
 
-  start_timers();
   {
     //char file[max_filename_length];
     //sprintf(file,"%s.full_log",output_filename_prefix.c_str());
@@ -564,7 +563,6 @@ actual_reconstruct(shared_ptr<DiscretisedDensity<3,float> > const& target_image_
   if(display_level>0) 
     display(image, image.find_max(), "Final image");
 
-  stop_timers();
   do_log_file(image);
 
   full_log.close();

src/include/stir/DataProcessor.inl

@@ -74,14 +74,14 @@ Succeeded
 DataProcessor<DataT>::
 apply(DataT& data)
 {
-  start_timers();
   //assert(consistency_check(data) == Succeeded::yes);
   if (!is_set_up_already )
     if (set_up(data) == Succeeded::no)
       {
 	warning("DataProcessor::apply: Building was unsuccesfull. No processing done.\n");
 	return Succeeded::no;
       }
+  start_timers();
   virtual_apply(data);
   stop_timers();
   return Succeeded::yes;
@@ -94,14 +94,14 @@ DataProcessor<DataT>::
 apply(DataT& data,
       const DataT& in_data)
 {
-  start_timers();
   //assert(consistency_check(in_data) == Succeeded::yes);
   if (!is_set_up_already )
     if (set_up(in_data) == Succeeded::no)
       {
 	warning("DataProcessor::apply: Building was unsuccesfull. No processing done.\n");
 	return Succeeded::no;
       }
+  start_timers();
   virtual_apply(data, in_data);
   stop_timers();
   return Succeeded::yes;

src/include/stir/HighResWallClockTimer.h

@@ -153,11 +153,10 @@ namespace stir {
 
     /*!
       \param bReset indicates whether the elapsed time should be reset before the timer is started.
-      The timer must not be running.
+      The timer must not be running if asking to reset.
     */
     inline void HighResWallClockTimer::start(bool bReset /* = false */)
       {
-	assert(!m_bRunning);
 	if (bReset) reset();
 	m_bRunning = true;
 #if defined(_AIX)

src/include/stir/TimedObject.h

@@ -21,6 +21,7 @@
 */
 
 #include "stir/CPUTimer.h"
+#include "stir/HighResWallClockTimer.h"
 
 START_NAMESPACE_STIR
 /*!
@@ -48,19 +49,25 @@ class TimedObject
   /*! Note: function is const such that it can be called in a
       function of a derived class that is const.
   */
-  inline void start_timers() const;
+  inline void start_timers(bool do_reset = false) const;
 
-  //! get current value of the timer (since first use or last reset)
+  //! get current value of the CPU timer (since first use or last reset)
   inline double get_CPU_timer_value() const;
 
+  //! get current value of the wall-clock timer (since first use or last reset)
+  inline double get_wall_clock_timer_value() const;
+
 private:
 
-  //! A timer that measured CPU time.
+  //! A timer that measures CPU time.
   /*! Note: member is mutable such that it can be modified in a const function.
   */
   mutable CPUTimer cpu_timer;
 
-  // TODO include other times (such as wall-clock)
+  //! A timer that measures wall clock time.
+  /*! Note: member is mutable such that it can be modified in a const function.
+  */
+  mutable HighResWallClockTimer wall_clock_timer;
 
 };
 

src/include/stir/TimedObject.inl

@@ -25,17 +25,20 @@ START_NAMESPACE_STIR
 void TimedObject::reset_timers()
 {
   cpu_timer.reset();
+  wall_clock_timer.reset();
 }
 
-void TimedObject::start_timers() const
+void TimedObject::start_timers(bool do_reset) const
 {
-  cpu_timer.start();
+  cpu_timer.start(do_reset);
+  wall_clock_timer.start(do_reset);
 }
 
 
 void TimedObject::stop_timers() const
 {
   cpu_timer.stop();
+  wall_clock_timer.stop();
 }
 
 
@@ -44,4 +47,9 @@ double TimedObject::get_CPU_timer_value() const
   return cpu_timer.value();
 }
 
+double TimedObject::get_wall_clock_timer_value() const
+{
+  return wall_clock_timer.value();
+}
+
 END_NAMESPACE_STIR

src/include/stir/Timer.h

@@ -3,6 +3,7 @@
 /*
     Copyright (C) 2000 PARAPET partners
     Copyright (C) 2000- 2009, Hammersmith Imanet Ltd
+    Copyright (C) 2023, University College London
     This file is part of STIR.
 
     SPDX-License-Identifier: Apache-2.0 AND License-ref-PARAPET-license
@@ -54,8 +55,13 @@ class Timer
 public:
   inline Timer();
   inline virtual ~Timer();  
-  inline void start();
+  //! start stopwatch, optionally resetting first
+  /*! the stopwatch should not be running already if asking to reset */
+  inline void start(bool do_reset = false);
+  //! stop stopwatch
   inline void stop();
+  //! reset stopwatch
+  /*! the stopwatch should not be running */
   inline void reset();
   //! return value is undefined when start() is not called first.
   inline double value() const;

src/include/stir/Timer.inl

@@ -14,12 +14,15 @@
 /*
     Copyright (C) 2000 PARAPET partners
     Copyright (C) 2000- 2009, Hammersmith Imanet Ltd
+    Copyright (C) 2023, University College London
     This file is part of STIR.
 
     SPDX-License-Identifier: Apache-2.0 AND License-ref-PARAPET-license
 
     See STIR/LICENSE.txt for details
 */
+#include "stir/error.h"
+
 START_NAMESPACE_STIR
 
 Timer::Timer()
@@ -32,13 +35,17 @@ Timer::Timer()
 Timer::~Timer()
 {}
 
-void Timer::start() 
+void Timer::start(bool do_reset)
 { 
   if (!running)
   {
+    if (do_reset)
+      reset();
     running = true;
     previous_value = get_current_value();
   }
+  else if (do_reset)
+    error("Timer::start called requesting reset, but the timer is running");
 }
 
 void Timer::stop()

src/recon_buildblock/BackProjectorByBin.cxx

@@ -152,8 +152,6 @@ back_project(DiscretisedDensity<3,float>& density,
 
   check(*viewgrams.get_proj_data_info_sptr(), density);
 
-  start_timers();
-
   // first check symmetries
   {
     const ViewSegmentNumbers basic_vs = viewgrams.get_basic_view_segment_num();
@@ -178,7 +176,6 @@ back_project(DiscretisedDensity<3,float>& density,
          max_axial_pos_num,
          min_tangential_pos_num,
          max_tangential_pos_num);
-  stop_timers();
 }
 #endif
 // -------------------------------------------------------------------------------------------------------------------- //
@@ -270,8 +267,6 @@ back_project(const RelatedViewgrams<float>& viewgrams,
 
   check(*viewgrams.get_proj_data_info_sptr(), *_density_sptr);
 
-  start_timers();
-
 #ifdef STIR_OPENMP
   const int thread_num=omp_get_thread_num();
   if(is_null_ptr(_local_output_image_sptrs[thread_num]))
@@ -303,7 +298,6 @@ back_project(const RelatedViewgrams<float>& viewgrams,
          max_axial_pos_num,
          min_tangential_pos_num,
          max_tangential_pos_num);
-  stop_timers();
 }
 
 void

src/recon_buildblock/BackProjectorByBinUsingInterpolation.cxx

@@ -454,8 +454,6 @@ BackProjectorByBinUsingInterpolation::
   back_project_2D_all_symmetries(const Sinogram<float> &sino, PETPlane &image, int view,
                                     const int min_tang_pos, const int max_tang_pos)
 {
-  start_timers();
-
   assert(sino.get_min_bin() == - sino.get_max_bin());
   assert(min_tang_pos == -max_tang_pos);
   assert(image.get_min_x() == - image.get_max_x());
@@ -508,16 +506,13 @@ BackProjectorByBinUsingInterpolation::
     backproj2D_Cho_view_viewplus90_180minview_90minview(image, projs, cphi, sphi, s);
   }
 
-  stop_timers();
 }
 
 void 
 BackProjectorByBinUsingInterpolation::
   back_project_2D_view_plus_90(const Sinogram<float> &sino, PETPlane &image, int view,
                                const int min_tang_pos, const int max_tang_pos)
 {
-  start_timers();
-
   assert(sino.get_min_bin() == - sino.get_max_bin());
   assert(min_tang_pos == -max_tang_pos);
   assert(image.get_min_x() == - image.get_max_x());
@@ -560,7 +555,6 @@ BackProjectorByBinUsingInterpolation::
     backproj2D_Cho_view_viewplus90(image, projs, cphi, sphi, s);
   }
 
-  stop_timers();
 }
 
 #endif
@@ -664,8 +658,6 @@ can only handle arc-corrected data (cast to ProjDataInfoCylindricalArcCorr)!\n")
        : 0 );
 
 
-  start_timers();
-
   const JacobianForIntBP jacobian(proj_data_info_cyl_sptr, use_exact_Jacobian_now);
 
   Array<4, float > Proj2424(IndexRange4D(0, 1, 0, 3, 0, 1, 1, 4));
@@ -803,7 +795,6 @@ can only handle arc-corrected data (cast to ProjDataInfoCylindricalArcCorr)!\n")
           axial_pos_to_z_offset);
       }
     }
-  stop_timers();
 }
 
 /*
@@ -867,8 +858,6 @@ can only handle arc-corrected data (cast to ProjDataInfoCylindricalArcCorr)!\n")
   // KTXXX not necessary anymore
   //assert(image.get_min_z() == 0);
 
-  start_timers();
-
   const JacobianForIntBP jacobian(proj_data_info_cyl_sptr, use_exact_Jacobian_now);
 
   Array<4, float > Proj2424(IndexRange4D(0, 1, 0, 3, 0, 1, 1, 4));
@@ -1001,7 +990,6 @@ can only handle arc-corrected data (cast to ProjDataInfoCylindricalArcCorr)!\n")
 							       axial_pos_to_z_offset);
       }
     }
-  stop_timers();
 }
 
 

src/recon_buildblock/ForwardProjectorByBin.cxx

@@ -135,7 +135,6 @@ forward_project(RelatedViewgrams<float>& viewgrams,
   if (viewgrams.get_num_viewgrams()==0)
     return;
   check(*viewgrams.get_proj_data_info_sptr(), density);
-  start_timers();
 
   // first check symmetries
   {
@@ -256,7 +255,6 @@ forward_project(RelatedViewgrams<float>& viewgrams,
     error("You need to call set_input() forward_project()");
 
   check(*viewgrams.get_proj_data_info_sptr(), *_density_sptr);
-  start_timers();
 
   // first check symmetries
   {
@@ -281,7 +279,6 @@ forward_project(RelatedViewgrams<float>& viewgrams,
          max_axial_pos_num,
          min_tangential_pos_num,
          max_tangential_pos_num);
-  stop_timers();
 }
 
 void

src/recon_buildblock/ForwardProjectorByBinUsingRayTracing.cxx

@@ -483,9 +483,6 @@ forward_project_all_symmetries(
   const int min_tang_pos_num_in_loop =
     min_abs_tangential_pos_num==0 ? 1 : min_abs_tangential_pos_num;
 
-  start_timers();
-
-
     Array <4,float> Projall(IndexRange4D(min_ax_pos_num, max_ax_pos_num, 0, 1, 0, 1, 0, 3));
     // KT 21/05/98 removed as now automatically zero 
     // Projall.fill(0);
@@ -653,8 +650,6 @@ forward_project_all_symmetries(
         }// end of } else {
     }// end of test for offset loop
 
-    stop_timers();
-
 }
 
 
@@ -905,8 +900,6 @@ void ForwardProjectorByBinUsingRayTracing::forward_project_2D(Sinogram<float> &s
 
     const int   projrad = (int) (sino.get_num_tangential_poss() / 2) - 1;
 
-    start_timers();
-
     //TODO for the moment, just handle 1 plane and use some 3D variables 
     const int min_ax_pos = 0;
     const int max_ax_pos = 0;
@@ -1023,8 +1016,6 @@ void ForwardProjectorByBinUsingRayTracing::forward_project_2D(Sinogram<float> &s
       }// end of } else {
     }// end of test for offset loop
 
-    stop_timers();
-
 }
 
 #endif // old 2D versions
@@ -1114,7 +1105,6 @@ forward_project_all_symmetries_2D(Viewgram<float> & pos_view,
 			         const int min_axial_pos_num, const int max_axial_pos_num,
 			         const int min_tangential_pos_num, const int max_tangential_pos_num) const
 {
-  start_timers();
 
   // KT 20/06/2001 should now work for non-arccorrected data as well
   const shared_ptr<const ProjDataInfoCylindrical> proj_data_info_sptr =
@@ -1444,7 +1434,6 @@ forward_project_all_symmetries_2D(Viewgram<float> & pos_view,
     }// end loop over D
   }// end of else
 
-  stop_timers();
 }