Skip to content
This repository was archived by the owner on May 18, 2019. It is now read-only.

Commit 417604f

Browse files
sjoelundOpenModelica-Hudson
sjoelund
authored and
OpenModelica-Hudson
committed
Extend LOG_STATS_V with more timers
See https://trac.openmodelica.org/OpenModelica/ticket/5353 Belonging to [master]: - #2997
1 parent 2305d75 commit 417604f

File tree

4 files changed

+72
-19
lines changed

4 files changed

+72
-19
lines changed

‎Compiler/Template/CodegenC.tpl‎

Lines changed: 20 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -4023,7 +4023,9 @@ template functionODE(list<list<SimEqSystem>> derivativEquations, Text method, Op
40234023
int <%symbolName(modelNamePrefix,"functionODE")%>(DATA *data, threadData_t *threadData)
40244024
{
40254025
TRACE_PUSH
4026-
<% if profileFunctions() then "rt_tick(SIM_TIMER_FUNCTION_ODE);" %>
4026+
#if !defined(OMC_MINIMAL_RUNTIME)
4027+
<% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_tick(SIM_TIMER_FUNCTION_ODE);
4028+
#endif !defined(OMC_MINIMAL_RUNTIME)
40274029
40284030
<%varDecls%>
40294031
@@ -4033,7 +4035,9 @@ template functionODE(list<list<SimEqSystem>> derivativEquations, Text method, Op
40334035
<%if Flags.isSet(Flags.PARMODAUTO) then 'PM_functionODE(<%nrfuncs%>, data, threadData, functionODE_systems);'
40344036
else fncalls %>
40354037
4036-
<% if profileFunctions() then "rt_accumulate(SIM_TIMER_FUNCTION_ODE);" %>
4038+
#if !defined(OMC_MINIMAL_RUNTIME)
4039+
<% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_accumulate(SIM_TIMER_FUNCTION_ODE);
4040+
#endif
40374041
40384042
TRACE_POP
40394043
return 0;
@@ -4061,13 +4065,20 @@ template functionAlgebraic(list<list<SimEqSystem>> algebraicEquations, String mo
40614065
TRACE_PUSH
40624066
<%varDecls%>
40634067
4068+
#if !defined(OMC_MINIMAL_RUNTIME)
4069+
<% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_tick(SIM_TIMER_ALGEBRAICS);
4070+
#endif
40644071
data->simulationInfo->callStatistics.functionAlgebraics++;
40654072
40664073
<%if Flags.isSet(Flags.PARMODAUTO) then 'PM_functionAlg(<%nrfuncs%>, data, threadData, functionAlg_systems);'
40674074
else fncalls %>
40684075
40694076
<%symbolName(modelNamePrefix,"function_savePreSynchronous")%>(data, threadData);
40704077
4078+
#if !defined(OMC_MINIMAL_RUNTIME)
4079+
<% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_accumulate(SIM_TIMER_ALGEBRAICS);
4080+
#endif
4081+
40714082
TRACE_POP
40724083
return 0;
40734084
}
@@ -4314,10 +4325,17 @@ template functionZeroCrossing(list<ZeroCrossing> zeroCrossings, list<SimEqSystem
43144325
TRACE_PUSH
43154326
<%varDecls2%>
43164327
4328+
#if !defined(OMC_MINIMAL_RUNTIME)
4329+
<% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_tick(SIM_TIMER_ZC);
4330+
#endif
43174331
data->simulationInfo->callStatistics.functionZeroCrossings++;
43184332
43194333
<%zeroCrossingsCode%>
43204334
4335+
#if !defined(OMC_MINIMAL_RUNTIME)
4336+
<% if profileFunctions() then "" else "if (measure_time_flag) " %>rt_accumulate(SIM_TIMER_ZC);
4337+
#endif
4338+
43214339
TRACE_POP
43224340
return 0;
43234341
}

‎SimulationRuntime/c/simulation/solver/dassl.c‎

Lines changed: 9 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -747,6 +747,8 @@ int functionODE_residual(double *t, double *y, double *yd, double* cj, double *d
747747
int saveJumpState;
748748
int success = 0;
749749

750+
if (measure_time_flag) rt_tick(SIM_TIMER_RESIDUALS);
751+
750752
if (data->simulationInfo->currentContext == CONTEXT_ALGEBRAIC)
751753
{
752754
setContext(data, t, CONTEXT_ODE);
@@ -796,6 +798,8 @@ int functionODE_residual(double *t, double *y, double *yd, double* cj, double *d
796798
unsetContext(data);
797799
}
798800

801+
if (measure_time_flag) rt_accumulate(SIM_TIMER_RESIDUALS);
802+
799803
TRACE_POP
800804
return 0;
801805
}
@@ -811,6 +815,8 @@ int function_ZeroCrossingsDASSL(int *neqm, double *t, double *y, double *yp,
811815
double timeBackup;
812816
int saveJumpState;
813817

818+
if (measure_time_flag) rt_tick(SIM_TIMER_EVENT);
819+
814820
if (data->simulationInfo->currentContext == CONTEXT_ALGEBRAIC)
815821
{
816822
setContext(data, t, CONTEXT_EVENTS);
@@ -837,6 +843,8 @@ int function_ZeroCrossingsDASSL(int *neqm, double *t, double *y, double *yp,
837843
unsetContext(data);
838844
}
839845

846+
if (measure_time_flag) rt_accumulate(SIM_TIMER_EVENT);
847+
840848
TRACE_POP
841849
return 0;
842850
}
@@ -921,7 +929,7 @@ int jacA_sym(double *t, double *y, double *yprime, double *delta, double *matrix
921929
k = 0;
922930
for(i=0; i < jacobian->sizeCols; i++)
923931
{
924-
jacobian->seedVars[i] = 1.0;
932+
jacobian->seedVars[i] = 1.0;
925933

926934
data->callback->functionJacA_column(data, threadData, jacobian, NULL);
927935

‎SimulationRuntime/c/simulation/solver/solver_main.c‎

Lines changed: 37 additions & 13 deletions
Original file line numberDiff line numberDiff line change
@@ -512,7 +512,7 @@ int finishSimulation(DATA* data, threadData_t *threadData, SOLVER_INFO* solverIn
512512

513513
int retValue = 0;
514514
int ui;
515-
double t;
515+
double t, total100;
516516

517517
SIMULATION_INFO *simInfo = data->simulationInfo;
518518

@@ -546,20 +546,22 @@ int finishSimulation(DATA* data, threadData_t *threadData, SOLVER_INFO* solverIn
546546

547547
infoStreamPrint(LOG_STATS, 1, "### STATISTICS ###");
548548

549+
total100 = rt_accumulated(SIM_TIMER_TOTAL)/100.0;
550+
549551
infoStreamPrint(LOG_STATS, 1, "timer");
550552
infoStreamPrint(LOG_STATS, 0, "%12gs reading init.xml", rt_accumulated(SIM_TIMER_INIT_XML));
551553
infoStreamPrint(LOG_STATS, 0, "%12gs reading info.xml", rt_accumulated(SIM_TIMER_INFO_XML));
552-
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] pre-initialization", rt_accumulated(SIM_TIMER_PREINIT), rt_accumulated(SIM_TIMER_PREINIT)/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
553-
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] initialization", rt_accumulated(SIM_TIMER_INIT), rt_accumulated(SIM_TIMER_INIT)/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
554-
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] steps", rt_accumulated(SIM_TIMER_STEP), rt_accumulated(SIM_TIMER_STEP)/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
555-
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] creating output-file", rt_accumulated(SIM_TIMER_OUTPUT), rt_accumulated(SIM_TIMER_OUTPUT)/rt_accumulated(SIM_TIMER_TOTAL)*100.0);
556-
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);
557-
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);
554+
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] pre-initialization", rt_accumulated(SIM_TIMER_PREINIT), rt_accumulated(SIM_TIMER_PREINIT)/total100);
555+
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] initialization", rt_accumulated(SIM_TIMER_INIT), rt_accumulated(SIM_TIMER_INIT)/total100);
556+
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] steps", rt_accumulated(SIM_TIMER_STEP), rt_accumulated(SIM_TIMER_STEP)/total100);
557+
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] creating output-file", rt_accumulated(SIM_TIMER_OUTPUT), rt_accumulated(SIM_TIMER_OUTPUT)/total100);
558+
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] event-handling", rt_accumulated(SIM_TIMER_EVENT), rt_accumulated(SIM_TIMER_EVENT)/total100);
559+
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] overhead", rt_accumulated(SIM_TIMER_OVERHEAD), rt_accumulated(SIM_TIMER_OVERHEAD)/total100);
558560

