Kassiopeia: Add processing duration as output fields

To understand which steps and tracks take long to calculate, this commit adds
new output fields `processing_duration` to Tracks, Steps, Events and Runs.

This replaces the old processing time calculation of KSRuns used to print
the estimated remaining time into the log since that can re-use the
newly added timings. However this excludes a minor bit of clean-up code
after the run processing from the respective timing.

Documentation/gh-pages/source/kassiopeia_output.rst

@@ -143,8 +143,8 @@ output is written after the completion of each step. Similary, at the track leve
 to the initial and final parameters of a track, i.e. the state at particle generation and termination.
 
 The standard output fields for the particle are defined at the end of the file
-:gh-code:`Kassiopeia/Operators/Source/KSParticle.cxx` while the step and track output fields can be found in
-:gh-code:`Kassiopeia/Operators/Source/KSStep.cxx` and :gh-code:`Kassiopeia/Operators/Source/KSTrack.cxx`, respectively.
+:gh-code:`Kassiopeia/Simulation/Source/KSParticle.cxx` while the step and track output fields can be found in
+:gh-code:`Kassiopeia/Simulation/Source/KSStep.cxx` and :gh-code:`Kassiopeia/Simulation/Source/KSTrack.cxx`, respectively.
 Other specialized output fields are also available for some propagation or interaction terms.
 
 Output fields
@@ -296,6 +296,8 @@ overview of the different fields and their types.
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 | Number of Turns    | ``number_of_turns``                 | ``unsigned int`` | ``KSRun``                  | Number of particle turns/reflections during run          |
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
+| Processing Duration| ``processing_duration``             | ``double``       | ``KSRun``                  | Computing time used for run                              |
++--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 | Event ID           | ``event_id``                        | ``int``          | ``KSEvent``                | Event ID of current event                                |
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 | Event Count        | ``event_count``                     | ``int``          | ``KSEvent``                | Total number of events                                   |
@@ -338,6 +340,8 @@ overview of the different fields and their types.
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 | Generator Radius   | ``generator_radius``                | ``double``       | ``KSEvent``                | Maximum radius of the generated particles (in m)         |
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
+| Processing Duration| ``processing_duration``             | ``double``       | ``KSEvent``                | Computing time used for event                            |
++--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 | Track ID           | ``event_id``                        | ``int``          | ``KSTrack``                | Track ID of current track                                |
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 | Track Count        | ``event_count``                     | ``int``          | ``KSTrack``                | Total number of tracks                                   |
@@ -440,6 +444,8 @@ overview of the different fields and their types.
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 | Intermed. Particle | ``trajectory_particle``             | ``KSParticle``   | ``KSStep``                 | Pointer to initial particle before propagation           |
 +--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
+| Processing Duration| ``processing_duration``             | ``double``       | ``KSStep``                 | Computing time used for step                             |
++--------------------+-------------------------------------+------------------+----------------------------+----------------------------------------------------------+
 
 Vector and matrix type can be accessed by their components in the written output data. For example, when the ``position``
 element is used, the corresponding fields in the output data can be found under the names ``position_x``, ``position_y``,

Kassiopeia/Simulation/CMakeLists.txt

