Gaudi Framework, version v20r2
	Generated: 18 Jul 2008

ChronoStatSvc.cpp

Go to the documentation of this file.

// $Id: ChronoStatSvc.cpp,v 1.18 2008/05/13 12:37:19 marcocle Exp $ 
// ============================================================================
// CVS tag $Name: v17r1 $, version $Revision: 1.18 $ 
// ============================================================================
#ifdef _WIN32
#pragma warning( disable : 4786 )
#endif
// ============================================================================
// STD & STL 
// ============================================================================
#include <iostream> 
#include <iomanip> 
#include <string> 
#include <algorithm>
#include <functional>
#include <fstream>
#include <iomanip>
// ============================================================================
// GaudiKernel
// ============================================================================
#include "GaudiKernel/Kernel.h"
#include "GaudiKernel/StatusCode.h"
#include "GaudiKernel/SvcFactory.h"
#include "GaudiKernel/IChronoStatSvc.h"
#include "GaudiKernel/MsgStream.h" 
#include "GaudiKernel/ChronoEntity.h"
#include "GaudiKernel/StatEntity.h"
#include "GaudiKernel/Stat.h"
// ============================================================================
// ============================================================================
#include "ChronoStatSvc.h"
// ============================================================================
// ============================================================================
DECLARE_SERVICE_FACTORY(ChronoStatSvc) 
// ============================================================================
// ============================================================================
// ============================================================================
//  comparison functor 
// ============================================================================
class ComparePairOfChronoEntityAndChronoTag 
  : public std::binary_function< 
  const std::pair<ChronoEntity*,const IChronoStatSvc::ChronoTag*> ,
  const std::pair<ChronoEntity*,const IChronoStatSvc::ChronoTag*> , bool > 
{
public: 
  inline bool operator()
    ( const  std::pair<ChronoEntity*,
      const IChronoStatSvc::ChronoTag*>& p1 , 
      const  std::pair< ChronoEntity*,
      const IChronoStatSvc::ChronoTag*>& p2 ) const 
  {
    const ChronoEntity* e1 = p1.first; 
    const ChronoEntity* e2 = p2.first; 
    return ( ( 0 == e1 || 0 == e2 ) ? true : (*e1)<(*e2) ) ;
  }  
};
// ============================================================================
//  comparison functor 
// ============================================================================
class ComparePairOfStatEntityAndStatTag 
  : public std::binary_function< 
  const std::pair<const StatEntity*,const IChronoStatSvc::StatTag*> ,
  const std::pair<const StatEntity*,const IChronoStatSvc::StatTag*> , bool >
{
public:
  inline bool operator() 
    ( const std::pair<const StatEntity*,
      const IChronoStatSvc::StatTag*>& p1,
      const std::pair<const StatEntity*,
      const IChronoStatSvc::StatTag*>& p2 ) const
  {
    const StatEntity* se1 = p1.first;
    const StatEntity* se2 = p2.first;
    return ( 0 == se1 || 0 == se2 ) ? true : (*se1)<(*se2) ;
  }
};
// ============================================================================
// Constructor 
// ============================================================================
ChronoStatSvc::ChronoStatSvc
( const std::string& name, ISvcLocator* svcloc )
  : Service( name , svcloc ) 
  , m_chronoEntities   ()  
  , m_chronoPrintLevel ( MSG::INFO ) 
  , m_statEntities     ()  
  , m_statPrintLevel   ( MSG::INFO ) 
  //
  // the header row 
  , m_header  ( "     Counter     |     #     |    sum     | mean/eff^* | rms/err^*  |     min     |     max     |")
  // format for regular statistical printout rows
  , m_format1 ( " %|-15.15s|%|17t||%|10d| |%|11.7g| |%|#11.5g| |%|#11.5g| |%|#12.5g| |%|#12.5g| |" )
  // format for "efficiency" statistical printout rows
  , m_format2 ( "*%|-15.15s|%|17t||%|10d| |%|11.5g| |(%|#9.7g| +- %|-#9.7g|)%%|   -------   |   -------   |" )
  // flag to use the special "efficiency" format 
  , m_useEffFormat ( true )
{
  declareProperty ( "ChronoPrintOutTable"    , 
                    m_chronoTableFlag      = true      );
  declareProperty ( "ChronoDestinationCout"  , 
                    m_chronoCoutFlag       = false     );
  declareProperty ( "ChronoPrintLevel"       , 
                    m_intChronoPrintLevel  = MSG::INFO );
  declareProperty ( "ChronoTableToBeOrdered" , 
                    m_chronoOrderFlag      = true      );
  declareProperty ( "PrintUserTime"          , 
                    m_printUserTime        = true      );
  declareProperty ( "PrintSystemTime"        , 
                    m_printSystemTime      = false     );
  declareProperty ( "PrintEllapsedTime"      , 
                    m_printEllapsedTime    = false     );
  declareProperty ( "StatPrintOutTable"      , 
                    m_statTableFlag        = true      );
  declareProperty ( "StatDestinationCout"    , 
                    m_statCoutFlag         = false     );
  declareProperty ( "StatPrintLevel"         , 
                    m_intStatPrintLevel    = MSG::INFO );
  declareProperty ( "StatTableToBeOrdered"   , 
                    m_statOrderFlag        = true      );
  
  // specify the number of events to be skipped by the memory auditor
  // in order to better spot memory leak
  declareProperty ( "NumberOfSkippedEventsForMemStat"      ,  
                    m_numberOfSkippedEventsForMemStat = -1 ) ;

  declareProperty( "AsciiStatsOutputFile",
                   m_statsOutFileName = "",
                   "Name of the output file storing the stats. If empty, no"
                   " statistics will be saved (default)" );
  
  declareProperty 
    ( "StatTableHeader"        , m_header                          , 
      "The header row for the output Stat-table"                   ) ;
  declareProperty 
    ( "RegularRowFormat"       , m_format1                         , 
      "The format for the regular row in the output Stat-table"    ) ;
  declareProperty 
    ( "EfficiencyRowFormat"    , m_format2                         , 
      "The format for the regular row in the outptu Stat-table"    ) ; 
  declareProperty 
    ( "UseEfficiencyRowFormat" , m_useEffFormat                    , 
      "Use the special format for printout of efficiency counters" ) ;
}
// ============================================================================
// Destructor.
// ============================================================================
ChronoStatSvc::~ChronoStatSvc()
{
  // clear the container of chrono entities 
  m_chronoEntities.clear();
  // clear the container of stat   entities 
  m_statEntities.clear();
}
// ============================================================================
// Implementation of IService::initialize()
// ============================================================================
StatusCode ChronoStatSvc::initialize()
{
  StatusCode sc = Service::initialize();
  if ( sc.isFailure() ) return sc;
  MsgStream log( msgSvc() , this->name() ); 

  // Set my own properties
  sc = setProperties();  

  if (sc.isFailure()) {
    log << MSG::ERROR << "setting my properties" << endreq;
    return StatusCode::FAILURE;
  }

  log << MSG::INFO << " Number of skipped events for MemStat" 
      << m_numberOfSkippedEventsForMemStat << endreq ;
  
  m_statPrintLevel = 
    ( MSG::FATAL < m_intStatPrintLevel   ) ? MSG::FATAL : 
    ( MSG::NIL   > m_intStatPrintLevel   ) ? MSG::NIL   : 
    ( MSG::Level ) m_intStatPrintLevel  ; 
  m_chronoPrintLevel = 
    ( MSG::FATAL < m_intChronoPrintLevel ) ? MSG::FATAL : 
    ( MSG::NIL   > m_intChronoPrintLevel ) ? MSG::NIL   : 
    ( MSG::Level ) m_intChronoPrintLevel ;
  if( m_chronoTableFlag  && 
      !m_printUserTime   && 
      !m_printSystemTime && 
      !m_printEllapsedTime ) { m_printUserTime   = true ; } 
  if(  m_printUserTime    ||  
       m_printSystemTime  ||  
       m_printEllapsedTime ) { m_chronoTableFlag = true ; }    
  chronoStart( name() ) ;
  return StatusCode::SUCCESS;
}
// ============================================================================
// Implementation of IService::finalize()
// ============================================================================
StatusCode ChronoStatSvc::finalize()
{
  std::string local = name()+".finalize()"; 
  MsgStream log( msgSvc() , local ); 
  chronoStop( name() ) ;
  
  if ( m_chronoTableFlag && 
       !m_chronoEntities.empty() && 
       ( m_printUserTime || m_printSystemTime ) )   
    {
      MsgStream log( msgSvc() , "*****Chrono*****" ); 
      const std::string stars( ( m_chronoCoutFlag ) ? 126 : 100  , '*' );  
      if( m_chronoCoutFlag  ) 
        { 
          std::cout << stars << std::endl;                           
          std::cout << local <<  " The Final CPU consumption (Chrono) Table " 
                    << ( m_chronoOrderFlag ? "(ordered)" : "(not ordered)" ) << std::endl; 
          std::cout << stars << std::endl;                           
        }
      else 
        {
          log << (MSG::Level) m_chronoPrintLevel 
        << stars << endreq;   
          log << (MSG::Level) m_chronoPrintLevel 
        << " The Final CPU consumption ( Chrono ) Table " 
              << ( m_chronoOrderFlag ? "(ordered)" : "(not ordered)" ) << endreq;  
          log << (MSG::Level) m_chronoPrintLevel << stars << endreq;   
        }
      {  // prepare container for printing 
        typedef std::pair<ChronoEntity*,const ChronoTag*>        MPair;
        typedef std::vector<MPair>                               MCont;
        MCont tmpCont;
        for( ChronoMap::iterator it = m_chronoEntities.begin() ; 
       m_chronoEntities.end() != it ;  ++it ) 
          { tmpCont.push_back( MPair( &(it->second) , &(it->first) ) ) ; } 
        // sort it  
        if( m_chronoOrderFlag ) 
  { std::sort( tmpCont.begin() , 
               tmpCont.end()   , 
               ComparePairOfChronoEntityAndChronoTag() ); } 
        // print User Time statistics 
        if( m_printUserTime   ) 
          {
            for( MCont::iterator iter = tmpCont.begin() ;  tmpCont.end() != iter ; ++iter ) 
              {
                // 
                ChronoEntity*    entity = iter->first  ; if( 0 == entity ) { continue ; } 
                const ChronoTag* tag    = iter->second ; if( 0 == tag    ) { continue ; } 

                entity->stop();              

                if     ( m_chronoCoutFlag )  
                  { std::cout << *tag << "\t"  << entity->outputUserTime  () << std::endl ; } 
                else                         
                  { 
                    MsgStream log( msgSvc() , *tag ) ; 
                    log << m_chronoPrintLevel << entity->outputUserTime  () << endreq ; 
                  }
                //
              }
          }
        if( m_printSystemTime ) 
          {
            if      ( m_printUserTime && m_chronoCoutFlag   ) 
              { std::cout << stars << std::endl;                           } 
            else if ( m_printUserTime && !m_chronoCoutFlag  ) 
              { log << (MSG::Level) m_chronoPrintLevel << stars << endreq; }  
            for( MCont::iterator iter = tmpCont.begin() ;  tmpCont.end() != iter ; ++iter ) 
              {
                ChronoEntity*    entity = iter->first  ; if( 0 == entity ) { continue ; } 
                const ChronoTag* tag    = iter->second ; if( 0 == tag    ) { continue ; } 

                entity->stop();              

                if     ( m_chronoCoutFlag )  
                  { std::cout << *tag << "\t"  << entity->outputSystemTime() << std::endl ; }
                else                         
                  { 
                    MsgStream log( msgSvc() , *tag ) ;  
                    log << m_chronoPrintLevel << entity->outputSystemTime() << endreq ; 
                  }
                //
              }
          }
        if( m_printEllapsedTime ) 
          {
            if      ( ( m_printUserTime || m_printSystemTime ) &&  m_chronoCoutFlag  ) 
              { std::cout << stars << std::endl;                           } 
            else if ( ( m_printUserTime || m_printSystemTime ) && !m_chronoCoutFlag  ) 
              { log << (MSG::Level) m_chronoPrintLevel << stars << endreq; }  
            for( MCont::iterator iter = tmpCont.begin() ;  tmpCont.end() != iter ; ++iter ) 
              {
                ChronoEntity*    entity = iter->first  ; if( 0 == entity ) { continue ; } 
                const ChronoTag* tag    = iter->second ; if( 0 == tag    ) { continue ; } 

                entity->stop();              

                if     ( m_chronoCoutFlag )  
                  { std::cout << *tag << "\t"  << entity->outputElapsedTime() << std::endl ; }
                else                         
                  { 
                    MsgStream log( msgSvc() , *tag ) ;  
                    log << m_chronoPrintLevel << entity->outputElapsedTime() << endreq ;
                  }
                //
              }
          }
        tmpCont.clear();   
      }
      if( m_chronoCoutFlag  ) { std::cout << stars << std::endl;              } 
      else                    { log << m_chronoPrintLevel << stars << endreq; }  
    }
  
    
  if ( m_statTableFlag ) { printStats () ; }
  
  if ( !m_statsOutFileName.value().empty() ) {
    saveStats();
  }
  
  log << MSG::INFO << " Service finalized succesfully " << endreq; 
  
  return Service::finalize(); 
}
// ============================================================================
// Implementation of IInterface::queryInterface()
// ============================================================================
StatusCode    
ChronoStatSvc::queryInterface
( const InterfaceID& riid , 
  void** ppvInterface    )
{
  if ( 0 == ppvInterface ) { return StatusCode::FAILURE ; }
  else if ( IChronoSvc::interfaceID()     == riid ) 
  { *ppvInterface = static_cast<IChronoSvc*>     (this) ; }
  else if ( IStatSvc::interfaceID()       == riid ) 
  { *ppvInterface = static_cast<IStatSvc*>       (this) ; }
  else if ( IChronoStatSvc::interfaceID() == riid ) 
  { *ppvInterface = static_cast<IChronoStatSvc*> (this) ; }
  else { return Service::queryInterface(riid, ppvInterface) ; }
  addRef();
  return StatusCode::SUCCESS;
}
// ============================================================================
// Implementation of IChronoStatSvc::chronoStart
// ============================================================================
ChronoEntity*
ChronoStatSvc::chronoStart
( const ChronoTag& chronoTag )
{
  ChronoEntity& entity = m_chronoEntities [ chronoTag ] ;
  entity.start() ;
  return &entity ;
}
// ============================================================================
// Implementation of IChronoStatSvc::chronoStop
// ============================================================================
const ChronoEntity*
ChronoStatSvc::chronoStop 
( const IChronoStatSvc::ChronoTag& chronoTag )
{
  ChronoEntity& entity = m_chronoEntities [ chronoTag ] ;
  entity.stop() ;
  return &entity ;
}
// ============================================================================
// Implementation of IChronoStatSvc::chronoDelta
// ============================================================================
IChronoStatSvc::ChronoTime 
ChronoStatSvc::chronoDelta
( const IChronoStatSvc::ChronoTag& chronoTag,
  IChronoStatSvc::ChronoType theType )
{
  return m_chronoEntities[ chronoTag ].delta( theType );
}
// ============================================================================
// Implementation of IChronoStatSvc::chronoPrint
// ============================================================================
void    ChronoStatSvc::chronoPrint
( const IChronoStatSvc::ChronoTag& chronoTag )
{
  MsgStream log ( msgSvc() , chronoTag );
  if( m_printUserTime   ) { 
    log << (MSG::Level) m_chronoPrintLevel 
        << m_chronoEntities[ chronoTag ].outputUserTime  () 
        << endreq; 
  }
  if( m_printSystemTime ) { 
    log << (MSG::Level) m_chronoPrintLevel 
        << m_chronoEntities[ chronoTag ].outputSystemTime() 
        << endreq; 
  }
}
// ============================================================================
// Implementation of IChronoSvc::chronoStatus
// ============================================================================
IChronoStatSvc::ChronoStatus 
ChronoStatSvc::chronoStatus
( const IChronoStatSvc::ChronoTag& chronoTag )
{ return m_chronoEntities[ chronoTag ].status(); }
// ============================================================================
// Implementation of IChronoStatSvc::stat
// ============================================================================
void    ChronoStatSvc::stat
( const IChronoStatSvc::StatTag    & statTag    ,
  const IChronoStatSvc::StatFlag   & statFlag   )
{
  StatMap::iterator theIter=m_statEntities.find(statTag);

  StatEntity * theStat=0 ;
  // if new entity, specify the neumber of events to be skipped
  if (theIter==m_statEntities.end()){
    // new stat entity
    StatEntity& theSe = m_statEntities[ statTag ]; 
    theStat=& theSe;
    theStat->setnEntriesBeforeReset(m_numberOfSkippedEventsForMemStat);
  }
  else
  {
    //existing stat entity
    theStat=&((*theIter).second);
  }
  
  theStat->addFlag ( statFlag ) ; 
}
// ============================================================================
// Implementation of IChronoStatSvc::statPrint
// ============================================================================
void    ChronoStatSvc::statPrint
( const IChronoStatSvc::StatTag& statTag )
{
  MsgStream log ( msgSvc() , statTag ) ;
  log << (MSG::Level) m_statPrintLevel << m_statEntities[ statTag ] << endreq; 
}
// ============================================================================
/*  extract the chrono entity for the given tag (name)
 *  @see IChronoStatSvc 
 *  @param t chrono tag(name)
 *  @return pointer to chrono entity 
 */
