Reading from an external file is very slow

[paul]

I would like to have OpenModelica read some parameters from a file which is separate from the model files. So i found the functions in the Modelica.Utilities (Modelica Standard Library). There is an example (Modelica.Utilities.Examples.readRealParameterModel) which reads 3 Parameters from an external file, and it spents one minute to do so. I tried to find out why it is so slow, but with no success. It is not clear what is wrong, the model in the library or the simulation environment, but i guess it is the latter.

With a real parameter file this task would be unfeasable. So this behavior must be considered a bug.

[paul]

I used OMEdit (rev. 16935) to simulate. The MDT even fails to simulate the same model; unfortunately, the error message just says nothing to me.

[Martin Sjölund]

How are you running this model? On ​https://test.openmodelica.org/~marsj/MSL32/BuildModelRecursive.html it says the model takes 0 seconds to run.
My OMEdit says:

LOG_STATS         | info    | ### STATISTICS ###
LOG_STATS         | info    | timer
|                 | |       | |  0.000202403s [  2.8%] pre-initialization
|                 | |       | |  0.000589525s [  8.2%] initialization
|                 | |       | |    2.458e-06s [  0.0%] steps
|                 | |       | |   0.00046295s [  6.4%] creating output-file
|                 | |       | |  0.000109467s [  1.5%] event-handling
|                 | |       | |   0.00149627s [ 20.8%] overhead
|                 | |       | |   0.00433231s [ 60.2%] simulation
|                 | |       | |   0.00719538s [100.0%] total
LOG_STATS         | info    | events
|                 | |       | |     0 state events
|                 | |       | |     0 time events
LOG_STATS         | info    | solver
|                 | |       | |    19 steps taken
|                 | |       | |    19 calls of functionODE
|                 | |       | |    18 evaluations of jacobian
|                 | |       | |     0 error test failures
|                 | |       | |     0 convergence test failures
LOG_STATS         | info    | ### END STATISTICS ###

[paul]

I just take OMEdit as it comes, open the the model, and run it. No special adjustments. My OMEdit says

LOG_STATS         | info    | ### STATISTICS ###
LOG_STATS         | info    | timer
|                 | |       | |   0.00119778s [  3.5%] pre-initialization
|                 | |       | |   0.00219283s [  6.3%] initialization
|                 | |       | | 4.06177e-005s [  0.1%] steps
|                 | |       | |   0.00194016s [  5.6%] creating output-file
|                 | |       | |  0.000389596s [  1.1%] event-handling
|                 | |       | |   0.00810787s [ 23.4%] overhead
|                 | |       | |    0.0208084s [ 60.0%] simulation
|                 | |       | |    0.0346772s [100.0%] total
LOG_STATS         | info    | events
|                 | |       | |     0 state events
|                 | |       | |     0 time events
LOG_STATS         | info    | solver
|                 | |       | |    19 steps taken
|                 | |       | |    19 calls of functionODE
|                 | |       | |    18 evaluations of jacobian
|                 | |       | |     0 error test failures
|                 | |       | |     0 convergence test failures
LOG_STATS         | info    | ### END STATISTICS ###

which does not explain the long duration. OMEdit itself spents a minute before the 'OMEdit - Simulation' window disappears, and the result is shown.

[paul]

What about the MDT failure? I've attached the error output (it is rather long), which appears after 1.5 minutes in the OpenModelica console. All is running on Win XP.

[Martin Sjölund]

You need to set MDT to use Modelica instead of MetaModelica

[paul]

How do i do that?

[Adrian Pop]

You remove +g=MetaModelica from Window->Preferences->Modelica and restart Eclipse.
But that might not be enough, I have to check as I think we add it anyway when we
start omc process from Eclipse.

[paul]

Ok, i think you are right. I removed the +g=MetaModelica, and started over, but the model still doesn't run.

[Adrian Pop]

Hi,

I now made a MDT 0.7.29 which does not set +g=MetaModelica by default.
You can update it in your Eclipse and see how is going.

Cheers,
Adrian Pop/

[paul]

Hi Adrian,

i updated to your version, and tried once more. Unfortunately, the failure remains.

--Paul

[Adrian Pop]