@@ -26,6 +26,7 @@ set( SIMULATION_HEADER_BASENAMES
     KSRootTerminator.h
     KSRootWriter.h
     KSRoot.h
+    KSTimed.h
 )
 set( SIMULATION_HEADER_PATH
     ${CMAKE_CURRENT_SOURCE_DIR}/Include
@@ -62,6 +63,7 @@ set( SIMULATION_SOURCE_BASENAMES
     KSRootTerminator.cxx
     KSRootWriter.cxx
     KSRoot.cxx
+    KSTimed.cxx
 )
 set( SIMULATION_SOURCE_PATH
     ${CMAKE_CURRENT_SOURCE_DIR}/Source

Kassiopeia/Simulation/Include/KSEvent.h

@@ -4,12 +4,13 @@
 #include "KField.h"
 #include "KSComponentTemplate.h"
 #include "KSParticle.h"
+#include "KSTimed.h"
 
 namespace Kassiopeia
 {
 class KSRun;
 
-class KSEvent : public KSComponentTemplate<KSEvent>
+class KSEvent : public KSComponentTemplate<KSEvent>, public KSTimed
 {
   public:
     KSEvent();

Kassiopeia/Simulation/Include/KSRun.h

@@ -3,11 +3,12 @@
 
 #include "KField.h"
 #include "KSComponentTemplate.h"
+#include "KSTimed.h"
 
 namespace Kassiopeia
 {
 
-class KSRun : public KSComponentTemplate<KSRun>
+class KSRun : public KSComponentTemplate<KSRun>, public KSTimed
 {
   public:
     KSRun();

Kassiopeia/Simulation/Include/KSStep.h

@@ -4,13 +4,14 @@
 #include "KField.h"
 #include "KSComponentTemplate.h"
 #include "KSParticle.h"
+#include "KSTimed.h"
 
 namespace Kassiopeia
 {
 
 class KSTrack;
 
-class KSStep : public KSComponentTemplate<KSStep>
+class KSStep : public KSComponentTemplate<KSStep>, public KSTimed
 {
   public:
     KSStep();
@@ -122,6 +123,7 @@ class KSStep : public KSComponentTemplate<KSStep>
 
   public:
     K_REFS(KSParticleQueue, ParticleQueue)
+
 };
 
 }  // namespace Kassiopeia

Kassiopeia/Simulation/Include/KSTimed.h

@@ -0,0 +1,23 @@
+#ifndef Kassiopeia_KSTimed_h_
+#define Kassiopeia_KSTimed_h_
+
+#include <chrono>
+
+namespace Kassiopeia
+{
+
+class KSTimed {
+  private:
+    std::chrono::steady_clock::time_point fTimeStart;
+    double fProcessingDuration = -1;
+
+  public:
+    void StartTiming();
+    void EndTiming();
+
+    const double& GetProcessingDuration() const {return fProcessingDuration;};
+};
+
+}
+
+#endif

Kassiopeia/Simulation/Include/KSTrack.h

@@ -4,12 +4,13 @@
 #include "KField.h"
 #include "KSComponentTemplate.h"
 #include "KSParticle.h"
+#include "KSTimed.h"
 
 namespace Kassiopeia
 {
 class KSEvent;
 
-class KSTrack : public KSComponentTemplate<KSTrack>
+class KSTrack : public KSComponentTemplate<KSTrack>, public KSTimed
 {
   public:
     KSTrack();

Kassiopeia/Simulation/Source/KSEvent.cxx

@@ -29,6 +29,7 @@ KSEvent::KSEvent() :
 {}
 KSEvent::KSEvent(const KSEvent& aCopy) :
     KSComponent(aCopy),
+    KSTimed(aCopy),
     fEventId(aCopy.fEventId),
     fEventCount(aCopy.fEventCount),
     fParentRunId(aCopy.fParentRunId),
@@ -54,6 +55,7 @@ KSEvent::KSEvent(const KSEvent& aCopy) :
 {}
 KSEvent& KSEvent::operator=(const KSEvent& aCopy)
 {
+    KSTimed::operator=(aCopy);
     fEventId = aCopy.fEventId;
     fEventCount = aCopy.fEventCount;
     fParentRunId = aCopy.fParentRunId;
@@ -105,6 +107,7 @@ STATICINT sKSEventDict =
     KSDictionary<KSEvent>::AddComponent(&KSEvent::GetGeneratorMinTime, "generator_min_time") +
     KSDictionary<KSEvent>::AddComponent(&KSEvent::GetGeneratorMaxTime, "generator_max_time") +
     KSDictionary<KSEvent>::AddComponent(&KSEvent::GetGeneratorLocation, "generator_location") +
-    KSDictionary<KSEvent>::AddComponent(&KSEvent::GetGeneratorRadius, "generator_radius");
+    KSDictionary<KSEvent>::AddComponent(&KSEvent::GetGeneratorRadius, "generator_radius") + 
+    KSDictionary<KSEvent>::AddComponent(&KSEvent::GetProcessingDuration, "processing_duration");
 
 }  // namespace Kassiopeia

Kassiopeia/Simulation/Source/KSRoot.cxx

@@ -418,6 +418,8 @@ void KSRoot::ExecuteRun()
     //clear any previous GSL errors
     KGslErrorHandler::GetInstance().ClearError();
 
+    fRun->StartTiming();
+
     // send report
     runmsg(eNormal) << "processing run " << fRun->GetRunId() << " ..." << eom;
 
@@ -468,6 +470,8 @@ void KSRoot::ExecuteRun()
         fRootRunModifier->ExecutePostRunModification();
     }
 
+    fRun->EndTiming();
+
     // write run
     fRun->PushUpdate();
     fRootRunModifier->PushUpdate();
@@ -501,7 +505,7 @@ void KSRoot::ExecuteEvent()
     fEvent->NumberOfTurns() = 0;
     fEventIndex++;
 
-    auto tClockStart = chrono::steady_clock::now();
+    fEvent->StartTiming();
 
     fRootEventModifier->ExecutePreEventModification();
 
@@ -579,6 +583,8 @@ void KSRoot::ExecuteEvent()
 
     fRootEventModifier->ExecutePostEventModification();
 
+    fEvent->EndTiming();
+
     // write event
     fEvent->PushUpdate();
     fRootEventModifier->PushUpdate();
@@ -589,8 +595,7 @@ void KSRoot::ExecuteEvent()
     fRootEventModifier->PushDeupdate();
 
     // determine time spent for event processing
-    auto tClockEnd = chrono::steady_clock::now();
-    auto tTimeSpan = chrono::duration_cast<chrono::duration<double>>(tClockEnd - tClockStart).count();
+    auto tTimeSpan = fEvent->GetProcessingDuration();
 
     fTotalExecTime += tTimeSpan;
 
@@ -623,6 +628,8 @@ void KSRoot::ExecuteTrack()
     fTrack->DiscreteSecondaries() = 0;
     fTrack->NumberOfTurns() = 0;
 
+    fTrack->StartTiming();
+
     fRootTrackModifier->ExecutePreTrackModification();
 
     // send report
@@ -702,6 +709,8 @@ void KSRoot::ExecuteTrack()
 
     fRootTrackModifier->ExecutePostTrackModification();
 
+    fTrack->EndTiming();
+
 
     // write track
 
@@ -766,6 +775,8 @@ void KSRoot::ExecuteStep()
     fStep->SurfaceNavigationName().clear();
     fStep->SurfaceNavigationFlag() = false;
 
+    fStep->StartTiming();
+
     // run pre-step modification
     bool hasPreModified = fRootStepModifier->ExecutePreStepModification();
     if (hasPreModified) {
@@ -922,6 +933,8 @@ void KSRoot::ExecuteStep()
                             }
                         }
 
+                        fStep->EndTiming();
+
                         // push update
                         fStep->PushUpdate();
                         fRootTrajectory->PushUpdate();
@@ -975,6 +988,8 @@ void KSRoot::ExecuteStep()
                         }
                     }
 
+                    fStep->EndTiming();
+
                     // push update
                     fStep->PushUpdate();
                     fRootSurfaceInteraction->PushUpdate();
@@ -1002,6 +1017,8 @@ void KSRoot::ExecuteStep()
 
             fStep->FinalParticle().SetActive(false);
 
+            fStep->EndTiming();
+
             // push update
             fStep->PushUpdate();
             fRootSurfaceInteraction->PushUpdate();

Kassiopeia/Simulation/Source/KSRun.cxx

@@ -22,6 +22,7 @@ KSRun::KSRun() :
 {}
 KSRun::KSRun(const KSRun& aCopy) :
     KSComponent(aCopy),
+    KSTimed(aCopy),
     fRunId(aCopy.fRunId),
     fRunCount(aCopy.fRunCount),
     fTotalEvents(aCopy.fTotalEvents),
@@ -38,6 +39,7 @@ KSRun::KSRun(const KSRun& aCopy) :
 {}
 KSRun& KSRun::operator=(const KSRun& aCopy)
 {
+    KSTimed::operator=(aCopy);
     fRunId = aCopy.fRunId;
     fRunCount = aCopy.fRunCount;
     fTotalEvents = aCopy.fTotalEvents;
@@ -72,7 +74,6 @@ STATICINT sKSRunDict =
     KSDictionary<KSRun>::AddComponent(&KSRun::GetDiscreteSecondaries, "discrete_secondaries") +
     KSDictionary<KSRun>::AddComponent(&KSRun::GetDiscreteEnergyChange, "discrete_energy_change") +
     KSDictionary<KSRun>::AddComponent(&KSRun::GetDiscreteMomentumChange, "discrete_momentum_change") +
-    KSDictionary<KSRun>::AddComponent(&KSRun::GetNumberOfTurns, "number_of_turns");
-
-
+    KSDictionary<KSRun>::AddComponent(&KSRun::GetNumberOfTurns, "number_of_turns") + 
+    KSDictionary<KSRun>::AddComponent(&KSRun::GetProcessingDuration, "processing_duration");
 }  // namespace Kassiopeia

Kassiopeia/Simulation/Source/KSStep.cxx

@@ -45,6 +45,7 @@ KSStep::KSStep() :
 {}
 KSStep::KSStep(const KSStep& aCopy) :
     KSComponent(aCopy),
+    KSTimed(aCopy),
     fStepId(aCopy.fStepId),
     fStepCount(aCopy.fStepCount),
     fParentTrackId(aCopy.fParentTrackId),
@@ -84,6 +85,7 @@ KSStep::KSStep(const KSStep& aCopy) :
 {}
 KSStep& KSStep::operator=(const KSStep& aCopy)
 {
+    KSTimed::operator=(aCopy);
     fStepId = aCopy.fStepId;
     fStepCount = aCopy.fStepCount;
     fParentTrackId = aCopy.fParentTrackId;
@@ -163,5 +165,6 @@ STATICINT sKSStepDict =
     KSDictionary<KSStep>::AddComponent(&KSStep::GetTrajectoryParticle, "trajectory_particle") +
     KSDictionary<KSStep>::AddComponent(&KSStep::GetInteractionParticle, "interaction_particle") +
     KSDictionary<KSStep>::AddComponent(&KSStep::GetNavigationParticle, "navigation_particle") +
-    KSDictionary<KSStep>::AddComponent(&KSStep::GetFinalParticle, "final_particle");
+    KSDictionary<KSStep>::AddComponent(&KSStep::GetFinalParticle, "final_particle") + 
+    KSDictionary<KSStep>::AddComponent(&KSStep::GetProcessingDuration, "processing_duration");
 }  // namespace Kassiopeia

Kassiopeia/Simulation/Source/KSTimed.cxx

@@ -0,0 +1,16 @@
+#include "KSTimed.h"
+
+namespace Kassiopeia
+{
+
+void KSTimed::StartTiming() {
+    fTimeStart = std::chrono::steady_clock::now();
+    fProcessingDuration = -1;
+}
+
+void KSTimed::EndTiming() {
+    std::chrono::steady_clock::time_point tTimeEnd = std::chrono::steady_clock::now();
+    fProcessingDuration = std::chrono::duration_cast<std::chrono::duration<double>>(tTimeEnd - fTimeStart).count();
+}
+
+}

Kassiopeia/Simulation/Source/KSTrack.cxx

@@ -26,6 +26,7 @@ KSTrack::KSTrack() :
 {}
 KSTrack::KSTrack(const KSTrack& aCopy) :
     KSComponent(aCopy),
+    KSTimed(aCopy),
     fTrackId(aCopy.fTrackId),
     fTrackCount(aCopy.fTrackCount),
     fParentEventId(aCopy.fParentEventId),
@@ -46,6 +47,7 @@ KSTrack::KSTrack(const KSTrack& aCopy) :
 {}
 KSTrack& KSTrack::operator=(const KSTrack& aCopy)
 {
+    KSTimed::operator=(aCopy);
     fTrackId = aCopy.fTrackId;
     fTrackCount = aCopy.fTrackCount;
     fParentEventId = aCopy.fParentEventId;
@@ -87,6 +89,7 @@ STATICINT sKSTrackDict =
     KSDictionary<KSTrack>::AddComponent(&KSTrack::GetCreatorName, "creator_name") +
     KSDictionary<KSTrack>::AddComponent(&KSTrack::GetTerminatorName, "terminator_name") +
     KSDictionary<KSTrack>::AddComponent(&KSTrack::GetInitialParticle, "initial_particle") +
-    KSDictionary<KSTrack>::AddComponent(&KSTrack::GetFinalParticle, "final_particle");
+    KSDictionary<KSTrack>::AddComponent(&KSTrack::GetFinalParticle, "final_particle") + 
+    KSDictionary<KSTrack>::AddComponent(&KSTrack::GetProcessingDuration, "processing_duration");
 
 }  // namespace Kassiopeia