Skip to content

StatusCode check fixes, master branch (2017.10.26.)

Attila Krasznahorkay requested to merge akraszna/GaudiGaudi:StatusCodeCheckFixes-master-20171026 into master

I only noticed these issues while trying to understand why our analysis test code was not scaling properly with the number of threads enabled. (I could never get it to use "more than 200% CPU", however many threads I used.) Turns out that the messages that I've just ignored at the end of our jobs, have a really huge significance... 😛

To give you a feeling of how much of a difference these changes make in our setup, this is what I got with our test code on top of today's master branch.

    o OUTPUT ('egammaTruthParticles')
    o OUTPUT ('finalTauPi0s')
    o OUTPUT ('xTrigDecision')
  ECalibAlg
    o INPUT  ('Electrons')
    o OUTPUT ('CalibratedElectrons')ESC[m
AvalancheSchedulerSvc     INFO No unmet INPUT data dependencies were foundESC[m
AvalancheSchedulerSvc     INFO Concurrency level information:ESC[m
AvalancheSchedulerSvc     INFO  o Number of events in flight: 4ESC[m
AvalancheSchedulerSvc     INFO  o TBB thread pool size:  'ThreadPoolSize':4ESC[m
ApplicationMgr            INFO Application Manager Initialized successfullyESC[m
ApplicationMgr            INFO Application Manager Started successfullyESC[m
EventLoopMgr         INFO Starting loop on events
EventLoopMgr         INFO   ===>>>  start of run 300000    <<<===
EventLoopMgr         INFO   ===>>>  start processing event #78, run #300000 on slot 0,  0 events processed so far  <<<===
EventLoopMgr         INFO   ===>>>  done processing event #78, run #300000 on slot 0,  4 events processed so far  <<<===
...
EventLoopMgr         INFO   ===>>>  start processing event #5253, run #300000 on slot 0,  4897 events processed so far  <<<===
EventLoopMgr         INFO   ===>>>  done processing event #5253, run #300000 on slot 0,  4901 events processed so far  <<<===
EventLoopMgr         INFO ---> Loop Finished (seconds): 88.2502
ApplicationMgr            INFO Application Manager Stopped successfullyESC[m
AvalancheSchedulerSvc     INFO Joining Scheduler threadESC[m
AvalancheSchedulerSvc     INFO Terminating thread-pool resourcesESC[m
ToolSvc                   INFO Removing all tools created by ToolSvcESC[m
StatusCodeSvc             INFO listing all unchecked return codes:ESC[m
StatusCodeSvc             INFO 
Num | Function                       | Source Library
----+--------------------------------+------------------------------------------
565000 | Algorithm::commitHandles()     | libGaudiKernel.so
39524 | AvalancheSchedulerSvc::updateStates(int, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&) | libGaudiHive.so
ESC[m
ApplicationMgr            INFO Application Manager Finalized successfullyESC[m
ApplicationMgr            INFO Application Manager Terminated successfullyESC[m
xAOD::TFileAccessTracer   INFO    Sending file access statistics to http://rucio-lb-prod.cern.ch:18762/traces/

And after the fix I see:

    o OUTPUT ('egammaTruthParticles')
    o OUTPUT ('finalTauPi0s')
    o OUTPUT ('xTrigDecision')
  ECalibAlg
    o INPUT  ('Electrons')
    o OUTPUT ('CalibratedElectrons')ESC[m
AvalancheSchedulerSvc     INFO No unmet INPUT data dependencies were foundESC[m
AvalancheSchedulerSvc     INFO Concurrency level information:ESC[m
AvalancheSchedulerSvc     INFO  o Number of events in flight: 4ESC[m
AvalancheSchedulerSvc     INFO  o TBB thread pool size:  'ThreadPoolSize':4ESC[m
ApplicationMgr            INFO Application Manager Initialized successfullyESC[m
ApplicationMgr            INFO Application Manager Started successfullyESC[m
EventLoopMgr         INFO Starting loop on events
EventLoopMgr         INFO   ===>>>  start of run 300000    <<<===
EventLoopMgr         INFO   ===>>>  start processing event #78, run #300000 on slot 0,  0 events processed so far  <<<===
EventLoopMgr         INFO   ===>>>  done processing event #78, run #300000 on slot 0,  1 events processed so far  <<<===
...
EventLoopMgr         INFO   ===>>>  start processing event #5253, run #300000 on slot 2,  4897 events processed so far  <<<===
EventLoopMgr         INFO   ===>>>  done processing event #5253, run #300000 on slot 2,  4901 events processed so far  <<<===
EventLoopMgr         INFO ---> Loop Finished (seconds): 1.57284
ApplicationMgr            INFO Application Manager Stopped successfullyESC[m
AvalancheSchedulerSvc     INFO Joining Scheduler threadESC[m
AvalancheSchedulerSvc     INFO Terminating thread-pool resourcesESC[m
ToolSvc                   INFO Removing all tools created by ToolSvcESC[m
ApplicationMgr            INFO Application Manager Finalized successfullyESC[m
ApplicationMgr            INFO Application Manager Terminated successfullyESC[m
xAOD::TFileAccessTracer   INFO    Sending file access statistics to http://rucio-lb-prod.cern.ch:18762/traces/

I.e. a reduction from ~90 seconds to ~2...

Merge request reports