TimingAuditor.cpp

Go to the documentation of this file.

#include "GaudiKernel/Auditor.h"
#include "GaudiKernel/IToolSvc.h"
#include "GaudiKernel/IIncidentListener.h"
#include "GaudiKernel/IIncidentSvc.h"
#include "GaudiKernel/IToolSvc.h"
#include "GaudiKernel/VectorMap.h"
#include "GaudiKernel/HashMap.h"
#include "GaudiKernel/MsgStream.h"
// ============================================================================
// GaudiAlg
// ============================================================================
#include "GaudiAlg/ISequencerTimerTool.h"
// ============================================================================
#ifdef __ICC
// disable icc warning #654: overloaded virtual function "B::Y" is only partially overridden in class "C"
//   TODO: there is only a partial overload of IAuditor::before and IAuditor::after
#pragma warning(disable:654)
#endif

class TimingAuditor: public extends1<Auditor, IIncidentListener> {
public:

  void before(StandardEventType evt, INamedInterface* alg) override;
  void after(StandardEventType evt, INamedInterface* alg, const StatusCode &sc) override;

  using Auditor::before; // avoid hiding base-class methods
  void before(CustomEventTypeRef evt, const std::string& name) override;
  using Auditor::after; // avoid hiding base-class methods
  void after(CustomEventTypeRef evt, const std::string& name, const StatusCode &sc) override;

private:
  void i_beforeInitialize( INamedInterface* alg );
  void i_afterInitialize( INamedInterface* alg );
  void i_beforeFinalize( INamedInterface* alg );
  void i_beforeExecute( INamedInterface* alg );
  void i_afterExecute( INamedInterface* alg);

public:
  void handle ( const Incident& )  override;

public:
  StatusCode initialize ()  override;
  StatusCode finalize   ()  override;

public:
  TimingAuditor ( const std::string& name, ISvcLocator* pSvc )
    : base_class ( name , pSvc )
  {
    declareProperty ( "OptimizedForDOD" , m_goodForDOD ) ;
  } 
  ~TimingAuditor() override = default;

  // delete default/copy constructor and assignment
  TimingAuditor () = delete;
  TimingAuditor           ( const TimingAuditor& ) = delete ;
  TimingAuditor& operator=( const TimingAuditor& ) = delete ;
private:
  // tool service
  SmartIF<IToolSvc>  m_toolSvc = nullptr; 
  // incident service
  SmartIF<IIncidentSvc> m_incSvc  = nullptr; 
  // the timer tool
  ISequencerTimerTool* m_timer   = nullptr; 
  // ApplicationManager
  SmartIF<INamedInterface> m_appMgr  = nullptr; 
  //
  GaudiUtils::VectorMap<const INamedInterface*,int>  m_map     ;
  // indentation level
  int                  m_indent  = 0 ; 
  // "in event"
  bool                 m_inEvent = false ; 
  // "optimized for Data-On-Demand Service"
  bool                 m_goodForDOD = false ; 
  //
  GaudiUtils::HashMap<std::string,int> m_mapUser ; 

  // Whether the timing has been saved already
  bool                 m_histoSaved = false ;


} ;
// ============================================================================
// ============================================================================
DECLARE_COMPONENT(TimingAuditor)
// ============================================================================
StatusCode TimingAuditor::initialize ()
{
  StatusCode sc = Auditor::initialize() ;
  if ( sc.isFailure() ) { return sc ; }                  // RETURN

  MsgStream log ( msgSvc() , name() ) ;

  // get tool service
  if ( ! m_toolSvc )
  {
    m_toolSvc = Auditor::service ( "ToolSvc" );
    if ( !m_toolSvc )
    {
      log << "Could not retrieve 'ToolSvc' " << endmsg ;
      return StatusCode::FAILURE ;                                        // RETURN
    }
    if ( !m_timer )
    {
      sc = m_toolSvc->retrieveTool
        ( "SequencerTimerTool/TIMER" , m_timer , this  , true ) ;
      if ( sc.isFailure() )
      {
        log << MSG::ERROR
            << "Could not retrieve ISequencerTimerTool" << endmsg ;
        return sc ;
      }
    }
  }
  // get incident service
  if ( !m_incSvc )
  {
    m_incSvc = Auditor::service ( "IncidentSvc" );
    if ( !m_incSvc )
    {
      log << MSG::ERROR
          << "Could not retrieve 'IncidentSvc'" << endmsg ;
      return StatusCode::FAILURE ;
    }
    m_incSvc -> addListener ( this , IncidentType::BeginEvent ) ;
    m_incSvc -> addListener ( this , IncidentType::EndEvent   ) ;
  }
  // get the application manager
  if ( !m_appMgr )
  {
    m_appMgr = Auditor::service ( "ApplicationMgr" );
    if ( !m_appMgr )
    {
      log << MSG::ERROR
          << "Could not retrieve 'ApplicationMgr'" << endmsg ;
      return sc ;
    }
    if ( m_map.end() == m_map.find( m_appMgr.get() ) )
    {
      m_map.insert ( m_appMgr.get() , m_timer->addTimer( "EVENT LOOP" )  ) ;
    }
  }
  //
  return StatusCode::SUCCESS ;
}
// ============================================================================
StatusCode TimingAuditor::finalize   ()
{
  if ( m_incSvc )
  {
    m_incSvc -> removeListener ( this , IncidentType::BeginEvent ) ;
    m_incSvc -> removeListener ( this , IncidentType::EndEvent   ) ;
    m_incSvc.reset();
  }
  if ( m_toolSvc )
  {
    // the 2 following line are commented out: it is
    // is a temporary hack which prevent a crash due to a problem in
    // the reference counting
    //     if ( 0 != m_timer )
    //     { m_toolSvc -> releaseTool ( m_timer ) . ignore() ; m_timer = 0 ; }
    m_toolSvc.reset();
  }
  m_appMgr.reset();
  // clear the map
  m_map.clear() ;
  // finalize the base class
  return Auditor::finalize () ;
}
// ============================================================================
void TimingAuditor::before(StandardEventType evt, INamedInterface *alg)
{
  switch (evt) {
  case IAuditor::Initialize : i_beforeInitialize( alg ); break;
  case IAuditor::Execute    : i_beforeExecute( alg );    break;
  case IAuditor::Finalize   : i_beforeFinalize( alg );   break;
  default: break;
  }
}
// ============================================================================
void TimingAuditor::after(StandardEventType evt, INamedInterface *alg, const StatusCode &)
{
  switch (evt) {
  case IAuditor::Initialize : i_afterInitialize( alg ); break;
  case IAuditor::Execute    : i_afterExecute( alg ); break;
  default: break;
  }
}
// ============================================================================
void TimingAuditor::i_beforeFinalize( INamedInterface* /*alg*/ )
{
  if (!m_histoSaved)
  {
    m_timer->saveHistograms();
    m_histoSaved = true;
  }
}

