Skip to content

Commit

Permalink
Generate a report for the profiler
Browse files Browse the repository at this point in the history
  • Loading branch information
@sjoelund
sjoelund committed Jun 5, 2015
1 parent 63ec7ef commit baac1ae
Show file tree
Hide file tree
Showing 2 changed files with 31 additions and 270 deletions.
17 changes: 5 additions & 12 deletions usersguide-sphinx/source/omnotebook.rst
View file
Expand Up @@ -95,8 +95,7 @@ Figure 426. **The front-page notebook of the OMNotebook version of the
DrModelica tutoring system.**

In each chapter of DrModelica the user is presented a short summary of
the corresponding chapter of the book “Principles of Object-Oriented
Modeling and Simulation with Modelica 2.1” by Peter Fritzson. The
the corresponding chapter of the Modelica book :cite:`openmodelica.org:fritzson:2004`. The
summary introduces some *keywords*, being hyperlinks that will lead the
user to other notebooks describing the keywords in detail.

Expand Down Expand Up @@ -767,6 +766,10 @@ Additional Features
References
----------

.. todo ::
Add these into extrarefs.bib and cite them somewhere
Eric Allen, Robert Cartwright, Brian Stoler. DrJava: A lightweight
pedagogic environment for Java. In Proceedings of the 33rd ACM Technical
Symposium on Computer Science Education (SIGCSE 2002) (Northern Kentucky
Expand All @@ -778,22 +781,12 @@ Programming. In Proc. of the Workshop on Developing Computer Science
Education – How Can It Be Done?. Linköping University, Dept. Computer &
Inf. Science, Linköping, Sweden, March 10, 2006.

Anders Fernström. Extending OMNotebook – An Interactive Notebook for
Structured Modelica Documents. Final thesis, LITH-IDA-EX--06/057—SE,
Dept. Computer and Information Science, Linköping University, Sweden,
September 4, 2006.

Eva-Lena Lengquist-Sandelin, Susanna Monemar, Peter Fritzson, and Peter
Bunus. DrModelica – A Web-Based Teaching Environment for Modelica. In
Proceedings of the 44th Scandinavian Conference on Simulation and
Modeling (SIMS’2003), available at www.scan-sims.org. Västerås, Sweden.
September 18-19, 2003.

The Modelica Association. The Modelica Language Specification Version
3.0, Sept 2007. http://www.modelica.org.

Stephen Wolfram. The Mathematica Book. Wolfram Media Inc, 1997.

.. |image19| image:: media/image33.png
.. |image20| image:: media/image35.png
.. |image25| image:: media/image44.png
Expand Down
284 changes: 26 additions & 258 deletions usersguide-sphinx/source/profiler.rst
View file
@@ -1,5 +1,5 @@
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.
Expand All @@ -17,7 +17,7 @@ systems are recorded.
To start a simulation in this mode, just use the measureTime flag of the
simulate command.

simulate(modelname, measureTime = true)
>>> 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
Expand All @@ -26,9 +26,13 @@ want to customize the report for comparison with other tools.

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

.. code-block:: modelica
.. omc-mos ::
:clear:
:hidden:
model A
.. omc-loadstring ::
model ProfilingTest
function f
input Real r;
output Real o = sin(r);
Expand All @@ -38,266 +42,30 @@ Below we use the performance profiler on the simple model A:
Real y(start=1);
Real z1 = cos(z2);
Real z2 = sin(z1);
equation
equation
der(y) = time;
end A;
We simulate as usual, but set measureTime=true to activate the
profiling:

simulate(A, measureTime = true)

// // record SimulationResult

// resultFile = "A\_res.mat",

// messages = "Time measurements are stored in A\_prof.html
(human-readable) and A\_prof.xml (for XSL transforms or more details)"

// end SimulationResult;

Example Report Generated for the A Model
----------------------------------------

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 the generated file
`*A\_prof.xml* <http://www.ida.liu.se/~marsj/A_prof4/A_prof.xml>`__,
shown in Section 8.1.7 below.

Settings
~~~~~~~~

The settings for the simulation are summarized in the table below:

+--------------------------+-----------------------------------------------------------------------------+
| **Name** | **Value** |
+--------------------------+-----------------------------------------------------------------------------+
| Integration method | euler |
+--------------------------+-----------------------------------------------------------------------------+
| Output format | mat |
+--------------------------+-----------------------------------------------------------------------------+
| Output name | `*A\_res.mat* <http://www.ida.liu.se/~marsj/A_prof4/A_res.mat>`__ |
+--------------------------+-----------------------------------------------------------------------------+
| Output size | 24.0 kB |
+--------------------------+-----------------------------------------------------------------------------+
| Profiling data | `*A\_prof.data* <http://www.ida.liu.se/~marsj/A_prof4/A_prof.data>`__ |
+--------------------------+-----------------------------------------------------------------------------+
| Profiling size | 27.3 kB |
+--------------------------+-----------------------------------------------------------------------------+

Summary
~~~~~~~

Execution times for different activities:

+-----------------------------+----------------+--------------------+
| **Task** | **Time** | **Fraction** |
+-----------------------------+----------------+--------------------+
| Pre-Initialization | 0.000401 | 19.17% |
+-----------------------------+----------------+--------------------+
| Initialization | 0.000046 | 2.20% |
+-----------------------------+----------------+--------------------+
| Event-handling | 0.000036 | 1.72% |
+-----------------------------+----------------+--------------------+
| Creating output file | 0.000264 | 12.62% |
+-----------------------------+----------------+--------------------+
| Linearization | 0.000000 | 0.00% |
+-----------------------------+----------------+--------------------+
| Time steps | 0.001067 | 51.00% |
+-----------------------------+----------------+--------------------+
| Overhead | 0.000273 | 13.05% |
+-----------------------------+----------------+--------------------+
| Unknown | 0.000406 | 0.24% |
+-----------------------------+----------------+--------------------+
| Total simulation time | 0.002092 | 100.00% |
+-----------------------------+----------------+--------------------+

Global Steps
~~~~~~~~~~~~

+-------------+-------------+------------------+----------------+------------------------+----------------+-----------------+
| ** ** | **Steps** | **Total Time** | **Fraction** | **Average Time** | **Max Time** | **Deviation** |
+-------------+-------------+------------------+----------------+------------------------+----------------+-----------------+
| |image39| | 499 | 0.001067 | 51.00% | 2.13827655310621e-06 | 0.000006611 | 2.09x |
+-------------+-------------+------------------+----------------+------------------------+----------------+-----------------+

Measured Function Calls
~~~~~~~~~~~~~~~~~~~~~~~

+------------------------+------------+-------------+---------------+----------------+----------------+-----------------+
| ** ** | **Name** | **Calls** | **Time** | **Fraction** | **Max Time** | **Deviation** |
+------------------------+------------+-------------+---------------+----------------+----------------+-----------------+
| |image40|\ |image41| | *A.f* | 1506 | 0.000092990 | 4.45% | 0.000000448 | 6.26x |
+------------------------+------------+-------------+---------------+----------------+----------------+-----------------+

Measured Blocks
~~~~~~~~~~~~~~~

+------------------------+-------------------+-------------+---------------+----------------+----------------+-----------------+
| ** ** | **Name** | **Calls** | **Time** | **Fraction** | **Max Time** | **Deviation** |
+------------------------+-------------------+-------------+---------------+----------------+----------------+-----------------+
| |image42|\ |image43| | *residualFunc3* | 2018 | 0.000521137 | 24.91% | 0.000035456 | 136.30x |
+------------------------+-------------------+-------------+---------------+----------------+----------------+-----------------+
| |image44|\ |image45| | *residualFunc1* | 1506 | 0.000393709 | 18.82% | 0.000002735 | 9.46x |
+------------------------+-------------------+-------------+---------------+----------------+----------------+-----------------+
end ProfilingTest;
Equations
^^^^^^^^^
We simulate as usual, but set measureTime=true to activate the profiling:

+-------------------------+-----------------+
| **Name** | **Variables** |
+-------------------------+-----------------+
| SES\_ALGORITHM 0 |   |
+-------------------------+-----------------+
| SES\_SIMPLE\_ASSIGN 1 | *der(y)* |
+-------------------------+-----------------+
| residualFunc3 | *z2*, *z1* |
+-------------------------+-----------------+
| residualFunc1 | *x* |
+-------------------------+-----------------+
.. omc-mos ::
Variables
^^^^^^^^^
setCommandLineOptions("--profiling=blocks+html")
simulate(ProfilingTest)
+--------------+---------------+
| **Name** | **Comment** |
+--------------+---------------+
| \ *y* |   |
+--------------+---------------+
| \ *der(y)* |   |
+--------------+---------------+
| \ *x* | This is x |
+--------------+---------------+
| \ *z1* |   |
+--------------+---------------+
| \ *z2* |   |
+--------------+---------------+
| \ *s* |   |
+--------------+---------------+
.. omc-mos ::
:hidden:
Genenerated XML for the Example
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
:target: ProfilingTest_prof.999.svg
system("pandoc -o ProfilingTest_prof.rst ProfilingTest_prof.html")
system("sed -i= 's/:target: ProfilingTest_prof.*/:width: 32px/' ProfilingTest_prof.rst")
system("cp ProfilingTest_prof* ../source/")
.. code-block:: xml
.. include :: ProfilingTest_prof.rst
<!DOCTYPE doc (View Source for full doctype...)>
<simulation>
<modelinfo>
<name>A</name>
<prefix>A</prefix>
<date>2011-03-07 12:55:53</date>
<method>euler</method>
<outputFormat>mat</outputFormat>
<outputFilename>A\_res.mat</outputFilename>
<outputFilesize>24617</outputFilesize>
<overheadTime>0.000273</overheadTime>
<preinitTime>0.000401</preinitTime>
<initTime>0.000046</initTime>
<eventTime>0.000036</eventTime>
<outputTime>0.000264</outputTime>
<linearizeTime>0.000000</linearizeTime>
<totalTime>0.002092</totalTime>
<totalStepsTime>0.001067</totalStepsTime>
<numStep>499</numStep>
<maxTime>0.000006611</maxTime>
</modelinfo>
<profilingdataheader>
<filename>A\_prof.data</filename>
<filesize>28000</filesize>
<format>
<uint32>step</uint32>
<double>time</double>
<double>cpu time</double>
<uint32>A.f (calls)</uint32>
<uint32>residualFunc3 (calls)</uint32>
<uint32>residualFunc1 (calls)</uint32>
<double>A.f (cpu time)</double>
<double>residualFunc3 (cpu time)</double>
<double>residualFunc1 (cpu time)</double>
</format>
</profilingdataheader>
<variables>
<variable id="1000" name="y" comment="">
<info filename="a.mo" startline="8" startcol="3" endline="8" endcol="18" readonly="writable" />
</variable>
<variable id="1001" name="der(y)" comment="">
<info filename="a.mo" startline="8" startcol="3" endline="8" endcol="18" readonly="writable" />
</variable>
<variable id="1002" name="x" comment="This is x">
<info filename="a.mo" startline="7" startcol="3" endline="7" endcol="28" readonly="writable" />
</variable>
<variable id="1003" name="z1" comment="">
<info filename="a.mo" startline="9" startcol="3" endline="9" endcol="20" readonly="writable" />
</variable>
<variable id="1004" name="z2" comment="">
<info filename="a.mo" startline="10" startcol="3" endline="10" endcol="20" readonly="writable" />
</variable>
<variable id="1005" name="s" comment="">
<info filename="a.mo" startline="6" startcol="3" endline="6" endcol="19" readonly="writable" />
</variable>
</variables>
<functions>
<function id="1006">
<name>A.f</name>
<ncall>1506</ncall>
<time>0.000092990</time>
<maxTime>0.000000448</maxTime>
<info filename="a.mo" startline="2" startcol="3" endline="5" endcol="8"
readonly="writable" />
</function>
</functions>
<equations>
<equation id="1007" name="SES\_ALGORITHM 0">
<refs />
</equation>
<equation id="1008" name="SES\_SIMPLE\_ASSIGN 1">
<refs>
<ref refid="1001" />
</refs>
</equation>
<equation id="1009" name="residualFunc3">
<refs>
<ref refid="1004" />
<ref refid="1003" />
</refs>
</equation>
<equation id="1010" name="residualFunc1">
<refs>
<ref refid="1002" />
</refs>
</equation>
</equations>
<profileblocks>
<profileblock>
<ref refid="1009" />
<ncall>2018</ncall>
<time>0.000521137</time>
<maxTime>0.000035456</maxTime>
</profileblock>
<profileblock>
<ref refid="1010" />
<ncall>1506</ncall>
<time>0.000393709</time>
<maxTime>0.000002735</maxTime>
</profileblock>
</profileblocks>
</simulation>
Genenerated JSON for the Example
================================

.. |image39| image:: media/image76.png
.. |image40| image:: media/image77.png
.. |image41| image:: media/image78.png
.. |image42| image:: media/image79.png
.. |image43| image:: media/image80.png
.. |image44| image:: media/image81.png
.. |image45| image:: media/image82.png
.. literalinclude :: ../tmp/ProfilingTest_prof.json
:caption: ProfilingTest_prof.json
:language: json

0 comments on commit baac1ae

Please sign in to comment.