Reference Manual

Go to the documentation of this file.
00001 #ifndef FastTimerService_h
00002 #define FastTimerService_h
00003 
00004 //system headers
00005 #ifdef __linux
00006 #include <time.h>
00007 #else
00008 typedef int clockid_t;
00009 #endif
00010 
00011 /* Darwin system headers */
00012 #if defined(__APPLE__) || defined(__MACH__)
00013 #include <mach/clock.h>
00014 #include <mach/mach.h>
00015 #endif // defined(__APPLE__) || defined(__MACH__)
00016 
00017 // C++ headers
00018 #include <cmath>
00019 #include <string>
00020 #include <map>
00021 #include <tr1/unordered_map>
00022 #include <unistd.h>
00023 
00024 // CMSSW headers
00025 #include "FWCore/ServiceRegistry/interface/ActivityRegistry.h"
00026 #include "FWCore/ServiceRegistry/interface/Service.h"
00027 #include "FWCore/ParameterSet/interface/ParameterSet.h"
00028 #include "FWCore/Framework/interface/TriggerNamesService.h"
00029 #include "FWCore/MessageLogger/interface/MessageLogger.h"
00030 #include "DataFormats/Common/interface/HLTPathStatus.h"
00031 #include "DataFormats/Provenance/interface/EventID.h"
00032 #include "DataFormats/Provenance/interface/Timestamp.h"
00033 #include "DataFormats/Provenance/interface/ModuleDescription.h"
00034 #include "DQMServices/Core/interface/DQMStore.h"
00035 #include "DQMServices/Core/interface/MonitorElement.h"
00036 
00037 
00038 /*
00039 procesing time is diveded into
00040  - source
00041  - pre-event processing overhead
00042  - event processing
00043  - post-event processing overhead
00044 
00045 until lumi-processing and run-processing are taken into account, they will count as inter-event overhead
00046 
00047 event processing time is diveded into
00048  - trigger processing (from the begin of the first path to the end of the last path)
00049  - trigger overhead
00050  - endpath processing (from the begin of the first endpath to the end of the last endpath)
00051  - endpath overhead
00052 */
00053 
00054 /*
00055 Timer per-call overhead (on lxplus, SLC 5.7):
00056 
00057 Test results for "clock_gettime(CLOCK_THREAD_CPUTIME_ID, & value)"
00058  - average time per call: 340 ns
00059  - resolution:              ? ns
00060 
00061 Test results for "clock_gettime(CLOCK_PROCESS_CPUTIME_ID, & value)"
00062  - average time per call: 360 ns
00063  - resolution:              ? ns
00064 
00065 Test results for "clock_gettime(CLOCK_REALTIME, & value)"
00066  - average time per call: 320 ns
00067  - resolution:              1 us
00068 
00069 Test results for "getrusage(RUSAGE_SELF, & value)"
00070  - average time per call: 380 ns
00071  - resolution:              1 ms
00072 
00073 Test results for "gettimeofday(& value, NULL)"
00074  - average time per call:  65 ns
00075  - resolution:              1 us
00076 
00077 Assuming an HLT process with ~2500 modules and ~500 paths, tracking each step
00078 with clock_gettime(CLOCK_THREAD_CPUTIME_ID) gives a per-event overhead of 2 ms
00079 
00080 Detailed informations on different timers can be extracted running $CMSSW_RELEASE_BASE/test/$SCRAM_ARCH/testTimer .
00081 */
00082 
00083 
00084 class FastTimerService {
00085 public:
00086   FastTimerService(const edm::ParameterSet &, edm::ActivityRegistry & );
00087   ~FastTimerService();
00088 
00089   // query the current module/path/event
00090   // Note: these functions incur in a "per-call timer overhead" (see above), currently of the order of 340ns
00091   double currentModuleTime() const;         // return the time spent since the last preModule() event
00092   double currentPathTime() const;           // return the time spent since the last preProcessPath() event
00093   double currentEventTime() const;          // return the time spent since the last preProcessEvent() event
00094 
00095   // query the time spent in a module/path (available after it has run)
00096   double queryModuleTime(const edm::ModuleDescription &) const;
00097   double queryPathActiveTime(const std::string &) const;
00098   double queryPathTotalTime(const std::string &) const;
00099 
00100   // query the time spent in the current event's
00101   //  - source        (available during event processing)
00102   //  - all paths     (available during endpaths)
00103   //  - all endpaths  (available after all endpaths have run)
00104   //  - processing    (available after the event has been processed)
00105   double querySourceTime() const;
00106   double queryPathsTime() const;
00107   double queryEndPathsTime() const;
00108   double queryEventTime() const;
00109 
00110   /* FIXME not yet implemented
00111   // try to assess the overhead which may not be included in the source, paths and event timers
00112   double queryPreSourceOverhead() const;    // time spent after the previous event's postProcessEvent and this event's preSource
00113   double queryPreEventOverhead() const;     // time spent after this event's postSource and preProcessEvent
00114   double queryPreEndPathsOverhead() const;  // time spent after the last path's postProcessPath and the first endpath's preProcessPath
00115   */
00116 
00117 private:
00118   void postBeginJob();
00119   void postEndJob();
00120   void preModuleBeginJob( edm::ModuleDescription const & );
00121   void preProcessEvent( edm::EventID const &, edm::Timestamp const & );
00122   void postProcessEvent( edm::Event const &, edm::EventSetup const & );
00123   void preSource();
00124   void postSource();
00125   void prePathBeginRun( std::string const & );
00126   void preProcessPath(  std::string const & );
00127   void postProcessPath( std::string const &, edm::HLTPathStatus const & );
00128   void preModule(  edm::ModuleDescription const & );
00129   void postModule( edm::ModuleDescription const & );
00130 
00131   // needed for the DAQ when reconfiguring between runs
00132   void reset();
00133 
00134 public:
00135   static void fillDescriptions(edm::ConfigurationDescriptions & descriptions);
00136 
00137 private:
00138 
00139   struct ModuleInfo {
00140     double                      time_active;        // per-event timer: time actually spent in this module
00141     double                      summary_active;
00142     TH1F *                      dqm_active;
00143     bool                        has_just_run;       // flag set to check if a module was active inside a particular path, or not
00144     bool                        is_exclusive;       // flag set to check if a module has been run only once
00145 
00146   public:
00147     ModuleInfo() :
00148       time_active(0.),
00149       summary_active(0.),
00150       dqm_active(0),
00151       has_just_run(false),
00152       is_exclusive(false)
00153     { }
00154 
00155     ~ModuleInfo() {
00156       reset();
00157     }
00158 
00159     // reset the timers and DQM plots
00160     void reset() {
00161       time_active = 0.;
00162       summary_active = 0.;
00163       // the DAQ destroys and re-creates the DQM and DQMStore services at each reconfigure, so we don't need to clean them up
00164       dqm_active = 0;
00165       has_just_run = false;
00166       is_exclusive = false;
00167     }
00168   };
00169 
00170   struct PathInfo {
00171     std::vector<ModuleInfo *>   modules;            // list of all modules contributing to the path (duplicate modules stored as null pointers)
00172     double                      time_active;        // per-event timer: time actually spent in this path
00173     double                      time_premodules;    // per-event timer: time spent between "begin path" and the first "begin module"
00174     double                      time_intermodules;  // per-event timer: time spent between modules
00175     double                      time_postmodules;   // per-event timer: time spent between the last "end module" and "end path"
00176     double                      time_overhead;      // per-event timer: sum of time_premodules, time_intermodules, time_postmodules
00177     double                      time_total;         // per-event timer: sum of the time spent in all modules which would have run in this path (plus overhead)
00178     double                      summary_active;
00179     double                      summary_premodules;
00180     double                      summary_intermodules;
00181     double                      summary_postmodules;
00182     double                      summary_overhead;
00183     double                      summary_total;
00184     uint32_t                    last_run;
00185     uint32_t                    index;              // index of the Path or EndPath in the "schedule"
00186     TH1F *                      dqm_active;
00187     TH1F *                      dqm_exclusive;
00188     TH1F *                      dqm_premodules;
00189     TH1F *                      dqm_intermodules;
00190     TH1F *                      dqm_postmodules;
00191     TH1F *                      dqm_overhead;
00192     TH1F *                      dqm_total;
00193     TH1F *                      dqm_module_counter; // for each module in the path, track how many times it ran
00194     TH1F *                      dqm_module_active;  // for each module in the path, track the active time spent 
00195     TH1F *                      dqm_module_total;   // for each module in the path, track the total time spent 
00196 
00197   public:
00198     PathInfo() :
00199       modules(),
00200       time_active(0.),
00201       time_premodules(0.),
00202       time_intermodules(0.),
00203       time_postmodules(0.),
00204       time_overhead(0.),
00205       time_total(0.),
00206       summary_active(0.),
00207       summary_premodules(0.),
00208       summary_intermodules(0.),
00209       summary_postmodules(0.),
00210       summary_overhead(0.),
00211       summary_total(0.),
00212       last_run(0),
00213       index(0),
00214       dqm_active(0),
00215       dqm_exclusive(0),
00216       dqm_premodules(0),
00217       dqm_intermodules(0),
00218       dqm_postmodules(0),
00219       dqm_overhead(0),
00220       dqm_total(0),
00221       dqm_module_counter(0),
00222       dqm_module_active(0),
00223       dqm_module_total(0)
00224     { }
00225 
00226     ~PathInfo() {
00227       reset();
00228     }
00229 
00230     // reset the timers and DQM plots
00231     void reset() {
00232       modules.clear();
00233       time_active = 0.;
00234       time_premodules = 0.;
00235       time_intermodules = 0.;
00236       time_postmodules = 0.;
00237       time_overhead = 0.;
00238       time_total = 0.;
00239       summary_active = 0.;
00240       summary_premodules = 0.;
00241       summary_intermodules = 0.;
00242       summary_postmodules = 0.;
00243       summary_overhead = 0.;
00244       summary_total = 0.;
00245       last_run = 0;
00246       index = 0;
00247 
00248       // the DAQ destroys and re-creates the DQM and DQMStore services at each reconfigure, so we don't need to clean them up
00249       dqm_active = 0; 
00250       dqm_premodules = 0;
00251       dqm_intermodules = 0;
00252       dqm_postmodules = 0;
00253       dqm_overhead = 0;
00254       dqm_total = 0;
00255       dqm_module_counter = 0;
00256       dqm_module_active = 0;
00257       dqm_module_total = 0;
00258     }
00259   };
00260 
00261   template <typename T> class PathMap   : public std::tr1::unordered_map<std::string, T> {};
00262   template <typename T> class ModuleMap : public std::tr1::unordered_map<edm::ModuleDescription const *, T> {};
00263 
00264   // timer configuration
00265   const clockid_t                               m_timer_id;             // the default is to use CLOCK_THREAD_CPUTIME_ID, unless useRealTimeClock is set, which will use CLOCK_REALTIME
00266   bool                                          m_is_cpu_bound;         // if the process is not bound to a single CPU, per-thread or per-process measuerements may be unreliable
00267   bool                                          m_enable_timing_paths;
00268   bool                                          m_enable_timing_modules;
00269   bool                                          m_enable_timing_exclusive;
00270   const bool                                    m_enable_timing_summary;
00271   const bool                                    m_skip_first_path;
00272 
00273   // dqm configuration
00274   const bool                                    m_enable_dqm;
00275   const bool                                    m_enable_dqm_bypath_active;     // require per-path timers
00276   const bool                                    m_enable_dqm_bypath_total;      // require per-path and per-module timers
00277   const bool                                    m_enable_dqm_bypath_overhead;   // require per-path and per-module timers
00278   const bool                                    m_enable_dqm_bypath_details;    // require per-path and per-module timers
00279   const bool                                    m_enable_dqm_bypath_counters;
00280   const bool                                    m_enable_dqm_bypath_exclusive;
00281   const bool                                    m_enable_dqm_bymodule;          // require per-module timers
00282   const bool                                    m_enable_dqm_bylumi;
00283   const double                                  m_dqm_eventtime_range;
00284   const double                                  m_dqm_eventtime_resolution;
00285   const double                                  m_dqm_pathtime_range;
00286   const double                                  m_dqm_pathtime_resolution;
00287   const double                                  m_dqm_moduletime_range;
00288   const double                                  m_dqm_moduletime_resolution;
00289   const uint32_t                                m_dqm_lumi_range;
00290   std::string                                   m_dqm_path;
00291 
00292   // job configuration and caching
00293   std::string const *                           m_first_path;           // the framework does not provide a pre-paths or pre-endpaths signal,
00294   std::string const *                           m_last_path;            // so we emulate them keeping track of the first and last path and endpath
00295   std::string const *                           m_first_endpath;
00296   std::string const *                           m_last_endpath;
00297   bool                                          m_is_first_module;      // helper to measure the time spent between the beginning of the path and the execution of the first module
00298 
00299   // per-event accounting
00300   double                                        m_event;
00301   double                                        m_source;
00302   double                                        m_all_paths;
00303   double                                        m_all_endpaths;
00304 
00305   // per-job summary
00306   unsigned int                                  m_summary_events;       // number of events
00307   double                                        m_summary_event;
00308   double                                        m_summary_source;
00309   double                                        m_summary_all_paths;
00310   double                                        m_summary_all_endpaths;
00311 
00312   // DQM
00313   DQMStore *                                    m_dqms;
00314   TH1F *                                        m_dqm_event;
00315   TH1F *                                        m_dqm_source;
00316   TH1F *                                        m_dqm_all_paths;
00317   TH1F *                                        m_dqm_all_endpaths;
00318   TProfile *                                    m_dqm_paths_active_time;
00319   TProfile *                                    m_dqm_paths_total_time;
00320   TProfile *                                    m_dqm_paths_exclusive_time;
00321 
00322   // per-lumisection plots
00323   TProfile *                                    m_dqm_bylumi_event;
00324   TProfile *                                    m_dqm_bylumi_source;
00325   TProfile *                                    m_dqm_bylumi_all_paths;
00326   TProfile *                                    m_dqm_bylumi_all_endpaths;
00327 
00328   // per-path and per-module accounting
00329   PathInfo *                                    m_current_path;
00330   PathMap<PathInfo>                             m_paths;
00331   ModuleMap<ModuleInfo>                         m_modules;              // this assumes that ModuleDescription are stored in the same object through the whole job,
00332                                                                         // which is true only *after* the edm::Worker constructors have run
00333   std::vector<PathInfo *>                       m_cache_paths;
00334   std::vector<ModuleInfo *>                     m_cache_modules;
00335 
00336 
00337   // timers
00338   std::pair<struct timespec, struct timespec>   m_timer_event;          // track time spent in each event
00339   std::pair<struct timespec, struct timespec>   m_timer_source;         // track time spent in the source
00340   std::pair<struct timespec, struct timespec>   m_timer_paths;          // track time spent in all paths
00341   std::pair<struct timespec, struct timespec>   m_timer_endpaths;       // track time spent in all endpaths
00342   std::pair<struct timespec, struct timespec>   m_timer_path;           // track time spent in each path
00343   std::pair<struct timespec, struct timespec>   m_timer_module;         // track time spent in each module
00344   struct timespec                               m_timer_first_module;   // record the start of the first active module in a path, if any
00345 
00346 #if defined(__APPLE__) || defined (__MACH__)
00347   clock_serv_t m_clock_port;
00348 #endif // defined(__APPLE__) || defined(__MACH__)
00349 
00350   void gettime(struct timespec & stamp) const
00351   {
00352 #if defined(_POSIX_TIMERS) && _POSIX_TIMERS >= 0
00353     clock_gettime(m_timer_id, & stamp);
00354 #else
00355 // special cases which do not support _POSIX_TIMERS
00356 #if defined(__APPLE__) || defined (__MACH__)
00357     mach_timespec_t timespec;
00358     clock_get_time(m_clock_port, &timespec);
00359     stamp.tv_sec  = timespec.tv_sec;
00360     stamp.tv_nsec = timespec.tv_nsec;
00361 #endif // defined(__APPLE__) || defined(__MACH__)
00362 #endif // defined(_POSIX_TIMERS) && _POSIX_TIMERS >= 0
00363   }
00364 
00365   void start(std::pair<struct timespec, struct timespec> & times) const
00366   {
00367     gettime(times.first);
00368   }
00369 
00370   void stop(std::pair<struct timespec, struct timespec> & times) const
00371   {
00372     gettime(times.second);
00373   }
00374 
00375   static
00376   double delta(const struct timespec & first, const struct timespec & second)
00377   {
00378     if (second.tv_nsec > first.tv_nsec)
00379       return (double) (second.tv_sec - first.tv_sec) + (double) (second.tv_nsec - first.tv_nsec) / (double) 1e9;
00380     else
00381       return (double) (second.tv_sec - first.tv_sec) - (double) (first.tv_nsec - second.tv_nsec) / (double) 1e9;
00382   }
00383 
00384   static
00385   double delta(const std::pair<struct timespec, struct timespec> & times)
00386   {
00387     return delta(times.first, times.second);
00388   }
00389 
00390   // find the module description associated to a module, by name
00391   edm::ModuleDescription const * findModuleDescription(const std::string & module) const;
00392 
00393   // associate to a path all the modules it contains
00394   void fillPathMap(std::string const & name, std::vector<std::string> const & modules);
00395 
00396 };
00397 
00398 #endif // ! FastTimerService_h
/data/refman/pasoursint/CMSSW_5_2_7_hltpatch1/src/HLTrigger/Timer/interface/FastTimerService.h
