Fixing duration calculation in result events

CHANGELOG.md

@@ -35,6 +35,7 @@ and this project adheres to [Semantic Versioning](https://semver.org/spec/v2.0.0
 - Removed version number "2.0" from the logo printed to console [#642](https://github.com/ie3-institute/simona/issues/642)
 - Fixed PV Model documentation [#684](https://github.com/ie3-institute/simona/issues/684), [#686](https://github.com/ie3-institute/simona/issues/686)
 - Removed `CsvDataSourceAdapter` workaround [#702](https://github.com/ie3-institute/simona/issues/702)
+- Logging wrong duration in the first simulation hour [#705](https://github.com/ie3-institute/simona/issues/705)
 
 ## [3.0.0] - 2023-08-07
 

src/main/scala/edu/ie3/simona/scheduler/RuntimeNotifier.scala

@@ -9,7 +9,7 @@ package edu.ie3.simona.scheduler
 import org.apache.pekko.actor.typed.ActorRef
 import edu.ie3.simona.event.RuntimeEvent
 import edu.ie3.simona.event.RuntimeEvent._
-import edu.ie3.simona.scheduler.RuntimeNotifier.now
+import edu.ie3.simona.scheduler.RuntimeNotifier._
 import edu.ie3.simona.util.SimonaConstants.INIT_SIM_TICK
 
 /** Determines runtime events at different stages of the simulation and notifies
@@ -28,15 +28,15 @@ import edu.ie3.simona.util.SimonaConstants.INIT_SIM_TICK
   *   Time in milliseconds when the simulation was last started (before
   *   initialization or after a pause)
   * @param lastCheckWindowTime
-  *   Time when in milliseconds when
+  *   Time in milliseconds when the last check window was passed
   */
 final case class RuntimeNotifier(
-    eventListener: ActorRef[RuntimeEvent],
-    readyCheckWindow: Option[Int],
-    lastCheck: Long = -1,
-    simStartTime: Long = -1,
-    lastStartTime: Long = -1,
-    lastCheckWindowTime: Long = -1
+    private val eventListener: ActorRef[RuntimeEvent],
+    private val readyCheckWindow: Option[Int],
+    private val lastCheck: Option[Long] = None,
+    private val simStartTime: Option[Long] = None,
+    private val lastStartTime: Option[Long] = None,
+    private val lastCheckWindowTime: Option[Long] = None
 ) {
 
   /** Notifier listeners that simulation has started or continued with given
@@ -65,10 +65,15 @@ final case class RuntimeNotifier(
         Simulating(tick, pauseOrEndTick)
     })
 
-    if (tick > 0L)
-      copy(lastStartTime = nowTime)
+    if (simStartTime.nonEmpty)
+      // Has been started before: resuming simulation
+      copy(lastStartTime = Some(nowTime), lastCheckWindowTime = Some(nowTime))
     else
-      copy(simStartTime = nowTime, lastStartTime = nowTime)
+      copy(
+        simStartTime = Some(nowTime),
+        lastStartTime = Some(nowTime),
+        lastCheckWindowTime = Some(nowTime)
+      )
   }
 
   /** Notifier listeners that simulation is pausing at given tick
@@ -78,7 +83,7 @@ final case class RuntimeNotifier(
     *   Updated notifier
     */
   def pausing(pauseTick: Long): RuntimeNotifier = {
-    notify(Ready(pauseTick, now() - simStartTime))
+    notify(Ready(pauseTick, duration(simStartTime)))
 
     this
   }
@@ -94,35 +99,33 @@ final case class RuntimeNotifier(
   def completing(completedTick: Long): RuntimeNotifier = {
     val nowTime = now()
 
-    // check if InitComplete should be sent, then adjust lastCheck
-    val adjustedLastCheck = if (lastCheck <= -1) {
-      if (completedTick >= INIT_SIM_TICK)
-        notify(InitComplete(nowTime - simStartTime))
-      0
-    } else
-      lastCheck
+    // first tick (usually INIT_SIM_TICK) has completed
+    if (lastCheck.isEmpty)
+      notify(InitComplete(duration(simStartTime)))
+
+    // start with 0 if this is the first completed tick
+    val adjustedLastCheck = lastCheck.getOrElse(0L)
 
     readyCheckWindow
       .flatMap { checkWindow =>
         val completedWindows =
           (adjustedLastCheck + checkWindow) to completedTick by checkWindow
 
+        completedWindows.foreach { tick =>
+          notify(CheckWindowPassed(tick, duration(lastStartTime, nowTime)))
+        }
+
         completedWindows.lastOption
           .map { lastPassedCheck =>
-            // at least one window has been passed
-            completedWindows.foreach { tick =>
-              notify(CheckWindowPassed(tick, nowTime - lastCheckWindowTime))
-            }
-
             copy(
-              lastCheck = lastPassedCheck,
-              lastCheckWindowTime = nowTime
+              lastCheck = Some(lastPassedCheck),
+              lastCheckWindowTime = Some(nowTime)
             )
           }
       }
       .getOrElse {
         // no check window set or no windows passed
-        copy(lastCheck = adjustedLastCheck)
+        copy(lastCheck = Some(adjustedLastCheck))
       }
   }
 
@@ -135,7 +138,7 @@ final case class RuntimeNotifier(
     notify(
       Done(
         endTick,
-        simStartTime - now(),
+        duration(simStartTime),
         errorInSim = false
       )
     )
@@ -156,7 +159,7 @@ final case class RuntimeNotifier(
     notify(
       Done(
         endTick,
-        simStartTime - now(),
+        duration(simStartTime),
         errorInSim = true
       )
     )
@@ -169,6 +172,23 @@ final case class RuntimeNotifier(
 
 object RuntimeNotifier {
 
+  /** Returns the duration from given interval start to end, with a fallback
+    * duration of 0 if the start is not (yet) set (which can happen in edge
+    * cases, e.g. simulation failed and aborts)
+    *
+    * @param intervalStart
+    *   Optional start of the interval
+    * @param intervalEnd
+    *   The end of the interval
+    * @return
+    *   The duration in milliseconds
+    */
+  private def duration(
+      intervalStart: Option[Long],
+      intervalEnd: Long = now()
+  ): Long =
+    intervalStart.map(intervalEnd - _).getOrElse(0)
+
   /** @return
     *   Current time in milliseconds
     */