Modelica Performance Analyzer

A common problem when simulating models in an equation-based language like Modelica is that the model may contain non-linear equation systems. These are solved in each time-step by extrapolating an initial guess and running a non-linear system solver. If the simulation takes too long to simulate, it is useful to run the performance analysis tool. The tool has around 5~25% overhead, which is very low compared to instruction-level profilers (30x-100x overhead). Due to being based on a single simulation run, the report may contain spikes in the charts.

When running a simulation for performance analysis, execution times of user-defined functions as well as linear, non-linear and mixed equation systems are recorded.

To start a simulation in this mode, turn on profiling with the following command line flag >>> setCommandLineOptions("--profiling=all")

The generated report is in HTML format (with images in the SVG format), stored in a file modelname_prof.html, but the XML database and measured times that generated the report and graphs are also available if you want to customize the report for comparison with other tools.

Below we use the performance profiler on the simple model A:

model ProfilingTest
  function f
    input Real r;
    output Real o = sin(r);
  end f;
  String s = "abc";
  Real x = f(x) "This is x";
  Real y(start=1);
  Real z1 = cos(z2);
  Real z2 = sin(z1);
equation
  der(y) = time;
end ProfilingTest;

We simulate as usual, after setting the profiling flag:

>>> setCommandLineOptions("--profiling=blocks+html")
true
>>> simulate(ProfilingTest)
record SimulationResult
    resultFile = "«DOCHOME»/ProfilingTest_res.mat",
    simulationOptions = "startTime = 0.0, stopTime = 1.0, numberOfIntervals = 500, tolerance = 1e-06, method = 'dassl', fileNamePrefix = 'ProfilingTest', options = '', outputFormat = 'mat', variableFilter = '.*', cflags = '', simflags = ''",
    messages = "LOG_SUCCESS       | info    | The initialization finished successfully without homotopy method.
LOG_SUCCESS       | info    | The simulation finished successfully.
Warning: empty y range [3:3], adjusting to [2.97:3.03]
Warning: empty y range [3:3], adjusting to [2.97:3.03]
Warning: empty y range [2:2], adjusting to [1.98:2.02]
Warning: empty y range [2:2], adjusting to [1.98:2.02]
Warning: empty y range [3:3], adjusting to [2.97:3.03]
Warning: empty y range [3:3], adjusting to [2.97:3.03]
stdout            | info    | Time measurements are stored in ProfilingTest_prof.html (human-readable) and ProfilingTest_prof.xml (for XSL transforms or more details)
",
    timeFrontend = 0.0006886240000000001,
    timeBackend = 0.006962923,
    timeSimCode = 0.010692904,
    timeTemplates = 0.003531035,
    timeCompile = 0.406606381,
    timeSimulation = 0.06202728,
    timeTotal = 0.4906109989999999
