Add more timers for solvers

- dassl, ida, euler, rungekutta (default) now have a timer for
  the solver itself to separate generated and solver code slightly.
- Added timer for functionDAE

Belonging to [master]:
  - #3007

Author: sjoelund

Compiler/Template/CodegenC.tpl

@@ -4104,8 +4104,16 @@ template evaluateDAEResiduals(list<list<SimEqSystem>> resEquations, String model
     int evalStages;
     data->simulationInfo->callStatistics.functionEvalDAE++;
 
+  #if !defined(OMC_MINIMAL_RUNTIME)
+    <% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_tick(SIM_TIMER_DAE);
+  #endif
+
     <%eqCalls%>
 
+  #if !defined(OMC_MINIMAL_RUNTIME)
+    <% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_accumulate(SIM_TIMER_DAE);
+  #endif
+
     TRACE_POP
     return 0;
   }
@@ -4229,6 +4237,9 @@ template functionDAE(list<SimEqSystem> allEquationsPlusWhen, String modelNamePre
     TRACE_PUSH
     int equationIndexes[1] = {0};<%/*reinits may use equation indexes, even though it has no equation...*/%>
     <%addRootsTempArray()%>
+  #if !defined(OMC_MINIMAL_RUNTIME)
+    <% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_tick(SIM_TIMER_DAE);
+  #endif !defined(OMC_MINIMAL_RUNTIME)
 
     data->simulationInfo->needToIterate = 0;
     data->simulationInfo->discreteCall = 1;
@@ -4237,6 +4248,9 @@ template functionDAE(list<SimEqSystem> allEquationsPlusWhen, String modelNamePre
     else fncalls %>
     data->simulationInfo->discreteCall = 0;
 
+  #if !defined(OMC_MINIMAL_RUNTIME)
+    <% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_accumulate(SIM_TIMER_DAE);
+  #endif !defined(OMC_MINIMAL_RUNTIME)
     TRACE_POP
     return 0;
   }

SimulationRuntime/c/simulation/solver/dassl.c

@@ -486,6 +486,8 @@ int dassl_step(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo)
 
   MODEL_DATA *mData = (MODEL_DATA*) data->modelData;
 
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
+
   memcpy(stateDer, data->localData[1]->realVars + data->modelData->nStates, sizeof(double)*data->modelData->nStates);
 
   dasslData->rpar[0] = (double*) (void*) data;
@@ -557,9 +559,11 @@ int dassl_step(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo)
     /* rhs final flag is FALSE during for dassl evaluation */
     RHSFinalFlag = 0;
 
+    if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
     /* read input vars */
     externalInputUpdate(data);
     data->callback->input_function(data, threadData);
+    if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
     DDASKR(dasslData->residualFunction, (int*) &dasslData->N,
             &solverInfo->currentTime, states, stateDer, &tout,
@@ -664,6 +668,7 @@ int dassl_step(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo)
   }
 
   infoStreamPrint(LOG_DASSL, 0, "Finished DASSL step.");
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
 
   TRACE_POP
   return retVal;
@@ -747,6 +752,7 @@ int functionODE_residual(double *t, double *y, double *yd, double* cj, double *d
   int saveJumpState;
   int success = 0;
 
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
   if (measure_time_flag) rt_tick(SIM_TIMER_RESIDUALS);
 
   if (data->simulationInfo->currentContext == CONTEXT_ALGEBRAIC)
@@ -799,6 +805,7 @@ int functionODE_residual(double *t, double *y, double *yd, double* cj, double *d
   }
 
   if (measure_time_flag) rt_accumulate(SIM_TIMER_RESIDUALS);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
   TRACE_POP
   return 0;
@@ -815,6 +822,7 @@ int function_ZeroCrossingsDASSL(int *neqm, double *t, double *y, double *yp,
   double timeBackup;
   int saveJumpState;
 
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
   if (measure_time_flag) rt_tick(SIM_TIMER_EVENT);
 
   if (data->simulationInfo->currentContext == CONTEXT_ALGEBRAIC)
@@ -844,6 +852,7 @@ int function_ZeroCrossingsDASSL(int *neqm, double *t, double *y, double *yp,
   }
 
   if (measure_time_flag) rt_accumulate(SIM_TIMER_EVENT);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
   TRACE_POP
   return 0;
@@ -1091,6 +1100,7 @@ static int callJacobian(double *t, double *y, double *yprime, double *deltaD, do
   threadData_t *threadData = (threadData_t*)(void*)((double**)rpar)[2];
 
   /* profiling */
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
   rt_tick(SIM_TIMER_JACOBIAN);
 
   if(dasslData->jacobianFunction(t, y, yprime, deltaD, pd, cj, h, wt, rpar, ipar))
@@ -1100,9 +1110,6 @@ static int callJacobian(double *t, double *y, double *yprime, double *deltaD, do
     return 1;
   }
 
-  /* profiling */
-  rt_accumulate(SIM_TIMER_JACOBIAN);
-
   /* debug */
   if (ACTIVE_STREAM(LOG_JAC)){
     _omc_matrix* dumpJac = _omc_createMatrix(dasslData->N, dasslData->N, pd);
@@ -1119,6 +1126,10 @@ static int callJacobian(double *t, double *y, double *yprime, double *deltaD, do
   /* set context for the start values extrapolation of non-linear algebraic loops */
   unsetContext(data);
 
+  /* profiling */
+  rt_accumulate(SIM_TIMER_JACOBIAN);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
+
   TRACE_POP
   return 0;
 }

SimulationRuntime/c/simulation/solver/ida_solver.c

@@ -162,6 +162,7 @@ ida_solver_initial(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo
   idaData->residualFunction = residualFunctionIDA;
   idaData->N = (long int)data->modelData->nStates;
 
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
   /* change parameter for DAE mode */
   if (compiledInDAEMode)
@@ -660,6 +661,8 @@ ida_solver_initial(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo
   }
   messageClose(LOG_SOLVER);
 
+  if (measure_time_flag) rt_clear(SIM_TIMER_SOLVER); /* Initialization should not add this timer... */
+
   free(tmp);
   TRACE_POP
   return 0;
@@ -719,8 +722,10 @@ ida_event_update(DATA* data, threadData_t *threadData)
       memcpy(idaData->statesDer, data->localData[0]->realVars + data->modelData->nStates, sizeof(double)*data->modelData->nStates);
 
       /* update inner algebraic get new values from data */
+      if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
       evaluateDAEResiduals_wrapperEventUpdate(data, threadData);
       getAlgebraicDAEVars(data, idaData->states + data->modelData->nStates);
+      if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
       infoStreamPrint(LOG_SOLVER, 0, "##IDA## do event update at %.15g", data->localData[0]->timeValue);
       flag = IDAReInit(idaData->ida_mem,
@@ -763,19 +768,23 @@ ida_event_update(DATA* data, threadData_t *threadData)
       IDAGetConsistentIC(idaData->ida_mem, idaData->y, idaData->yp);
 
       /* update inner algebraic variables */
+      if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
       evaluateDAEResiduals_wrapperEventUpdate(data, threadData);
 
       memcpy(data->localData[0]->realVars, idaData->states, sizeof(double)*data->modelData->nStates);
       // and  also algebraic vars
       setAlgebraicDAEVars(data, idaData->states + data->modelData->nStates);
       memcpy(data->localData[0]->realVars + data->modelData->nStates, idaData->statesDer, sizeof(double)*data->modelData->nStates);
+      if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
       /* reset initial step size again to default */
       IDASetInitStep(idaData->ida_mem, 0.0);
     }
   }
   else{
+    if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
     data->callback->functionDAE(data, threadData);
+    if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
   }
 }
 
@@ -793,6 +802,8 @@ ida_solver_step(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo)
   int stepsMode;
   int restartAfterLSFail = 0;
 
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
+
   IDA_SOLVER *idaData = (IDA_SOLVER*) solverInfo->solverData;
 
   SIMULATION_DATA *sData = data->localData[0];
@@ -895,6 +906,7 @@ ida_solver_step(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo)
       NV_Ith_S(idaData->y, i) = NV_Ith_S(idaData->y, i) + NV_Ith_S(idaData->yp, i) * solverInfo->currentStepSize;
     }
     sData->timeValue = solverInfo->currentTime + solverInfo->currentStepSize;
+    if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
     data->callback->functionODE(data, threadData);
     solverInfo->currentTime = sData->timeValue;
 
@@ -932,9 +944,11 @@ ida_solver_step(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo)
   {
     infoStreamPrint(LOG_SOLVER, 1, "##IDA## new step from %.15g to %.15g", solverInfo->currentTime, tout);
 
+    if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
     /* read input vars */
     externalInputUpdate(data);
     data->callback->input_function(data, threadData);
+    if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
     if (omc_flag[FLAG_IDA_SCALING])
     {
@@ -1123,6 +1137,7 @@ ida_solver_step(DATA* data, threadData_t *threadData, SOLVER_INFO* solverInfo)
   }
 
   infoStreamPrint(LOG_SOLVER, 0, "##IDA## Finished Integrator step.");
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
 
   TRACE_POP
   return retVal;
@@ -1191,13 +1206,17 @@ int residualFunctionIDA(double time, N_Vector yy, N_Vector yp, N_Vector res, voi
   }
 
   /* read input vars */
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
   externalInputUpdate(data);
   data->callback->input_function(data, threadData);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
   if (idaData->daeMode)
   {
     /* eval residual vars */
+    if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
     data->simulationInfo->daeModeData->evaluateDAEResiduals(data, threadData, EVAL_DYNAMIC);
+    if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
     /* get residual variables */
     for(i=0; i < idaData->N; i++)
     {
@@ -1208,7 +1227,9 @@ int residualFunctionIDA(double time, N_Vector yy, N_Vector yp, N_Vector res, voi
   else
   {
     /* eval function ODE */
+    if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
     data->callback->functionODE(data, threadData);
+    if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
     for(i=0; i < idaData->N; i++)
     {
       NV_Ith_S(res, i) = data->localData[0]->realVars[data->modelData->nStates + i] - NV_Ith_S(yp, i);
@@ -1241,6 +1262,7 @@ int residualFunctionIDA(double time, N_Vector yy, N_Vector yp, N_Vector res, voi
     unsetContext(data);
   }
   messageClose(LOG_SOLVER_V);
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
 
   TRACE_POP
   return retVal;
@@ -1283,6 +1305,7 @@ int rootsFunctionIDA(double time, N_Vector yy, N_Vector yp, double *gout, void*
   data->localData[0]->timeValue = time;
 
   /* read input vars */
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
   externalInputUpdate(data);
   data->callback->input_function(data, threadData);
   /* eval needed equations*/
@@ -1295,6 +1318,7 @@ int rootsFunctionIDA(double time, N_Vector yy, N_Vector yp, double *gout, void*
   }
 
   data->callback->function_ZeroCrossings(data, threadData, gout);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
   threadData->currentErrorStage = saveJumpState;
 
@@ -1308,6 +1332,7 @@ int rootsFunctionIDA(double time, N_Vector yy, N_Vector yp, double *gout, void*
     unsetContext(data);
   }
   messageClose(LOG_SOLVER_V);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
 
   TRACE_POP
   return 0;
@@ -1493,6 +1518,7 @@ static int callDenseJacobian(long int Neq, double tt, double cj,
   int retVal;
 
   /* profiling */
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
   rt_tick(SIM_TIMER_JACOBIAN);
 
   if (idaData->jacobianMethod == COLOREDNUMJAC || idaData->jacobianMethod == NUMJAC)
@@ -1508,9 +1534,6 @@ static int callDenseJacobian(long int Neq, double tt, double cj,
     throwStreamPrint(threadData, "##IDA## Something goes wrong while obtain jacobian matrix!");
   }
 
-  /* profiling */
-  rt_accumulate(SIM_TIMER_JACOBIAN);
-
   /* debug */
   if (ACTIVE_STREAM(LOG_JAC)){
     _omc_matrix* dumpJac = _omc_createMatrix(idaData->N, idaData->N, Jac->data);
@@ -1528,6 +1551,10 @@ static int callDenseJacobian(long int Neq, double tt, double cj,
     }
   }
 
+  /* profiling */
+  rt_accumulate(SIM_TIMER_JACOBIAN);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
+
   TRACE_POP
   return retVal;
 }
@@ -1775,6 +1802,7 @@ static int callSparseJacobian(double tt, double cj,
   threadData_t* threadData = (threadData_t*)(((IDA_USERDATA*)((IDA_SOLVER*)user_data)->simData)->threadData);
 
   /* profiling */
+  if (measure_time_flag) rt_accumulate(SIM_TIMER_SOLVER);
   rt_tick(SIM_TIMER_JACOBIAN);
 
   if (idaData->jacobianMethod == COLOREDSYMJAC || idaData->jacobianMethod == SYMJAC)
@@ -1786,9 +1814,6 @@ static int callSparseJacobian(double tt, double cj,
     retVal = jacoColoredNumericalSparse(tt, yy, yp, rr, Jac, cj, user_data);
   }
 
-  /* profiling */
-  rt_accumulate(SIM_TIMER_JACOBIAN);
-
   /* debug */
   if (ACTIVE_STREAM(LOG_JAC)){
     infoStreamPrint(LOG_JAC, 0, "##IDA## Sparse Matrix A.");
@@ -1808,6 +1833,10 @@ static int callSparseJacobian(double tt, double cj,
     SlsAddMat(Jac, idaData->tmpJac);
   }
 
+  /* profiling */
+  rt_accumulate(SIM_TIMER_JACOBIAN);
+  if (measure_time_flag) rt_tick(SIM_TIMER_SOLVER);
+
   TRACE_POP
   return retVal;
 }