// ============================================================================
void TimingAuditor::i_beforeInitialize( INamedInterface* alg )
{
  if ( m_goodForDOD ) { return ; }
  //
  if ( !alg ) { return ; }
  auto found = m_map.find( alg ) ;
  if ( m_map.end() != found ) { return ; }
  ++m_indent ;
  std::string nick = alg->name() ;
  if ( 0 < m_indent ) { nick = std::string ( m_indent , ' ') + nick ; }
  if ( m_inEvent )
  {
    nick[0] = '*' ;
    MsgStream log( msgSvc() , name() ) ;
    log << MSG::DEBUG
        << "Insert non-structural component '"
        << alg->name() << "' of type '"
        << System::typeinfoName(typeid(*alg)) << "' at level "
        << m_indent << endmsg ;
  }
  int timer = m_timer->addTimer( nick ) ;
  m_map.insert ( alg , timer ) ;
  m_timer->start( timer ) ;
}
// ============================================================================
void TimingAuditor::i_afterInitialize( INamedInterface* alg )
{
  if ( m_goodForDOD || !alg ) { return ; }
  --m_indent ;
}
// ============================================================================
void TimingAuditor::i_beforeExecute( INamedInterface* alg )
{
  if ( !alg ) { return ; }
  ++m_indent ;
  auto found = m_map.find( alg ) ;
  if ( m_map.end() == found )
  {
    MsgStream log( msgSvc() , name() ) ;
    log << MSG::DEBUG
        << "Insert non-structural component '"
        << alg->name() << "' of type '"
        << System::typeinfoName(typeid(*alg)) << "' at level "
        << m_indent << endmsg ;
    std::string nick = alg->name() ;
    if ( 0 < m_indent  ) { nick = std::string ( m_indent , ' ') + nick ; }
    if ( !m_goodForDOD ) { nick[0]='*' ;}
    int timer = m_timer->addTimer( nick ) ;
    m_map.insert ( alg , timer ) ;
    m_timer->start( timer ) ;
    return ;
  }
  m_timer->start( found->second ) ;
}
// ============================================================================
void TimingAuditor::i_afterExecute( INamedInterface* alg )
{
  if ( !alg ) { return ; }
  auto found = m_map.find( alg ) ;
  if ( m_map.end() == found ) { return ; }
  m_timer->stop( found->second ) ;
  --m_indent ;
}
// ============================================================================
void TimingAuditor::before(CustomEventTypeRef evt, const std::string& name)
{
  // Ignore obvious mistakes
  if ( name.empty() && evt.empty() ) { return; }

  // look for the user timer in the map
  int timer = 0;
  std::string nick = name + ":" + evt;
  auto found = m_mapUser.find( nick );

  if ( m_mapUser.end() == found ) {
    // add a new timer if not yet available
    timer = m_timer->addTimer( nick ) ;
    m_mapUser[nick] = timer;
  } else {
    timer = found->second;
  }
  m_timer->start( timer );
}
// ============================================================================
void TimingAuditor::after(CustomEventTypeRef evt, const std::string& name, const StatusCode &)
{
  // Ignore obvious mistakes
  if ( name.empty() && evt.empty() ) { return; }

  // look for the user timer in the map
  std::string nick = name + ":" + evt;
  auto found = m_mapUser.find( nick );

  // We cannot do much if the timer is not available
  if ( m_mapUser.end() == found ) {
    MsgStream log(msgSvc(), this->name());
    log << MSG::WARNING << "Trying to stop the measure  of the timing for '"
                        << nick << "' but it was never started. Check the code"
                        << endmsg;
    return;
  }
  m_timer->stop( found->second );
}
// ============================================================================
void TimingAuditor::handle ( const Incident& i )
{
  if      ( IncidentType::BeginEvent == i.type () ) {
    m_timer -> start ( m_map[ m_appMgr.get() ] ) ;
    ++m_indent ;
    m_inEvent = true ;
  } else if ( IncidentType::EndEvent   == i.type () ) {
    m_timer -> stop  ( m_map[ m_appMgr.get() ] ) ;
    --m_indent ;
    m_inEvent = false ;
  }
}
// ============================================================================
// The END
// ============================================================================