Gaudi Framework, version v24r2

Home   Generated: Wed Dec 4 2013
 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"
25 #include "GaudiKernel/MsgStream.h"
27 #include "GaudiKernel/StatEntity.h"
28 #include "GaudiKernel/Stat.h"
30 // ============================================================================
32 // ============================================================================
33 #include "ChronoStatSvc.h"
34 // ============================================================================
37 // ============================================================================
39 // ============================================================================
46 // ============================================================================
47 // ============================================================================
48 // comparison functor
49 // ============================================================================
51  : public std::binary_function<
52  const std::pair<ChronoEntity*,const IChronoStatSvc::ChronoTag*> ,
53  const std::pair<ChronoEntity*,const IChronoStatSvc::ChronoTag*> , bool >
54 {
55 public:
56  inline bool operator()
58  const IChronoStatSvc::ChronoTag*>& p1 ,
59  const std::pair< ChronoEntity*,
60  const IChronoStatSvc::ChronoTag*>& p2 ) const
61  {
62  const ChronoEntity* e1 = p1.first;
63  const ChronoEntity* e2 = p2.first;
64  return ( ( 0 == e1 || 0 == e2 ) ? true : (*e1)<(*e2) ) ;
65  }
66 };
67 // ============================================================================
68 // comparison functor
69 // ============================================================================
71  : public std::binary_function<
72  const std::pair<const StatEntity*,const IChronoStatSvc::StatTag*> ,
73  const std::pair<const StatEntity*,const IChronoStatSvc::StatTag*> , bool >
74 {
75 public:
77  inline bool operator()
78  ( const std::pair<const StatEntity*,
79  const IChronoStatSvc::StatTag*>& p1,
80  const std::pair<const StatEntity*,
81  const IChronoStatSvc::StatTag*>& p2 ) const
82  {
83  const StatEntity* se1 = p1.first;
84  const StatEntity* se2 = p2.first;
85  return ( 0 == se1 || 0 == se2 ) ? true : (*se1)<(*se2) ;
86  }
87 };
88 // ============================================================================
89 // Constructor
90 // ============================================================================
92 ( const std::string& name, ISvcLocator* svcloc )
93  : base_class( name , svcloc )
94  , m_chronoEntities ()
95  , m_chronoPrintLevel ( MSG::INFO )
96  , m_statEntities ()
97  , m_statPrintLevel ( MSG::INFO )
98  //
99  // the header row
100  , m_header ( " Counter | # | sum | mean/eff^* | rms/err^* | min | max |")
101  // format for regular statistical printout rows
102  , m_format1 ( " %|-15.15s|%|17t||%|10d| |%|11.7g| |%|#11.5g| |%|#11.5g| |%|#12.5g| |%|#12.5g| |" )
103  // format for "efficiency" statistical printout rows
104  , m_format2 ( "*%|-15.15s|%|17t||%|10d| |%|11.5g| |(%|#9.7g| +- %|-#9.7g|)%%| ------- | ------- |" )
105  // flag to use the special "efficiency" format
106  , m_useEffFormat ( true )
107 {
109  declareProperty ( "ChronoPrintOutTable" ,
110  m_chronoTableFlag = true );
112  declareProperty ( "ChronoDestinationCout" ,
113  m_chronoCoutFlag = false );
115  declareProperty ( "ChronoPrintLevel" ,
116  m_intChronoPrintLevel = MSG::INFO );
119  declareProperty ( "ChronoTableToBeOrdered" ,
120  m_chronoOrderFlag = true );
122  declareProperty ( "PrintUserTime" ,
123  m_printUserTime = true );
125  declareProperty ( "PrintSystemTime" ,
126  m_printSystemTime = false );
128  declareProperty ( "PrintEllapsedTime" ,
129  m_printEllapsedTime = false );
132  declareProperty ( "StatPrintOutTable" ,
133  m_statTableFlag = true );
135  declareProperty ( "StatDestinationCout" ,
136  m_statCoutFlag = false );
138  declareProperty ( "StatPrintLevel" ,
139  m_intStatPrintLevel = MSG::INFO );
142  declareProperty ( "StatTableToBeOrdered" ,
143  m_statOrderFlag = true );
144 
145  // specify the number of events to be skipped by the memory auditor
146  // in order to better spot memory leak
147  declareProperty ( "NumberOfSkippedEventsForMemStat" ,
148  m_numberOfSkippedEventsForMemStat = -1 ) ;
149 
150  declareProperty( "AsciiStatsOutputFile",
151  m_statsOutFileName = "",
152  "Name of the output file storing the stats. If empty, no"
153  " statistics will be saved (default)" );
154 
155  declareProperty
156  ( "StatTableHeader" , m_header ,
157  "The header row for the output Stat-table" ) ;
158  declareProperty
159  ( "RegularRowFormat" , m_format1 ,
160  "The format for the regular row in the output Stat-table" ) ;
161  declareProperty
162  ( "EfficiencyRowFormat" , m_format2 ,
163  "The format for the regular row in the output Stat-table" ) ;
164  declareProperty
165  ( "UseEfficiencyRowFormat" , m_useEffFormat ,
166  "Use the special format for printout of efficiency counters" ) ;
167 
168  declareProperty
169  ( "PerEventFile", m_perEventFile="",
170  "File name for per-event deltas" );
171 
172 }
173 // ============================================================================
174 // Destructor.
175 // ============================================================================
177 {
178  // clear the container of chrono entities
180  // clear the container of stat entities
182 }
183 // ============================================================================
184 // Implementation of IService::initialize()
185 // ============================================================================
187 {
189  if ( sc.isFailure() ) return sc;
191  MsgStream log( msgSvc() , this->name() );
192 
193  // Set my own properties
194  sc = setProperties();
195 
196  if (sc.isFailure()) {
197  log << MSG::ERROR << "setting my properties" << endmsg;
198  return StatusCode::FAILURE;
199  }
200 
201  // only add an EndEvent listener if per-event output requested
202  if (m_perEventFile != "") {
203  m_ofd.open(m_perEventFile.c_str());
204  if (!m_ofd.is_open()) {
205  log << MSG::ERROR << "unable to open per-event output file \""
206  << m_perEventFile << "\"" << endmsg;
207  return StatusCode::FAILURE;
208  } else {
209  SmartIF<IIncidentSvc> ii(serviceLocator()->service("IncidentSvc"));
210  if (! ii) {
211  log << MSG::ERROR << "Unable to find IncidentSvc" << endmsg;
212  return StatusCode::FAILURE;
213  }
214  ii->addListener(this, IncidentType::EndEvent);
215  }
216  }
217 
218  log << MSG::INFO << " Number of skipped events for MemStat"
220 
234  if( m_chronoTableFlag &&
235  !m_printUserTime &&
237  !m_printEllapsedTime ) { m_printUserTime = true ; }
239  if( m_printUserTime ||
244  chronoStart( name() ) ;
246  return StatusCode::SUCCESS;
247 }
248 // ============================================================================
249 // Implementation of IService::finalize()
250 // ============================================================================
252 {
253  std::string local = name()+".finalize()";
255  MsgStream main_log( msgSvc() , local );
258  chronoStop( name() ) ;
259 
260  if (m_ofd.is_open()) {
261  MsgStream log(msgSvc(), name());
262  log << MSG::DEBUG << "writing per-event timing data to '" << m_perEventFile << "'" << endmsg;
263  std::string alg;
265  for (itr=m_perEvtTime.begin(); itr != m_perEvtTime.end(); ++itr) {
266  alg = itr->first;
267  alg.erase(alg.length()-8,8);
268  m_ofd << alg << " ";
270  for (itt=itr->second.begin(); itt!=itr->second.end(); ++itt) {
271  m_ofd << " " << (long int)(*itt);
272  }
273  m_ofd << std::endl;
274  }
275 
276  m_ofd.close();
277  }
278 
281  if ( m_chronoTableFlag &&
282  !m_chronoEntities.empty() &&
284  {
286  MsgStream log( msgSvc() , "*****Chrono*****" );
287  const std::string stars( ( m_chronoCoutFlag ) ? 126 : 100 , '*' );
288  if( m_chronoCoutFlag )
289  {
290  std::cout << stars << std::endl;
291  std::cout << local << " The Final CPU consumption (Chrono) Table "
292  << ( m_chronoOrderFlag ? "(ordered)" : "(not ordered)" ) << std::endl;
293  std::cout << stars << std::endl;
294  }
295  else
296  {
298  << stars << endmsg;
300  << " The Final CPU consumption ( Chrono ) Table "
301  << ( m_chronoOrderFlag ? "(ordered)" : "(not ordered)" ) << endmsg;
302  log << (MSG::Level) m_chronoPrintLevel << stars << endmsg;
303  }
305  { // prepare container for printing
307  typedef std::vector<MPair> MCont;
308  MCont tmpCont;
310  m_chronoEntities.end() != it ; ++it )
311  { tmpCont.push_back( MPair( &(it->second) , &(it->first) ) ) ; }
312  // sort it
313  if( m_chronoOrderFlag )
314  { std::sort( tmpCont.begin() ,
315  tmpCont.end() ,
317  // print User Time statistics
318  if( m_printUserTime )
319  {
320  for( MCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
321  {
322  //
323  ChronoEntity* entity = iter->first ; if( 0 == entity ) { continue ; }
324  const ChronoTag* tag = iter->second ; if( 0 == tag ) { continue ; }
325 
326  entity->stop();
327 
328  if ( m_chronoCoutFlag )
329  { std::cout << *tag << "\t" << entity->outputUserTime () << std::endl ; }
330  else
331  {
332  MsgStream(msgSvc(), *tag)
333  << m_chronoPrintLevel << entity->outputUserTime () << endmsg ;
334  }
335  //
336  }
337  }
339  if( m_printSystemTime )
340  {
344  { std::cout << stars << std::endl; }
345  else if ( m_printUserTime && !m_chronoCoutFlag )
346  { log << (MSG::Level) m_chronoPrintLevel << stars << endmsg; }
348  for( MCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
349  {
351  ChronoEntity* entity = iter->first ; if( 0 == entity ) { continue ; }
352  const ChronoTag* tag = iter->second ; if( 0 == tag ) { continue ; }
353 
354  entity->stop();
355 
356  if ( m_chronoCoutFlag )
357  { std::cout << *tag << "\t" << entity->outputSystemTime() << std::endl ; }
358  else
359  {
360  MsgStream(msgSvc(), *tag)
361  << m_chronoPrintLevel << entity->outputSystemTime() << endmsg ;
362  }
363  //
364  }
365  }
367  if( m_printEllapsedTime )
368  {
372  { std::cout << stars << std::endl; }
373  else if ( ( m_printUserTime || m_printSystemTime ) && !m_chronoCoutFlag )
374  { log << (MSG::Level) m_chronoPrintLevel << stars << endmsg; }
376  for( MCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
377  {
379  ChronoEntity* entity = iter->first ; if( 0 == entity ) { continue ; }
380  const ChronoTag* tag = iter->second ; if( 0 == tag ) { continue ; }
381 
382  entity->stop();
383 
384  if ( m_chronoCoutFlag )
385  { std::cout << *tag << "\t" << entity->outputElapsedTime() << std::endl ; }
386  else
387  {
388  MsgStream(msgSvc(), *tag)
389  << m_chronoPrintLevel << entity->outputElapsedTime() << endmsg ;
390  }
391  //
392  }
393  }
395  tmpCont.clear();
396  }
398  if( m_chronoCoutFlag ) { std::cout << stars << std::endl; }
399  else { log << m_chronoPrintLevel << stars << endmsg; }
400  }
401 
403 
405  if ( m_statTableFlag ) { printStats () ; }
406 
407  if ( !m_statsOutFileName.value().empty() ) {
408  saveStats();
409  }
410 
411  main_log << MSG::INFO << " Service finalized successfully " << endmsg;
412 
413  return Service::finalize();
414 }
415 // ============================================================================
416 // Implementation of IChronoStatSvc::chronoStart
417 // ============================================================================
418 ChronoEntity*
420 ( const ChronoTag& chronoTag )
421 {
422  ChronoEntity& entity = m_chronoEntities [ chronoTag ] ;
423  entity.start() ;
424  return &entity ;
425 }
426 // ============================================================================
427 // Implementation of IChronoStatSvc::chronoStop
428 // ============================================================================
429 const ChronoEntity*
431 ( const IChronoStatSvc::ChronoTag& chronoTag )
432 {
433  ChronoEntity& entity = m_chronoEntities [ chronoTag ] ;
434  entity.stop() ;
435  return &entity ;
436 }
437 // ============================================================================
438 // Implementation of IChronoStatSvc::chronoDelta
439 // ============================================================================
442 ( const IChronoStatSvc::ChronoTag& chronoTag,
444 {
445  return m_chronoEntities[ chronoTag ].delta( theType );
446 }
447 // ============================================================================
448 // Implementation of IChronoStatSvc::chronoPrint
449 // ============================================================================
451 ( const IChronoStatSvc::ChronoTag& chronoTag )
452 {
453  MsgStream log ( msgSvc() , chronoTag );
454  if( m_printUserTime ) {
455  log << (MSG::Level) m_chronoPrintLevel
456  << m_chronoEntities[ chronoTag ].outputUserTime ()
457  << endmsg;
458  }
459  if( m_printSystemTime ) {
460  log << (MSG::Level) m_chronoPrintLevel
461  << m_chronoEntities[ chronoTag ].outputSystemTime()
462  << endmsg;
463  }
464 }
465 // ============================================================================
466 // Implementation of IChronoSvc::chronoStatus
467 // ============================================================================
470 ( const IChronoStatSvc::ChronoTag& chronoTag )
471 { return m_chronoEntities[ chronoTag ].status(); }
472 // ============================================================================
473 // Implementation of IChronoStatSvc::stat
474 // ============================================================================
476 ( const IChronoStatSvc::StatTag & statTag ,
477  const IChronoStatSvc::StatFlag & statFlag )
478 {
479  StatMap::iterator theIter=m_statEntities.find(statTag);
480 
481  StatEntity * theStat=0 ;
482  // if new entity, specify the number of events to be skipped
483  if (theIter==m_statEntities.end()){
484  // new stat entity
485  StatEntity& theSe = m_statEntities[ statTag ];
486  theStat=& theSe;
487  theStat->setnEntriesBeforeReset(m_numberOfSkippedEventsForMemStat);
488  }
489  else
490  {
491  //existing stat entity
492  theStat=&((*theIter).second);
493  }
494 
495  theStat->addFlag ( statFlag ) ;
496 }
497 // ============================================================================
498 // Implementation of IChronoStatSvc::statPrint
499 // ============================================================================
501 ( const IChronoStatSvc::StatTag& statTag )
502 {
503  MsgStream log ( msgSvc() , statTag ) ;
504  log << (MSG::Level) m_statPrintLevel << m_statEntities[ statTag ] << endmsg;
505 }
506 // ============================================================================
507 /* extract the chrono entity for the given tag (name)
508  * @see IChronoStatSvc
509  * @param t chrono tag(name)
510  * @return pointer to chrono entity
511  */
512 // ============================================================================
513 const ChronoEntity* ChronoStatSvc::chrono
514 ( const IChronoStatSvc::ChronoTag& t ) const
515 {
516  ChronoMap::const_iterator it = m_chronoEntities.find ( t ) ;
517  if ( m_chronoEntities.end() != it ) { return &(it->second) ; }
518  return 0 ;
519 }
520 // ============================================================================
521 /* extract the stat entity for the given tag (name)
522  * @see IChronoStatSvc
523  * @param t stat tag(name)
524  * @return pointer to stat entity
525  */
526 // ============================================================================
528 ( const IChronoStatSvc::StatTag& t ) const
529 {
530  StatMap::const_iterator it = m_statEntities.find ( t ) ;
531  if ( m_statEntities.end() != it ) { return &(it->second) ; }
532  return 0 ;
533 }
534 // ============================================================================
535 // dump all the statistics into an ASCII file
536 // ============================================================================
538 {
539  std::ofstream out( m_statsOutFileName.value().c_str(),
541  if ( !out.good() ) {
542  MsgStream msg( msgSvc() , name() );
543  msg << MSG::INFO
544  << "Could not open the output file for writing chrono statistics ["
545  << m_statsOutFileName.value() << "]"
546  << endmsg;
547  return;
548  } else {
549  // format it our way
550  out << std::scientific << std::setprecision(8) ;
551  }
552 
553  // ChronoEntity
555  typedef std::vector<MPair> MCont;
556  MCont chronos;
557 
559  m_chronoEntities.end() != it ; ++it ) {
560  chronos.push_back( MPair( &(it->second) , &(it->first) ) ) ;
561  }
562 
563  // sort it
564  std::sort( chronos.begin() ,
565  chronos.end() ,
567 
568  // print User Time statistics
569  for( MCont::iterator iter = chronos.begin() ;
570  chronos.end() != iter;
571  ++iter ) {
572  //
573  const ChronoEntity* entity = iter->first;
574  if( 0 == entity ) { continue ; }
575 
576  const ChronoTag* tag = iter->second ;
577  if( 0 == tag ) { continue ; }
578 
579  // create an entry in the .INI-like table
580  out << "\n[" << *tag << "]\n";
581 
582  // user
583  out << "cpu_user_total = " << entity->uTotalTime() << "\n";
584  out << "cpu_user_min = " << entity->uMinimalTime() << "\n";
585  out << "cpu_user_mean = " << entity->uMeanTime() << "\n";
586  out << "cpu_user_RMS = " << entity->uRMSTime() << "\n";
587  out << "cpu_user_max = " << entity->uMaximalTime() << "\n";
588  out << "cpu_user_nbr = " << entity->nOfMeasurements() << "\n";
589 
590  // system
591  out << "\n"; // just for clarity
592  out << "cpu_system_total = " << entity->kTotalTime() << "\n";
593  out << "cpu_system_min = " << entity->kMinimalTime() << "\n";
594  out << "cpu_system_mean = " << entity->kMeanTime() << "\n";
595  out << "cpu_system_RMS = " << entity->kRMSTime() << "\n";
596  out << "cpu_system_max = " << entity->kMaximalTime() << "\n";
597  out << "cpu_system_nbr = " << entity->nOfMeasurements() << "\n";
598 
599  // real
600  out << "\n"; // just for clarity
601  out << "cpu_real_total = " << entity->eTotalTime() << "\n";
602  out << "cpu_real_min = " << entity->eMinimalTime() << "\n";
603  out << "cpu_real_mean = " << entity->eMeanTime() << "\n";
604  out << "cpu_real_RMS = " << entity->eRMSTime() << "\n";
605  out << "cpu_real_max = " << entity->eMaximalTime() << "\n";
606  out << "cpu_real_nbr = " << entity->nOfMeasurements() << "\n";
607 
608  }
609 
610  out << std::endl;
611 }
612 // ============================================================================
613 // print the "Stat" part of the ChronoStatSvc
614 // ============================================================================
616 {
618  if ( m_statEntities.empty() ) { return ; }
619 
620  MsgStream log ( msgSvc() , "******Stat******" ) ;
622  const std::string stars( ( m_statCoutFlag ) ? 126 : 100 , '*' ) ;
624  if ( m_statCoutFlag )
625  {
626  std::cout << stars << std::endl;
627  std::cout << " The Final stat Table "
628  << ( m_statOrderFlag ? "(ordered)" : "(not ordered)" ) << std::endl;
629  std::cout << stars << std::endl;
630  }
631  else
632  {
633  log << m_statPrintLevel << stars << endmsg;
634  log << m_statPrintLevel << " The Final stat Table "
635  << ( m_statOrderFlag ? "(ordered)" : "(not ordered)" ) << endmsg;
636  log << m_statPrintLevel << stars << endmsg;
637  }
638 
639  {
640  // prepare container for printing
642  typedef std::vector<SPair> SCont;
643  SCont tmpCont;
645  it != m_statEntities.end(); it++ )
646  { tmpCont.push_back( SPair( &(it->second) , &(it->first) ) ) ; }
647  // sort it
648  if ( m_statOrderFlag )
649  { std::sort( tmpCont.begin() ,
650  tmpCont.end() ,
652 
653 
654  {
655  // print the table header
656  if ( m_statCoutFlag ) { std::cout << m_header << std::endl ; }
657  else { log << m_statPrintLevel << m_header << endmsg ; }
658  }
659  // loop over counters and print them:
660  for ( SCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter )
661  {
663  const StatEntity* entity = iter->first ;
664  if ( 0 == entity ) { continue ; }
665  const StatTag* tag = iter->second ;
666  if ( 0 == tag ) { continue ; }
667 
668  if ( m_statCoutFlag )
669  {
670  std::cout
672  ( *tag , *entity , m_useEffFormat , m_format1 , m_format2 )
673  << std::endl;
674  }
675  else
676  {
677  log
680  ( *tag , *entity , m_useEffFormat , m_format1 , m_format2 )
681  << endmsg ;
682  }
683  }
684  tmpCont.clear();
685  }
687  if ( m_statCoutFlag ) { std::cout << stars << std::endl; }
688  else { log << m_statPrintLevel << stars << endmsg; }
689 }
690 
691 // ============================================================================
692 
693 void ChronoStatSvc::handle(const Incident& /* inc */) {
694 
695  if (! m_ofd.is_open()) return;
696 
699  for (itr=m_chronoEntities.begin(); itr != m_chronoEntities.end(); ++itr) {
700  if (itr->first.find(":Execute") == std::string::npos) continue;
701 
702  itm = m_perEvtTime.find(itr->first);
703  if (itm == m_perEvtTime.end()) {
704  // for when we move past gcc46....
705  // m_perEvtTime[itr->first] =
706  // std::vector<IChronoSvc::ChronoTime> {
707  // itr->second.delta(IChronoSvc::ELAPSED) };
708 
710  m_perEvtTime[itr->first].push_back(itr->second.delta(IChronoSvc::ELAPSED));
711  } else {
712  itm->second.push_back( itr->second.delta(IChronoSvc::ELAPSED) );
713  }
714  }
715 
716 }
717 
718 
719 // ============================================================================
720 // The END
721 // ============================================================================

Generated at Wed Dec 4 2013 14:33:07 for Gaudi Framework, version v24r2 by Doxygen version 1.8.2 written by Dimitri van Heesch, © 1997-2004