Have you checked in Window->Preferences->Modelica
if Command line parameters is empty?
The update does not delete the values that are already saved there.
If you still have +g=MetaModelica there, delete it and restart Eclipse.
Let me know how it goes.

[Adeel Asghar]

Make sure you also kill all omc processes. MDT has the ability to connect to the already running omc process.

[paul]

New omc process, no command line parameters, and the failure remains. I attach the error log again.

[Adeel Asghar]

OK. I got the same problem. For now as a work around you can send clearCommandLineOptions before sending simulate command,

clearCommandLineOptions()

it should return true.

Meanwhile i will try to investigate why MDT is running with +g=MetaModelica.

[paul]

Ok, the clearing lets the model simulate.

By the way, are there any new findings concerning the slow execution? I saw the test results, but what was the system the tests ran on? Can it be that the problem occurs only on Win XP systems?

[Martin Sjölund]

The results from my OMEdit are on a slow Ubuntu laptop. OpenModelica on Windows XP in general is slower than Linux.

[Martin Sjölund]

Oh, and file operations in particular are slower on Windows.

[anonymous]

But can it be that these general differences between the systems amount to a runtime of one minute for the reading of 3 parameters?

[Martin Sjölund]

Yes :)

[Adrian Pop]

I don't think the reading of parameters is slow.
Maybe the operations that OMEdit does with the model takes time.
Have you tried with just OMC from command line with a script.mos?

loadModel(Modelica); getErrorString();
simulate(Modelica.Utilities.Examples.readRealParameterModel); getErrorString();

Start->cmd.exe

> cd path\to\script.mos
> c:\OpenModelica\bin\omc script.mos

See how much that takes.

[Adeel Asghar]

Use r17053. I have fixed the MDT issue. The compiler was forced to use the MetaModelica grammar for MDT that is why the MetaModelica flag is always on for MDT.

[paul]

Replying to adrpo:

I don't think the reading of parameters is slow.

