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 = "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.00565602,
    timeBackend = 0.001794289,
    timeSimCode = 0.014784655,
    timeTemplates = 0.002813055,
    timeCompile = 0.61565447,
    timeSimulation = 0.053375571,
    timeTotal = 0.694178423
end SimulationResult;
"Warning: The initial conditions are not fully specified. Use +d=initialization for more information.
Warning: There are iteration variables with default zero start attribute. Use +d=initialization for more information.
"

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  
Output format  
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.000211 7.75%
Initialization 0.000068 2.50%
Event-handling 0.000031 1.14%
Creating output file 0.000422 15.49%
Linearization 0.000000 0.00%
Time steps 0.001628 59.77%
Overhead 0.000358 13.14%
Unknown 0.000217 0.22%
Total simulation time 0.002724 100.00%

Global Steps

  Steps Total Time Fraction Average Time Max Time Deviation
Graph thumbnail 999 499 0.001628 59.77% 3.2625250501002e-06 0.000059754 17.32x

Measured Function Calls

  Name Calls Time Fraction Max Time Deviation
Graph thumbnail function fun0Graph thumbnail count function fun0 ProfilingTest.f 506 0.000040396 1.48% 0.000006034 74.58x

Measured Blocks

  Name Calls Time Fraction Max Time Deviation
Graph thumbnail eq0Graph thumbnail count eq0 ` <#eq0>`__ 2 0.000012958 0.48% 0.000013038 1.01x
Graph thumbnail eq5Graph thumbnail count eq5 ` <#eq5>`__ 12 0.000017810 0.65% 0.000018690 11.59x
Graph thumbnail eq10Graph thumbnail count eq10 ` <#eq10>`__ 504 0.000415338 15.25% 0.000011809 13.33x
Graph thumbnail eq13Graph thumbnail count eq13 ` <#eq13>`__ 504 0.000340317 12.49% 0.000011888 16.61x

Equations

Name Variables
   
   
  ` <#var0>`__
  ` <#var0>`__
   
  ` <#var0>`__
  ` <#var0>`__
  ` <#var0>`__
  ` <#var0>`__
   
  ` <#var0>`__
  ` <#var0>`__
   
  ` <#var0>`__
  ` <#var0>`__

Genenerated JSON for the Example

Listing 4 ProfilingTest_prof.json
{
"name":"ProfilingTest",
"prefix":"ProfilingTest",
"date":"2015-06-16 12:59:57",
"method":"",
"outputFormat":"",
"outputFilename":"ProfilingTest_res.mat",
"outputFilesize":24569,
"overheadTime":0.000357517,
"preinitTime":0.000211275,
"initTime":6.802e-05,
"eventTime":3.07e-05,
"outputTime":0.00042202,
"linearizeTime":0,
"totalTime":0.00272385,
"totalStepsTime":3.008e-06,
"totalTimeProfileBlocks":0.000786423,
"numStep":499,
"maxTime":5.9754e-05,
"functions":[
{"name":"ProfilingTest.f","ncall":506,"time":0.000040396,"maxTime":0.000006034}
],
"profileBlocks":[
{"id":0,"ncall":2,"time":0.000012958,"maxTime":0.000013038},
{"id":5,"ncall":12,"time":0.000017810,"maxTime":0.000018690},
{"id":10,"ncall":504,"time":0.000415338,"maxTime":0.000011809},
{"id":13,"ncall":504,"time":0.000340317,"maxTime":0.000011888}
]
}