Do not run both event and output timers at the same time

When doing event iteration, we sometimes emit to the result-file. When
doing so, we should not include this time in the time it takes to
perform event iteration.

Fixes https://trac.openmodelica.org/OpenModelica/ticket/5381

Belonging to [master]:
  - #2993

Author: sjoelund

SimulationRuntime/c/simulation/solver/perform_simulation.c

@@ -110,8 +110,11 @@ static int simulationUpdate(DATA* data, threadData_t *threadData, SOLVER_INFO* s
       threadData->currentErrorStage = ERROR_EVENTHANDLING;
       infoStreamPrint(LOG_EVENTS, 1, "%s event at time=%.12g", eventType == 1 ? "time" : "state", solverInfo->currentTime);
       /* prevent emit if noEventEmit flag is used */
-      if (!(omc_flag[FLAG_NOEVENTEMIT])) /* output left limit */
+      if (!(omc_flag[FLAG_NOEVENTEMIT])) /* output left limit */ {
+        rt_accumulate(SIM_TIMER_EVENT);
         sim_result.emit(&sim_result, data, threadData);
+        rt_tick(SIM_TIMER_EVENT);
+      }
       handleEvents(data, threadData, solverInfo->eventLst, &(solverInfo->currentTime), solverInfo);
       cleanUpOldValueListAfterEvent(data, solverInfo->currentTime);
       messageClose(LOG_EVENTS);
@@ -125,7 +128,7 @@ static int simulationUpdate(DATA* data, threadData_t *threadData, SOLVER_INFO* s
       solverInfo->didEventStep = 0;
     }
 
-    if (measure_time_flag) rt_accumulate(SIM_TIMER_EVENT);
+    if (measure_time_flag) { rt_accumulate(SIM_TIMER_EVENT); rt_tick(SIM_TIMER_EVENT); }
     /***** End event handling *****/
 
 
@@ -208,8 +211,8 @@ static void fmtEmitStep(DATA* data, threadData_t *threadData, MEASURE_TIME* mt,
     double tmpdbl;
     unsigned int tmpint;
     int total = data->modelData->modelDataXml.nFunctions + data->modelData->modelDataXml.nProfileBlocks;
-    rt_tick(SIM_TIMER_OVERHEAD);
     rt_accumulate(SIM_TIMER_STEP);
+    rt_tick(SIM_TIMER_OVERHEAD);
 
     /* Disable time measurements if we have trouble writing to the file... */
     flag = flag && 1 == fwrite(&mt->stepNo, sizeof(unsigned int), 1, mt->fmtInt);

SimulationRuntime/c/simulation/solver/solver_main.c

@@ -512,6 +512,7 @@ int finishSimulation(DATA* data, threadData_t *threadData, SOLVER_INFO* solverIn
 
   int retValue = 0;
   int ui;
+  double t;
 
   SIMULATION_INFO *simInfo = data->simulationInfo;
 
@@ -555,10 +556,8 @@ int finishSimulation(DATA* data, threadData_t *threadData, SOLVER_INFO* solverIn
     infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] event-handling", rt_accumulated(SIM_TIMER_EVENT), rt_accumulated(SIM_TIMER_EVENT)/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
     infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] overhead", rt_accumulated(SIM_TIMER_OVERHEAD), rt_accumulated(SIM_TIMER_OVERHEAD)/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
 
-    if(S_OPTIMIZATION != solverInfo->solverMethod)
-      infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] simulation", rt_accumulated(SIM_TIMER_TOTAL)-rt_accumulated(SIM_TIMER_OVERHEAD)-rt_accumulated(SIM_TIMER_EVENT)-rt_accumulated(SIM_TIMER_OUTPUT)-rt_accumulated(SIM_TIMER_STEP)-rt_accumulated(SIM_TIMER_INIT)-rt_accumulated(SIM_TIMER_PREINIT), (rt_accumulated(SIM_TIMER_TOTAL)-rt_accumulated(SIM_TIMER_OVERHEAD)-rt_accumulated(SIM_TIMER_EVENT)-rt_accumulated(SIM_TIMER_OUTPUT)-rt_accumulated(SIM_TIMER_STEP)-rt_accumulated(SIM_TIMER_INIT)-rt_accumulated(SIM_TIMER_PREINIT))/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
-    else
-      infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] optimization", rt_accumulated(SIM_TIMER_TOTAL)-rt_accumulated(SIM_TIMER_OVERHEAD)-rt_accumulated(SIM_TIMER_EVENT)-rt_accumulated(SIM_TIMER_OUTPUT)-rt_accumulated(SIM_TIMER_STEP)-rt_accumulated(SIM_TIMER_INIT)-rt_accumulated(SIM_TIMER_PREINIT), (rt_accumulated(SIM_TIMER_TOTAL)-rt_accumulated(SIM_TIMER_OVERHEAD)-rt_accumulated(SIM_TIMER_EVENT)-rt_accumulated(SIM_TIMER_OUTPUT)-rt_accumulated(SIM_TIMER_STEP)-rt_accumulated(SIM_TIMER_INIT)-rt_accumulated(SIM_TIMER_PREINIT))/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
+    t = rt_accumulated(SIM_TIMER_TOTAL)-rt_accumulated(SIM_TIMER_OVERHEAD)-rt_accumulated(SIM_TIMER_EVENT)-rt_accumulated(SIM_TIMER_OUTPUT)-rt_accumulated(SIM_TIMER_STEP)-rt_accumulated(SIM_TIMER_INIT)-rt_accumulated(SIM_TIMER_PREINIT);
+    infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] %s", t, t/rt_accumulated(SIM_TIMER_TOTAL)*100.0, S_OPTIMIZATION == solverInfo->solverMethod ? "optimization" : "simulation");
 
     infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] total", rt_accumulated(SIM_TIMER_TOTAL), rt_accumulated(SIM_TIMER_TOTAL)/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
     messageClose(LOG_STATS);