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, just use the measureTime flag of the simulate command.

>>> simulate(modelname, measureTime = true)

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, but set measureTime=true to activate the profiling:

>>> 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 [1:1], adjusting to [0.99:1.01]
Warning: empty y range [1:1], adjusting to [0.99:1.01]
Warning: empty y range [1:1], adjusting to [0.99:1.01]
Warning: empty y range [1:1], adjusting to [0.99:1.01]
Warning: empty y range [1:1], adjusting to [0.99:1.01]
Warning: empty y range [1:1], adjusting to [0.99:1.01]
stdout            | info    | Time measurements are stored in ProfilingTest_prof.html (human-readable) and ProfilingTest_prof.xml (for XSL transforms or more details)
",
    timeFrontend = 0.007467334000000001,
    timeBackend = 0.014916187,
    timeSimCode = 0.05062397,
    timeTemplates = 0.029550562,
    timeCompile = 0.6009116699999999,
    timeSimulation = 0.070503063,
    timeTotal = 0.7741415659999999
end SimulationResult;
"Warning: The initial conditions are not fully specified. For more information set -d=initialization. In OMEdit Tools->Options->Simulation->OMCFlags, in OMNotebook call setCommandLineOptions("-d=initialization").
Warning: There are iteration variables with default zero start attribute. For more information set -d=initialization. In OMEdit Tools->Options->Simulation->OMCFlags, in OMNotebook call setCommandLineOptions("-d=initialization").
"

Error

Profiling output should go here, but is currently broken on the build server.

Genenerated JSON for the Example

Listing 6 ProfilingTest_prof.json

{
"name":"ProfilingTest",
"prefix":"ProfilingTest",
"date":"2018-12-17 14:09:56",
"method":"dassl",
"outputFormat":"mat",
"outputFilename":"ProfilingTest_res.mat",
"outputFilesize":24581,
"overheadTime":0.000556517,
"preinitTime":0.00016607,
"initTime":0.000247193,
"eventTime":7.1285e-05,
"outputTime":0.000701701,
"jacobianTime":2.4318e-05,
"totalTime":0.00796788,
"totalStepsTime":9.992e-06,
"totalTimeProfileBlocks":0.00282322,
"numStep":499,
"maxTime":0.000127335,
"functions":[
{"name":"ProfilingTest.f","ncall":506,"time":0.000027496,"maxTime":0.000001986}
],
"profileBlocks":[
{"id":0,"ncall":7,"time":0.000126123,"maxTime":0.000128955},
{"id":12,"ncall":2,"time":0.000005311,"maxTime":0.000005783},
{"id":20,"ncall":504,"time":0.000985815,"maxTime":0.000041570},
{"id":22,"ncall":504,"time":0.001705973,"maxTime":0.000039157}
]
}

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.

Figure 96 Setting up the profiler from OMEdit.

When profiling the DoublePendulum example from MSL, the following output in Figure 97 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).

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