end SimulationResult;
"Warning: There are nonlinear iteration variables with default zero start attribute found in NLSJac0. For more information set -d=initialization. In OMEdit Tools->Options->Simulation->Show additional information from the initialization process, in OMNotebook call setCommandLineOptions(\"-d=initialization\").
Warning: The initial conditions are not fully specified. For more information set -d=initialization. In OMEdit Tools->Options->Simulation->Show additional information from the initialization process, in OMNotebook call setCommandLineOptions(\"-d=initialization\").
"

Profiling information for ProfilingTest

Information

All times are measured using a real-time wall clock. This means context switching produces bad worst-case execution times (max times) for blocks. If you want better results, use a CPU-time clock or run the command using real-time priviliges (avoiding context switches).

Note that for blocks where the individual execution time is close to the accuracy of the real-time clock, the maximum measured time may deviate a lot from the average.

For more details, see ProfilingTest_prof.xml.

Settings

Name

Value

Integration method

dassl

Output format

mat

Output name

ProfilingTest_res.mat

Output size

24.0 kB

Profiling data

ProfilingTest_prof.data

Profiling size

0 B

Summary

Task

Time

Fraction

Pre-Initialization

0.000116

1.96%

Initialization

0.000155

2.62%

Event-handling

0.000000

0.00%

Creating output file

0.000364

6.16%

Linearization

NaN%

Time steps

0.004643

78.56%

Overhead

0.000139

2.35%

Unknown

NaN

NaN%

Total simulation time

0.005910

100.00%

Global Steps

Steps

Total Time

Fractio n

Average Time

Max Time

Deviati on

|Graph thumbna il 999|

499

0.00464 3

78.56%

9.30460 9218436 88e-06

0.00009 4448

9.15x

Measured Function Calls

Name

Calls

Time

Fractio n

Max Time

Deviati on

|Graph thumbna il functio n fun0||Graph thumbna il count functio n fun0|

Profil ingTest .f _

1512

0.00015 8472

2.68%

0.00000 1883

16.97x

Measured Blocks

Name

Calls

Time

Fractio n

Max Time

Deviati on

|Graph thumbna il eq0|| Graph thumbna il count eq0|

` <#eq0 >`__

7

0.00009 0172

1.53%

0.00009 0901

6.06x

|Graph thumbna il eq11||Graph thumbna il count eq11|

` <#eq1 1>`__

4

0.00000 4063

0.07%

0.00000 4428

3.36x

|Graph thumbna il eq19||Graph thumbna il count eq19|

` <#eq1 9>`__

1006

0.00089 4060

15.13%

0.00001 3133

13.78x

|Graph thumbna il eq21||Graph thumbna il count eq21|

` <#eq2 1>`__

1508

0.00149 5272

25.30%

0.00001 3544

12.66x

Equations

Name

Variables

eq0

eq1

y

eq2

s

eq3

z2

eq4

eq5

` <#var0>`__

eq6

` <#var0>`__

eq7

` <#var0>`__

eq8

` <#var0>`__

eq9

z1

eq10

eq11

x

eq12

eq13

z2

eq14

eq15

` <#var0>`__

eq16

` <#var0>`__

eq17

` <#var0>`__

eq18

` <#var0>`__

eq19

z1

eq20

eq21

x

eq22

der(y)

eq23

Variables

Name

Comment

y

der(y)

x

This is x

z1

z2

s


This report was generated by OpenModelica on 2021-10-27 10:08:40.

Genenerated JSON for the Example

Listing 9 ProfilingTest_prof.json
{
"name":"ProfilingTest",
"prefix":"ProfilingTest",
"date":"2021-10-27 10:08:40",
"method":"dassl",
"outputFormat":"mat",
"outputFilename":"ProfilingTest_res.mat",
"outputFilesize":24581,
"overheadTime":0.000181729,
"preinitTime":0.00011652,
"initTime":0.000154672,
"eventTime":0,
"outputTime":0.000364457,
"jacobianTime":2.89802e-05,
"totalTime":0.00590971,
"totalStepsTime":8.34451e-06,
"totalTimeProfileBlocks":0.00248357,
"numStep":499,
"maxTime":9.4447512e-05,
"functions":[
{"name":"ProfilingTest.f","ncall":1512,"time":0.000158472,"maxTime":0.000001883}
],
"profileBlocks":[
{"id":0,"ncall":7,"time":0.000090172,"maxTime":0.000090901},
{"id":11,"ncall":4,"time":0.000004063,"maxTime":0.000004428},
{"id":19,"ncall":1006,"time":0.000894060,"maxTime":0.000013133},
{"id":21,"ncall":1508,"time":0.001495272,"maxTime":0.000013544}
]
}

Using the Profiler from OMEdit

When running a simulation from OMEdit, it is possible to enable profiling information, which can be combined with the transformations browser.

Profiling setup

Figure 133 Setting up the profiler from OMEdit.

When profiling the DoublePendulum example from MSL, the following output in Figure 134 is a typical result. This information clearly shows which system takes longest to simulate (a linear system, where most of the time overhead probably comes from initializing LAPACK over and over).

Profiling results

Figure 134 Profiling results of the Modelica standard library DoublePendulum example, sorted by execution time.