// ============================================================================
const ChronoEntity* ChronoStatSvc::chrono 
( const IChronoStatSvc::ChronoTag& t ) const  
{
  ChronoMap::const_iterator it = m_chronoEntities.find ( t ) ;
  if ( m_chronoEntities.end() != it ) { return &(it->second) ; }
  return 0 ;
}
// ============================================================================
/*  extract the stat   entity for the given tag (name)
 *  @see IChronoStatSvc 
 *  @param t stat   tag(name)
 *  @return pointer to stat   entity 
 */
// ============================================================================
const StatEntity*   ChronoStatSvc::stat   
( const IChronoStatSvc::StatTag&   t ) const 
{
  StatMap::const_iterator it = m_statEntities.find ( t ) ;
  if ( m_statEntities.end() != it ) { return &(it->second) ; }
  return 0 ;
}
// ============================================================================
// dump all the statistics into an ASCII file
// ============================================================================
void ChronoStatSvc::saveStats()
{
  std::ofstream out( m_statsOutFileName.value().c_str(),
                     std::ios_base::out | std::ios_base::trunc );
  if ( !out.good() ) {
    MsgStream msg( msgSvc() , name() );
    msg << MSG::INFO
        << "Could not open the output file for writing chrono statistics ["
        << m_statsOutFileName.value() << "]"
        << endreq;
    return;
  } else {
    // format it our way
    out << std::scientific << std::setprecision(8) ;
  }

  // ChronoEntity
  typedef std::pair<ChronoEntity*, const ChronoTag*> MPair;
  typedef std::vector<MPair>                         MCont;
  MCont chronos;
    
  for( ChronoMap::iterator it = m_chronoEntities.begin() ; 
       m_chronoEntities.end() != it ;  ++it ) { 
    chronos.push_back( MPair( &(it->second) , &(it->first) ) ) ; 
  } 
    
  // sort it  
  std::sort( chronos.begin() , 
             chronos.end()   , 
             ComparePairOfChronoEntityAndChronoTag() );
    
  // print User Time statistics 
  for( MCont::iterator iter = chronos.begin() ;  
       chronos.end() != iter; 
       ++iter ) {
    // 
    const ChronoEntity*    entity = iter->first; 
    if( 0 == entity ) { continue ; } 
      
    const ChronoTag* tag    = iter->second ; 
    if( 0 == tag    ) { continue ; } 

    // create an entry in the .INI-like table
    out << "\n[" << *tag << "]\n";

    // user
    out << "cpu_user_total = " << entity->uTotalTime() << "\n";
    out << "cpu_user_min = "   << entity->uMinimalTime() << "\n";
    out << "cpu_user_mean = "  << entity->uMeanTime() << "\n";
    out << "cpu_user_RMS = "   << entity->uRMSTime() << "\n";
    out << "cpu_user_max = "   << entity->uMaximalTime() << "\n";
    out << "cpu_user_nbr = "   << entity->nOfMeasurements() << "\n";
    
    // system
    out << "\n"; // just for clarity
    out << "cpu_system_total = " << entity->kTotalTime() << "\n";
    out << "cpu_system_min = "   << entity->kMinimalTime() << "\n";
    out << "cpu_system_mean = "  << entity->kMeanTime() << "\n";
    out << "cpu_system_RMS = "   << entity->kRMSTime() << "\n";
    out << "cpu_system_max = "   << entity->kMaximalTime() << "\n";
    out << "cpu_system_nbr = "   << entity->nOfMeasurements() << "\n";
      
    // real
    out << "\n"; // just for clarity
    out << "cpu_real_total = " << entity->eTotalTime() << "\n";
    out << "cpu_real_min = "   << entity->eMinimalTime() << "\n";
    out << "cpu_real_mean = "  << entity->eMeanTime() << "\n";
    out << "cpu_real_RMS = "   << entity->eRMSTime() << "\n";
    out << "cpu_real_max = "   << entity->eMaximalTime() << "\n";
    out << "cpu_real_nbr = "   << entity->nOfMeasurements() << "\n";

  }
  
  out << std::endl;
}
// ============================================================================
// print the "Stat" part of the ChronoStatSvc
// ============================================================================
void ChronoStatSvc::printStats() 
{
  if ( m_statEntities.empty() ) { return ; }
  
  MsgStream log ( msgSvc() , "******Stat******" ) ; 
  const std::string stars( ( m_statCoutFlag ) ? 126 : 100  , '*' ) ;   
  if ( m_statCoutFlag  ) 
        { 
          std::cout << stars << std::endl;   
          std::cout <<  " The Final stat Table " 
              << ( m_statOrderFlag ? "(ordered)" : "(not ordered)" ) << std::endl;
          std::cout << stars << std::endl;            
        }
  else
  {
          log << m_statPrintLevel << stars << endreq; 
          log <<  m_statPrintLevel << " The Final stat Table " 
              << ( m_statOrderFlag ? "(ordered)" : "(not ordered)" ) << endreq;   
          log << m_statPrintLevel << stars << endreq; 
        } 
  
  {  
    // prepare container for printing 
    typedef std::pair<const StatEntity*,const StatTag*>  SPair;
    typedef std::vector<SPair>                           SCont;
    SCont tmpCont;
    for( StatMap::const_iterator it = m_statEntities.begin(); 
         it != m_statEntities.end(); it++ ) 
    { tmpCont.push_back( SPair( &(it->second) , &(it->first) ) ) ; } 
    // sort it 
    if ( m_statOrderFlag ) 
    { std::sort( tmpCont.begin() , 
                 tmpCont.end()   ,
                 ComparePairOfStatEntityAndStatTag() ); }

    
    {
      // print the table header
      if ( m_statCoutFlag ) { std::cout <<                     m_header << std::endl ; }
      else                  { log       << m_statPrintLevel << m_header << endreq    ; }
    }
    // loop over counters and print them:
    for ( SCont::iterator iter = tmpCont.begin() ; tmpCont.end() != iter ; ++iter ) 
          {
      const StatEntity* entity = iter->first  ; 
      if ( 0 == entity ) { continue ; } 
      const StatTag*    tag    = iter->second ; 
      if ( 0 == tag    ) { continue ; } 

            if ( m_statCoutFlag ) 
      { 
        std::cout 
          << Gaudi::Utils::formatAsTableRow  
          ( *tag , *entity , m_useEffFormat , m_format1 , m_format2 ) 
          << std::endl; 
      } 
            else          
      { 
        log
          << m_statPrintLevel 
          << Gaudi::Utils::formatAsTableRow
          ( *tag , *entity , m_useEffFormat , m_format1 , m_format2 ) 
          << endreq ; 
      } 
          }
    tmpCont.clear();   
  }
  if ( m_statCoutFlag  ) { std::cout << stars << std::endl;            } 
  else                   { log << m_statPrintLevel << stars << endreq; }  
}

// ============================================================================
// The END 
// ============================================================================

---