I know it is :(

...
See how much that takes.

First, i used OMShell and got the same result as with OMEdit (1 min). Then, i tried your script, and it spent 3 min 24 sec :o (10 sec for the loading of the MSL).

So i wonder whether the Windows version is special with respect to that subject. (Does it undergoes the same tests as cited above for Linux?)

@adeas31: Thanks for the fix. I haven't updated yet (i was off my desk for some time) but i will do so in the days to come.

[paul]

Now MDT simulates the model too. It spents 1:15 to do so.

[Adrian Pop]

Hi,

The problem is that we try to evaluate constant function calls and we build dlls for them,
load them in the process and call them. And this happens quite many times.

You can use +d=nogen to prevent dll generation during compilation.

adrpo@ida-liu050 ~/dev/OpenModelicaNoChanges/build/bin
$ ./omc +d=nogen script.mos
true
""
record SimulationResult
    resultFile = "c:/bin/cygwin/home/adrpo/dev/OpenModelicaNoChanges/build/bin/Modelica.Utilities.Examples.readRealParameterModel_res.mat",
    simulationOptions = "startTime = 0.0, stopTime = 1.01, numberOfIntervals = 500, tolerance = 0.000001, method = 'dassl', fileNamePrefix = 'Modelica.Utilities.Examples.readRealParameterModel', options = '', outputFormat = 'mat', variableFilter = '.*', measureTime = false, cflags = '', simflags = ''",
    messages = "",
    timeFrontend = 0.4449119886793644,
    timeBackend = 0.01226569002061027,
    timeSimCode = 0.006913332927851735,
    timeTemplates = 0.035199138941862405,
    timeCompile = 2.251662795343942,
    timeSimulation = 0.11431693930171449,
    timeTotal = 2.8661568120523504
end SimulationResult;
""

Inside a script you can use setCommandLineOptions("+d=nogen");
before calling simulate.

[Adrian Pop]

This is actually a duplicate of #1227.
We do constant evaluation for all parameters and
we should only do it for structural parameters.
The new instantiation which is in the works should
fix this issue.

[anonymous]

Replying to adrpo:

Hi Adrian,

I turned the dll-generation off and it actually reduces the runtime (to 6 sec, with exception of the script-variant which met 56 sec (why?)).

The problem is that we try to evaluate constant function calls and we build dlls for them,
load them in the process and call them. And this happens quite many times.

I'm not sure i understand it right: are the parameter values read over and over again? Since parameters are constant during a simulation run, it would be sufficient to read the parameter values once only. Then it should be of no importance (concerning runtime) whether a library is called in order to get the values. Please let me know what i'm getting wrong.

Inside a script you can use setCommandLineOptions("+d=nogen");
before calling simulate.

Btw, how can one switch a flag back, ie. in this case turn the dll-generation on again when it has been turned off with the above command before?

[Adrian Pop]

What do you mean by "with the exception of the script variant"?
This script:

loadModel(Modelica); getErrorString();
setCommandLineOptions("+d=nogen"); // disable dll generation
simulate(Modelica.Utilities.Examples.readRealParameterModel); getErrorString();
setCommandLineOptions("+d=gen"); // set back the dll generation

runs in 7 seconds:

adrpo@ida-liu050 ~/dev/OpenModelicaNoChanges/build/bin
$ time ./omc read.mos
true
""
true
record SimulationResult
    resultFile = "c:/bin/cygwin/home/adrpo/dev/OpenModelicaNoChanges/build/bin/Modelica.Utilities.Examples.readRealParameterModel_res.mat",
    simulationOptions = "startTime = 0.0, stopTime = 1.01, numberOfIntervals = 500, tolerance = 0.000001, method = 'dassl', fileNamePrefix = 'Modelica.Utilities.Examples.readRealParameterModel', options = '', outputFormat = 'mat', variableFilter = '.*', measureTime = false, cflags = '', simflags = ''",
    messages = "",
    timeFrontend = 0.42345906085842505,
    timeBackend = 0.012500510059921454,
    timeSimCode = 0.006671583772626451,
    timeTemplates = 0.028995270493437742,
    timeCompile = 1.7608242414350352,
    timeSimulation = 0.16018999635836464,
    timeTotal = 2.3933216410918132
end SimulationResult;
""
true

real    0m7.700s
user    0m0.000s
sys     0m0.015s

You can use setCommandLineOptions("+d=gen"); to switch it back.

Parameters values are not read several times, the functions that read the parameters
are compiled into dlls each time there is a function call that cannot be evaluated via
the internal function interpretation.

Functions are compiled 126 times in the case of this model:

adrpo@ida-liu050 ~/dev/OpenModelicaNoChanges/build/bin
$ ./omc +showErrorMessages +d=dynload,failtrace read.mos > trace.txt 2>&1
adrpo@ida-liu050 ~/dev/OpenModelicaNoChanges/build/bin
$ cat trace.txt | grep compileModel | wc -l
126

and that takes quite some time.

We are working on a new rewrite of the flattening part of the compiler which will fix this issue, but it will take a while (2-3 months or so).

[anonymous]

Replying to adrpo:

What do you mean by "with the exception of the script variant"?

I mean exactly the script you used, but run in the command shell of Win XP as you suggested above. Compared with having MDT and OMC running the model it spents still more time in both cases, with and without the +d=nogen (without 3 min 24 sec). The "timeTotal" from the output of the command is 45.24 sec (sorry i don't post the full output; there is no copy and paste in the shell).

Thanks for your answer concerning the reading of parameters. It is still somewhat mysterious to me. Anyway, i think the will be advantageous.

[Martin Sjölund]

Postponed until 1.9.1

[Martin Sjölund]

This ticket was not closed for 1.9.1, which has now been released. It was batch modified for milestone 1.9.2 (but maybe an empty milestone was more appropriate; feel free to change it).

[Martin Sjölund]

Milestone changed to 1.9.3 since 1.9.2 was released.

[Martin Sjölund]

Moved to new milestone 1.9.4

[Martin Sjölund]

Milestone pushed to 1.9.5

[Martin Sjölund]

Milestone renamed

[Francesco Casella]

I have checked ​https://test.openmodelica.org/libraries/MSL_3.2.1/BuildModelRecursive.html and it seems that the cited test case is now running in a few seconds, provided -d=nogen is used.

Please refer to #1227 if you want this to work efficiently without that compiler setting.

[Martin Sjölund]

Milestone deleted