559561
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);
560-
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] %s", t, t/rt_accumulated(SIM_TIMER_TOTAL)*100.0, S_OPTIMIZATION == solverInfo->solverMethod ? "optimization" : "simulation");
562+
infoStreamPrint(LOG_STATS, 0, "%12gs [%5.1f%%] %s", t, t/total100, S_OPTIMIZATION == solverInfo->solverMethod ? "optimization" : "simulation");
561563

562-
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);
564+
infoStreamPrint(LOG_STATS, 0, "%12gs [100.0%%] total", rt_accumulated(SIM_TIMER_TOTAL));
563565
messageClose(LOG_STATS);
564566

565567
infoStreamPrint(LOG_STATS, 1, "events");
@@ -579,11 +581,13 @@ int finishSimulation(DATA* data, threadData_t *threadData, SOLVER_INFO* solverIn
579581

580582
infoStreamPrint(LOG_STATS, 1, "solver: %s", SOLVER_METHOD_NAME[solverInfo->solverMethod]);
581583
infoStreamPrint(LOG_STATS, 0, "%5d steps taken", solverInfo->solverStats[0]);
584+
582585
infoStreamPrint(LOG_STATS, 0, "%5d calls of functionODE", solverInfo->solverStats[1]);
586+
583587
infoStreamPrint(LOG_STATS, 0, "%5d evaluations of jacobian", solverInfo->solverStats[2]);
588+
584589
infoStreamPrint(LOG_STATS, 0, "%5d error test failures", solverInfo->solverStats[3]);
585590
infoStreamPrint(LOG_STATS, 0, "%5d convergence test failures", solverInfo->solverStats[4]);
586-
infoStreamPrint(LOG_STATS, 0, "%gs time of jacobian evaluation", rt_accumulated(SIM_TIMER_JACOBIAN));
587591
messageClose(LOG_STATS);
588592
}
589593

