Gaudi Framework, version v23r5
Home   Generated: Wed Nov 28 2012
 All Classes Namespaces Files Functions Variables Typedefs Enumerations Enumerator Properties Friends Macros Groups Pages
ChronoStatSvc.cpp
Go to the documentation of this file.
1 // $Id: ChronoStatSvc.cpp,v 1.18 2008/05/13 12:37:19 marcocle Exp $
2 // ============================================================================
3 // CVS tag $Name: $, version $Revision: 1.18 $
4 // ============================================================================
5 #ifdef _WIN32
6 #pragma warning( disable : 4786 )
7 #endif
8 // ============================================================================
9 // STD & STL
10 // ============================================================================
11 #include <iostream>
12 #include <iomanip>
13 #include <string>
14 #include <algorithm>
15 #include <functional>
16 #include <fstream>
17 #include <iomanip>
18 // ============================================================================
19 // GaudiKernel
20 // ============================================================================
21 #include "GaudiKernel/Kernel.h"
22 #include "GaudiKernel/StatusCode.h"
23 #include "GaudiKernel/SvcFactory.h"
24 #include "GaudiKernel/IChronoStatSvc.h"
25 #include "GaudiKernel/MsgStream.h"
26 #include "GaudiKernel/ChronoEntity.h"
27 #include "GaudiKernel/StatEntity.h"
28 #include "GaudiKernel/Stat.h"
29 // ============================================================================
31 // ============================================================================
32 #include "ChronoStatSvc.h"
33 // ============================================================================
36 // ============================================================================
37 DECLARE_SERVICE_FACTORY(ChronoStatSvc)
38 // ============================================================================
45 // ============================================================================
46 // ============================================================================
47 // comparison functor
48 // ============================================================================
49 class ComparePairOfChronoEntityAndChronoTag
50  : public std::binary_function<
51  const std::pair<ChronoEntity*,const IChronoStatSvc::ChronoTag*> ,
52  const std::pair<ChronoEntity*,const IChronoStatSvc::ChronoTag*> , bool >
53 {
54 public:
55  inline bool operator()
56  ( const std::pair<ChronoEntity*,
57  const IChronoStatSvc::ChronoTag*>& p1 ,
58  const std::pair< ChronoEntity*,
59  const IChronoStatSvc::ChronoTag*>& p2 ) const
60  {
61  const ChronoEntity* e1 = p1.first;
62  const ChronoEntity* e2 = p2.first;
63  return ( ( 0 == e1 || 0 == e2 ) ? true : (*e1)<(*e2) ) ;
64  }
65 };
66 // ============================================================================
67 // comparison functor
68 // ============================================================================
69 class ComparePairOfStatEntityAndStatTag
70  : public std::binary_function<
71  const std::pair<const StatEntity*,const IChronoStatSvc::StatTag*> ,
72  const std::pair<const StatEntity*,const IChronoStatSvc::StatTag*> , bool >
73 {
74 public:
76  inline bool operator()
77  ( const std::pair<const StatEntity*,
78  const IChronoStatSvc::StatTag*>& p1,
79  const std::pair<const StatEntity*,
80  const IChronoStatSvc::StatTag*>& p2 ) const
81  {
82  const StatEntity* se1 = p1.first;
83  const StatEntity* se2 = p2.first;
84  return ( 0 == se1 || 0 == se2 ) ? true : (*se1)<(*se2) ;
85  }
86 };
87 // ============================================================================
88 // Constructor
89 // ============================================================================
90 ChronoStatSvc::ChronoStatSvc
91 ( const std::string& name, ISvcLocator* svcloc )
92  : base_class( name , svcloc )
93  , m_chronoEntities ()
94  , m_chronoPrintLevel ( MSG::INFO )
95  , m_statEntities ()
96  , m_statPrintLevel ( MSG::INFO )
97  //
98  // the header row
99  , m_header ( " Counter | # | sum | mean/eff^* | rms/err^* | min | max |")
100  // format for regular statistical printout rows
101  , m_format1 ( " %|-15.15s|%|17t||%|10d| |%|11.7g| |%|#11.5g| |%|#11.5g| |%|#12.5g| |%|#12.5g| |" )
102  // format for "efficiency" statistical printout rows
103  , m_format2 ( "*%|-15.15s|%|17t||%|10d| |%|11.5g| |(%|#9.7g| +- %|-#9.7g|)%%| ------- | ------- |" )
104  // flag to use the special "efficiency" format
105  , m_useEffFormat ( true )
106 {
108  declareProperty ( "ChronoPrintOutTable" ,
109  m_chronoTableFlag = true );
111  declareProperty ( "ChronoDestinationCout" ,
112  m_chronoCoutFlag = false );
114  declareProperty ( "ChronoPrintLevel" ,
115  m_intChronoPrintLevel = MSG::INFO );
118  declareProperty ( "ChronoTableToBeOrdered" ,
119  m_chronoOrderFlag = true );
121  declareProperty ( "PrintUserTime" ,
122  m_printUserTime = true );
124  declareProperty ( "PrintSystemTime" ,
125  m_printSystemTime = false );
127  declareProperty ( "PrintEllapsedTime" ,
128  m_printEllapsedTime = false );
131  declareProperty ( "StatPrintOutTable" ,
132  m_statTableFlag = true );
134  declareProperty ( "StatDestinationCout" ,
135  m_statCoutFlag = false );
137  declareProperty ( "StatPrintLevel" ,
138  m_intStatPrintLevel = MSG::INFO );
141  declareProperty ( "StatTableToBeOrdered" ,
142  m_statOrderFlag = true );
143 
144  // specify the number of events to be skipped by the memory auditor
145  // in order to better spot memory leak
146  declareProperty ( "NumberOfSkippedEventsForMemStat" ,
147  m_numberOfSkippedEventsForMemStat = -1 ) ;
148 
149  declareProperty( "AsciiStatsOutputFile",
150  m_statsOutFileName = "",
151  "Name of the output file storing the stats. If empty, no"
152  " statistics will be saved (default)" );
153 
154  declareProperty
155  ( "StatTableHeader" , m_header ,
156  "The header row for the output Stat-table" ) ;
157  declareProperty
158  ( "RegularRowFormat" , m_format1 ,
159  "The format for the regular row in the output Stat-table" ) ;
160  declareProperty
161  ( "EfficiencyRowFormat" , m_format2 ,
162  "The format for the regular row in the outptu Stat-table" ) ;
163  declareProperty
164  ( "UseEfficiencyRowFormat" , m_useEffFormat ,
165  "Use the special format for printout of efficiency counters" ) ;
166 }
167 // ============================================================================
168 // Destructor.
169 // ============================================================================
170 ChronoStatSvc::~ChronoStatSvc()
171 {
172  // clear the container of chrono entities
173  m_chronoEntities.clear();
174  // clear the container of stat entities
175  m_statEntities.clear();
176 }
177 // ============================================================================
178 // Implementation of IService::initialize()
179 // ============================================================================
180 StatusCode ChronoStatSvc::initialize()
181 {
182  StatusCode sc = Service::initialize();
183  if ( sc.isFailure() ) return sc;
185  MsgStream log( msgSvc() , this->name() );
186 
187  // Set my own properties
188  sc = setProperties();
189 
190  if (sc.isFailure()) {
191  log << MSG::ERROR << "setting my properties" << endmsg;
192  return StatusCode::FAILURE;
193  }
194 
195  log << MSG::INFO << " Number of skipped events for MemStat"
196  << m_numberOfSkippedEventsForMemStat << endmsg ;
197 
201  m_statPrintLevel =
202  ( MSG::FATAL < m_intStatPrintLevel ) ? MSG::FATAL :
203  ( MSG::NIL > m_intStatPrintLevel ) ? MSG::NIL :
204  ( MSG::Level ) m_intStatPrintLevel ;
206  m_chronoPrintLevel =
207  ( MSG::FATAL < m_intChronoPrintLevel ) ? MSG::FATAL :
208  ( MSG::NIL > m_intChronoPrintLevel ) ? MSG::NIL :
209  ( MSG::Level ) m_intChronoPrintLevel ;
211  if( m_chronoTableFlag &&
212  !m_printUserTime &&
213  !m_printSystemTime &&
214  !m_printEllapsedTime ) { m_printUserTime = true ; }
216  if( m_printUserTime ||
217  m_printSystemTime ||
218  m_printEllapsedTime ) { m_chronoTableFlag = true ; }
221  chronoStart( name() ) ;
223  return StatusCode::SUCCESS;
224 }
225 // ============================================================================
226 // Implementation of IService::finalize()
227 // ============================================================================
228 StatusCode ChronoStatSvc::finalize()
229 {
230  std::string local = name()+".finalize()";
232  MsgStream main_log( msgSvc() , local );
235  chronoStop( name() ) ;
236 
239  if ( m_chronoTableFlag &&
240  !m_chronoEntities.empty() &&
241  ( m_printUserTime || m_printSystemTime ) )
242  {
244  MsgStream log( msgSvc() , "*****Chrono*****" );
245  const std::string stars( ( m_chronoCoutFlag ) ? 126 : 100 , '*' );
246  if( m_chronoCoutFlag )
247  {
248  std::cout << stars << std::endl;
249  std::cout << local << " The Final CPU consumption (Chrono) Table "
250  << ( m_chronoOrderFlag ? "(ordered)" : "(not ordered)" ) << std::endl;
251  std::cout << stars << std::endl;
252  }
253  else
254  {
255  log << (MSG::Level) m_chronoPrintLevel
256  << stars << endmsg;
257  log << (MSG::Level) m_chronoPrintLevel
258  << " The Final CPU consumption ( Chrono ) Table "
259  << ( m_chronoOrderFlag ? "(ordered)" : "(not ordered)" ) << endmsg;
260  log << (MSG::Level) m_chronoPrintLevel << stars << endmsg;
261  }
263  { // prepare container for printing
264  typedef std::pair<ChronoEntity*,const ChronoTag*> MPair;
265  typedef std::vector<MPair> MCont;
266  MCont tmpCont;
267  for( ChronoMap::iterator it = m_chronoEntities.begin() ;
268  m_chronoEntities.end() != it ; ++it )
269  { tmpCont.push_back( MPair( &(it->second) , &(it->first) ) ) ; }
270  // sort it
271  if( m_chronoOrderFlag )
272  { std::sort( tmpCont.begin() ,
273  tmpCont.end() ,
274  ComparePairOfChronoEntityAndChronoTag() ); }
275  // print User Time statistics
276  if( m_printUserTime )
277  {
278  for( MCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
279  {
280  //
281  ChronoEntity* entity = iter->first ; if( 0 == entity ) { continue ; }
282  const ChronoTag* tag = iter->second ; if( 0 == tag ) { continue ; }
283 
284  entity->stop();
285 
286  if ( m_chronoCoutFlag )
287  { std::cout << *tag << "\t" << entity->outputUserTime () << std::endl ; }
288  else
289  {
290  MsgStream(msgSvc(), *tag)
291  << m_chronoPrintLevel << entity->outputUserTime () << endmsg ;
292  }
293  //
294  }
295  }
297  if( m_printSystemTime )
298  {
301  if ( m_printUserTime && m_chronoCoutFlag )
302  { std::cout << stars << std::endl; }
303  else if ( m_printUserTime && !m_chronoCoutFlag )
304  { log << (MSG::Level) m_chronoPrintLevel << stars << endmsg; }
306  for( MCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
307  {
309  ChronoEntity* entity = iter->first ; if( 0 == entity ) { continue ; }
310  const ChronoTag* tag = iter->second ; if( 0 == tag ) { continue ; }
311 
312  entity->stop();
313 
314  if ( m_chronoCoutFlag )
315  { std::cout << *tag << "\t" << entity->outputSystemTime() << std::endl ; }
316  else
317  {
318  MsgStream(msgSvc(), *tag)
319  << m_chronoPrintLevel << entity->outputSystemTime() << endmsg ;
320  }
321  //
322  }
323  }
325  if( m_printEllapsedTime )
326  {
329  if ( ( m_printUserTime || m_printSystemTime ) && m_chronoCoutFlag )
330  { std::cout << stars << std::endl; }
331  else if ( ( m_printUserTime || m_printSystemTime ) && !m_chronoCoutFlag )
332  { log << (MSG::Level) m_chronoPrintLevel << stars << endmsg; }
334  for( MCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
335  {
337  ChronoEntity* entity = iter->first ; if( 0 == entity ) { continue ; }
338  const ChronoTag* tag = iter->second ; if( 0 == tag ) { continue ; }
339 
340  entity->stop();
341 
342  if ( m_chronoCoutFlag )
343  { std::cout << *tag << "\t" << entity->outputElapsedTime() << std::endl ; }
344  else
345  {
346  MsgStream(msgSvc(), *tag)
347  << m_chronoPrintLevel << entity->outputElapsedTime() << endmsg ;
348  }
349  //
350  }
351  }
353  tmpCont.clear();
354  }
356  if( m_chronoCoutFlag ) { std::cout << stars << std::endl; }
357  else { log << m_chronoPrintLevel << stars << endmsg; }
358  }
359 
361 
363  if ( m_statTableFlag ) { printStats () ; }
364 
365  if ( !m_statsOutFileName.value().empty() ) {
366  saveStats();
367  }
368 
369  main_log << MSG::INFO << " Service finalized successfully " << endmsg;
370 
371  return Service::finalize();
372 }
373 // ============================================================================
374 // Implementation of IChronoStatSvc::chronoStart
375 // ============================================================================
376 ChronoEntity*
377 ChronoStatSvc::chronoStart
378 ( const ChronoTag& chronoTag )
379 {
380  ChronoEntity& entity = m_chronoEntities [ chronoTag ] ;
381  entity.start() ;
382  return &entity ;
383 }
384 // ============================================================================
385 // Implementation of IChronoStatSvc::chronoStop
386 // ============================================================================
387 const ChronoEntity*
388 ChronoStatSvc::chronoStop
389 ( const IChronoStatSvc::ChronoTag& chronoTag )
390 {
391  ChronoEntity& entity = m_chronoEntities [ chronoTag ] ;
392  entity.stop() ;
393  return &entity ;
394 }
395 // ============================================================================
396 // Implementation of IChronoStatSvc::chronoDelta
397 // ============================================================================
398 IChronoStatSvc::ChronoTime
399 ChronoStatSvc::chronoDelta
400 ( const IChronoStatSvc::ChronoTag& chronoTag,
401  IChronoStatSvc::ChronoType theType )
402 {
403  return m_chronoEntities[ chronoTag ].delta( theType );
404 }
405 // ============================================================================
406 // Implementation of IChronoStatSvc::chronoPrint
407 // ============================================================================
408 void ChronoStatSvc::chronoPrint
409 ( const IChronoStatSvc::ChronoTag& chronoTag )
410 {
411  MsgStream log ( msgSvc() , chronoTag );
412  if( m_printUserTime ) {
413  log << (MSG::Level) m_chronoPrintLevel
414  << m_chronoEntities[ chronoTag ].outputUserTime ()
415  << endmsg;
416  }
417  if( m_printSystemTime ) {
418  log << (MSG::Level) m_chronoPrintLevel
419  << m_chronoEntities[ chronoTag ].outputSystemTime()
420  << endmsg;
421  }
422 }
423 // ============================================================================
424 // Implementation of IChronoSvc::chronoStatus
425 // ============================================================================
426 IChronoStatSvc::ChronoStatus
427 ChronoStatSvc::chronoStatus
428 ( const IChronoStatSvc::ChronoTag& chronoTag )
429 { return m_chronoEntities[ chronoTag ].status(); }
430 // ============================================================================
431 // Implementation of IChronoStatSvc::stat
432 // ============================================================================
433 void ChronoStatSvc::stat
434 ( const IChronoStatSvc::StatTag & statTag ,
435  const IChronoStatSvc::StatFlag & statFlag )
436 {
437  StatMap::iterator theIter=m_statEntities.find(statTag);
438 
439  StatEntity * theStat=0 ;
440  // if new entity, specify the neumber of events to be skipped
441  if (theIter==m_statEntities.end()){
442  // new stat entity
443  StatEntity& theSe = m_statEntities[ statTag ];
444  theStat=& theSe;
445  theStat->setnEntriesBeforeReset(m_numberOfSkippedEventsForMemStat);
446  }
447  else
448  {
449  //existing stat entity
450  theStat=&((*theIter).second);
451  }
452 
453  theStat->addFlag ( statFlag ) ;
454 }
455 // ============================================================================
456 // Implementation of IChronoStatSvc::statPrint
457 // ============================================================================
458 void ChronoStatSvc::statPrint
459 ( const IChronoStatSvc::StatTag& statTag )
460 {
461  MsgStream log ( msgSvc() , statTag ) ;
462  log << (MSG::Level) m_statPrintLevel << m_statEntities[ statTag ] << endmsg;
463 }
464 // ============================================================================
465 /* extract the chrono entity for the given tag (name)
466  * @see IChronoStatSvc
467  * @param t chrono tag(name)
468  * @return pointer to chrono entity
469  */
470 // ============================================================================
471 const ChronoEntity* ChronoStatSvc::chrono
472 ( const IChronoStatSvc::ChronoTag& t ) const
473 {
474  ChronoMap::const_iterator it = m_chronoEntities.find ( t ) ;
475  if ( m_chronoEntities.end() != it ) { return &(it->second) ; }
476  return 0 ;
477 }
478 // ============================================================================
479 /* extract the stat entity for the given tag (name)
480  * @see IChronoStatSvc
481  * @param t stat tag(name)
482  * @return pointer to stat entity
483  */
484 // ============================================================================
485 const StatEntity* ChronoStatSvc::stat
486 ( const IChronoStatSvc::StatTag& t ) const
487 {
488  StatMap::const_iterator it = m_statEntities.find ( t ) ;
489  if ( m_statEntities.end() != it ) { return &(it->second) ; }
490  return 0 ;
491 }
492 // ============================================================================
493 // dump all the statistics into an ASCII file
494 // ============================================================================
495 void ChronoStatSvc::saveStats()
496 {
497  std::ofstream out( m_statsOutFileName.value().c_str(),
498  std::ios_base::out | std::ios_base::trunc );
499  if ( !out.good() ) {
500  MsgStream msg( msgSvc() , name() );
501  msg << MSG::INFO
502  << "Could not open the output file for writing chrono statistics ["
503  << m_statsOutFileName.value() << "]"
504  << endmsg;
505  return;
506  } else {
507  // format it our way
508  out << std::scientific << std::setprecision(8) ;
509  }
510 
511  // ChronoEntity
512  typedef std::pair<ChronoEntity*, const ChronoTag*> MPair;
513  typedef std::vector<MPair> MCont;
514  MCont chronos;
515 
516  for( ChronoMap::iterator it = m_chronoEntities.begin() ;
517  m_chronoEntities.end() != it ; ++it ) {
518  chronos.push_back( MPair( &(it->second) , &(it->first) ) ) ;
519  }
520 
521  // sort it
522  std::sort( chronos.begin() ,
523  chronos.end() ,
524  ComparePairOfChronoEntityAndChronoTag() );
525 
526  // print User Time statistics
527  for( MCont::iterator iter = chronos.begin() ;
528  chronos.end() != iter;
529  ++iter ) {
530  //
531  const ChronoEntity* entity = iter->first;
532  if( 0 == entity ) { continue ; }
533 
534  const ChronoTag* tag = iter->second ;
535  if( 0 == tag ) { continue ; }
536 
537  // create an entry in the .INI-like table
538  out << "\n[" << *tag << "]\n";
539 
540  // user
541  out << "cpu_user_total = " << entity->uTotalTime() << "\n";
542  out << "cpu_user_min = " << entity->uMinimalTime() << "\n";
543  out << "cpu_user_mean = " << entity->uMeanTime() << "\n";
544  out << "cpu_user_RMS = " << entity->uRMSTime() << "\n";
545  out << "cpu_user_max = " << entity->uMaximalTime() << "\n";
546  out << "cpu_user_nbr = " << entity->nOfMeasurements() << "\n";
547 
548  // system
549  out << "\n"; // just for clarity
550  out << "cpu_system_total = " << entity->kTotalTime() << "\n";
551  out << "cpu_system_min = " << entity->kMinimalTime() << "\n";
552  out << "cpu_system_mean = " << entity->kMeanTime() << "\n";
553  out << "cpu_system_RMS = " << entity->kRMSTime() << "\n";
554  out << "cpu_system_max = " << entity->kMaximalTime() << "\n";
555  out << "cpu_system_nbr = " << entity->nOfMeasurements() << "\n";
556 
557  // real
558  out << "\n"; // just for clarity
559  out << "cpu_real_total = " << entity->eTotalTime() << "\n";
560  out << "cpu_real_min = " << entity->eMinimalTime() << "\n";
561  out << "cpu_real_mean = " << entity->eMeanTime() << "\n";
562  out << "cpu_real_RMS = " << entity->eRMSTime() << "\n";
563  out << "cpu_real_max = " << entity->eMaximalTime() << "\n";
564  out << "cpu_real_nbr = " << entity->nOfMeasurements() << "\n";
565 
566  }
567 
568  out << std::endl;
569 }
570 // ============================================================================
571 // print the "Stat" part of the ChronoStatSvc
572 // ============================================================================
573 void ChronoStatSvc::printStats()
574 {
576  if ( m_statEntities.empty() ) { return ; }
577 
578  MsgStream log ( msgSvc() , "******Stat******" ) ;
580  const std::string stars( ( m_statCoutFlag ) ? 126 : 100 , '*' ) ;
582  if ( m_statCoutFlag )
583  {
584  std::cout << stars << std::endl;
585  std::cout << " The Final stat Table "
586  << ( m_statOrderFlag ? "(ordered)" : "(not ordered)" ) << std::endl;
587  std::cout << stars << std::endl;
588  }
589  else
590  {
591  log << m_statPrintLevel << stars << endmsg;
592  log << m_statPrintLevel << " The Final stat Table "
593  << ( m_statOrderFlag ? "(ordered)" : "(not ordered)" ) << endmsg;
594  log << m_statPrintLevel << stars << endmsg;
595  }
596 
597  {
598  // prepare container for printing
599  typedef std::pair<const StatEntity*,const StatTag*> SPair;
600  typedef std::vector<SPair> SCont;
601  SCont tmpCont;
602  for( StatMap::const_iterator it = m_statEntities.begin();
603  it != m_statEntities.end(); it++ )
604  { tmpCont.push_back( SPair( &(it->second) , &(it->first) ) ) ; }
605  // sort it
606  if ( m_statOrderFlag )
607  { std::sort( tmpCont.begin() ,
608  tmpCont.end() ,
609  ComparePairOfStatEntityAndStatTag() ); }
610 
611 
612  {
613  // print the table header
614  if ( m_statCoutFlag ) { std::cout << m_header << std::endl ; }
615  else { log << m_statPrintLevel << m_header << endmsg ; }
616  }
617  // loop over counters and print them:
618  for ( SCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
619  {
621  const StatEntity* entity = iter->first ;
622  if ( 0 == entity ) { continue ; }
623  const StatTag* tag = iter->second ;
624  if ( 0 == tag ) { continue ; }
625 
626  if ( m_statCoutFlag )
627  {
628  std::cout
629  << Gaudi::Utils::formatAsTableRow
630  ( *tag , *entity , m_useEffFormat , m_format1 , m_format2 )
631  << std::endl;
632  }
633  else
634  {
635  log
636  << m_statPrintLevel
637  << Gaudi::Utils::formatAsTableRow
638  ( *tag , *entity , m_useEffFormat , m_format1 , m_format2 )
639  << endmsg ;
640  }
641  }
642  tmpCont.clear();
643  }
645  if ( m_statCoutFlag ) { std::cout << stars << std::endl; }
646  else { log << m_statPrintLevel << stars << endmsg; }
647 }
648 
649 // ============================================================================
650 // The END
651 // ============================================================================
Generated at Wed Nov 28 2012 12:17:10 for Gaudi Framework, version v23r5 by Doxygen version 1.8.2 written by Dimitri van Heesch, © 1997-2004