@@ -594,12 +598,32 @@ int finishSimulation(DATA* data, threadData_t *threadData, SOLVER_INFO* solverIn
594598
}
595599
else
596600
{
597-
infoStreamPrint(LOG_STATS_V, 0, "%5ld calls of functionODE", data->simulationInfo->callStatistics.functionODE);
601+
infoStreamPrint(LOG_STATS_V, 1, "%5ld calls of functionODE", data->simulationInfo->callStatistics.functionODE);
602+
infoStreamPrint(LOG_STATS_V, 0, "%12gs [%5.1f%%]", rt_accumulated(SIM_TIMER_FUNCTION_ODE), rt_accumulated(SIM_TIMER_FUNCTION_ODE)/total100);
603+
messageClose(LOG_STATS_V);
598604
}
599-
infoStreamPrint(LOG_STATS_V, 0, "%5ld calls of functionAlgebraics", data->simulationInfo->callStatistics.functionAlgebraics);
605+
606+
if (rt_ncall(SIM_TIMER_RESIDUALS)) {
607+
infoStreamPrint(LOG_STATS_V, 1, "%5d calls of functionODE_residual", rt_ncall(SIM_TIMER_RESIDUALS));
608+
infoStreamPrint(LOG_STATS_V, 0, "%12gs [%5.1f%%]", rt_accumulated(SIM_TIMER_RESIDUALS), rt_accumulated(SIM_TIMER_RESIDUALS)/total100);
609+
messageClose(LOG_STATS_V);
610+
}
611+
612+
infoStreamPrint(LOG_STATS_V, 1, "%5d calls of functionAlgebraics", data->simulationInfo->callStatistics.functionAlgebraics);
613+
infoStreamPrint(LOG_STATS_V, 0, "%12gs [%5.1f%%]", rt_accumulated(SIM_TIMER_ALGEBRAICS), rt_accumulated(SIM_TIMER_ALGEBRAICS)/total100);
614+
messageClose(LOG_STATS_V);
615+
616+
infoStreamPrint(LOG_STATS_V, 1, "%5d evaluations of jacobian", rt_ncall(SIM_TIMER_JACOBIAN));
617+
infoStreamPrint(LOG_STATS_V, 0, "%12gs [%5.1f%%]", rt_accumulated(SIM_TIMER_JACOBIAN), rt_accumulated(SIM_TIMER_JACOBIAN)/total100);
618+
messageClose(LOG_STATS_V);
619+
600620
infoStreamPrint(LOG_STATS_V, 0, "%5ld calls of updateDiscreteSystem", data->simulationInfo->callStatistics.updateDiscreteSystem);
601621
infoStreamPrint(LOG_STATS_V, 0, "%5ld calls of functionZeroCrossingsEquations", data->simulationInfo->callStatistics.functionZeroCrossingsEquations);
602-
infoStreamPrint(LOG_STATS_V, 0, "%5ld calls of functionZeroCrossings", data->simulationInfo->callStatistics.functionZeroCrossings);
622+
623+
infoStreamPrint(LOG_STATS_V, 1, "%5ld calls of functionZeroCrossings", data->simulationInfo->callStatistics.functionZeroCrossings);
624+
infoStreamPrint(LOG_STATS_V, 0, "%12gs [%5.1f%%]", rt_accumulated(SIM_TIMER_ZC), rt_accumulated(SIM_TIMER_ZC)/total100);
625+
messageClose(LOG_STATS_V);
626+
603627
messageClose(LOG_STATS_V);
604628

605629
infoStreamPrint(LOG_STATS_V, 1, "linear systems");

‎SimulationRuntime/c/util/rtclock.h‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -60,9 +60,12 @@ static inline double rt_tock(int ix) {return 0.0;}
6060
#define SIM_TIMER_PREINIT 6
6161
#define SIM_TIMER_OVERHEAD 7
6262
#define SIM_TIMER_FUNCTION_ODE 8
63-
#define SIM_TIMER_INIT_XML 9
64-
#define SIM_TIMER_INFO_XML 10
65-
#define SIM_TIMER_FIRST_FUNCTION 11
63+
#define SIM_TIMER_RESIDUALS 9
64+
#define SIM_TIMER_ALGEBRAICS 10
65+
#define SIM_TIMER_ZC 11
66+
#define SIM_TIMER_INIT_XML 12
67+
#define SIM_TIMER_INFO_XML 13
68+
#define SIM_TIMER_FIRST_FUNCTION 14
6669

6770
#define SIM_PROF_TICK_FN(ix) rt_tick(ix+SIM_TIMER_FIRST_FUNCTION)
6871
#define SIM_PROF_ACC_FN(ix) rt_accumulate(ix+SIM_TIMER_FIRST_FUNCTION)

0 commit comments

Comments
 (0)