search

OpenModelica / OpenModelica

OpenModelica is an open-source Modelica-based modeling and simulation environment intended for industrial and academic usage.
https://openmodelica.org
Other
850 stars 306 forks source link

slow translation of ZonedBorefield model in Buildings library #12446

Open mwetter opened 5 months ago

mwetter commented 5 months ago

The model Buildings.Fluid.Geothermal.ZonedBorefields.Validation.SteadyStateBoreholeDynamics in the Buildings Library, commit af4ef2b866 (development branch issue3793_seasonalGeothermalStorage) translates very slow in OpenModelica.

Connected to OpenModelica 1.24.0~dev-83-g26c8457

Connected to OMSimulator 2.1.2~1-g896adee-linux-notlm-debug

This is a new model that translates in about 10 seconds in Dymola, with OpenModelica, running 

omc Buildings.Fluid.Geothermal.ZonedBorefields.Validation.SteadyStateBoreholeDynamics_translate.mos

where the .mos script is

setCommandLineOptions("-d=nogen");
setCommandLineOptions("-d=initialization");
setCommandLineOptions("-d=backenddaeinfo");
setCommandLineOptions("-d=discreteinfo");
setCommandLineOptions("-d=stateselection");
installPackage(Modelica, "");
setMatchingAlgorithm("PFPlusExt");
setIndexReductionMethod("dynamicStateSelection");

print("Loading library");
loadFile("Buildings/package.mo");
print("Loading model");
print("Translating model");
translateModel(Buildings.Fluid.Geothermal.ZonedBorefields.Validation.SteadyStateBoreholeDynamics, method="dassl", tolerance=1e-06, numberOfIntervals=500, variableFilter="(borHol.TBorAve[[]2[]]|TBorFieOut[[]2[]].T|TBorFieIn[[]2[]].T|TBorFieIn[[]1[]].T|borHol.TBorAve[[]1[]]|TBorFieOut[[]1[]].T)");
getErrorString();
print("Compiling model");
retVal := system("make -f Buildings.Fluid.Geothermal.ZonedBorefields.Validation.SteadyStateBoreholeDynamics.makefile");
exit(retVal);

takes around 4 minutes, with the majority of time spend in the translateModel command. Note that an earlier version of this model that was configured for a larger bore field took about 50 minutes for omc to translate. It appears like there is some part of the translator that has a large overhead.

The script is generated from our CI test environment (using BuildingsPy).

perost commented 5 months ago

You can add the -d=execstat flag to get more detailed information about how much time each compilation phase takes.

mwetter commented 5 months ago

@perost : Thanks for the good hint. The two biggest parts are:

Notification: Performance of analyzeInitialSystem (initialization): time 48.55/73.84, allocations: 134.5 MB / 6.453 GB, free: 276 MB / 1.902 GB
Notification: Performance of analyzeInitialSystem (initialization_lambda0): time 48.47/133.3, allocations: 134 MB / 6.986 GB, free: 420.1 MB / 1.902 GB

followed by a few that take around 10 seconds. This model has a lot of function calls that are evaluated as part of the model initialization, but these calls should not change the structure of the system of equations. Not sure why this causes such high a time for the initial system analysis.

Below is the full performance profiling output:


Notification: Performance of loadFile(Buildings/package.mo): time 2.632/2.632, allocations: 0.6856 GB / 0.7173 GB, free: 12.24 MB / 0.558 GB
Notification: Performance of FrontEnd - loaded program: time 0.0004557/0.0004558, allocations: 8.719 kB / 1.033 GB, free: 0.7617 MB / 0.808 GB
Notification: Performance of FrontEnd - Absyn->SCode: time 0.8438/0.8443, allocations: 160.2 MB / 1.19 GB, free: 0.582 MB / 0.9642 GB
Notification: Performance of NFInst.instantiate(Buildings.Fluid.Geothermal.ZonedBorefields.Validation.SteadyStateBoreholeDynamics): time 0.7236/1.568, allocations: 125.3 MB / 1.312 GB, free: 14.07 MB / 1.042 GB
Notification: Performance of NFInst.instExpressions: time 0.1483/1.716, allocations: 36.13 MB / 1.347 GB, free: 4.531 MB / 1.058 GB
Notification: Performance of NFInst.updateImplicitVariability: time 0.006219/1.723, allocations: 144.7 kB / 1.348 GB, free: 4.484 MB / 1.058 GB
Notification: Performance of NFTyping.typeComponents: time 0.02203/1.745, allocations: 4.618 MB / 1.352 GB, free: 2.613 MB / 1.058 GB
Notification: Performance of NFTyping.typeBindings: time 0.02595/1.771, allocations: 5.028 MB / 1.357 GB, free: 15.62 MB / 1.074 GB
Notification: Performance of NFTyping.typeClassSections: time 0.03967/1.81, allocations: 5.49 MB / 1.362 GB, free: 12.48 MB / 1.074 GB
Notification: Performance of NFFlatten.flatten: time 0.2724/2.083, allocations: 72.03 MB / 1.433 GB, free: 0.6328 MB / 1.12 GB
Notification: Performance of NFFlatten.resolveConnections: time 0.1314/2.214, allocations: 31.9 MB / 1.464 GB, free: 0.5508 MB / 1.152 GB
Notification: Performance of NFEvalConstants.evaluate: time 0.09066/2.305, allocations: 20.68 MB / 1.484 GB, free: 11.83 MB / 1.183 GB
Notification: Performance of NFSimplifyModel.simplify: time 0.08695/2.392, allocations: 20.57 MB / 1.504 GB, free: 7.188 MB / 1.199 GB
Notification: Performance of NFPackage.collectConstants: time 0.01875/2.411, allocations: 3.262 MB / 1.507 GB, free: 3.926 MB / 1.199 GB
Notification: Performance of NFFlatten.collectFunctions: time 0.05188/2.463, allocations: 8.912 MB / 1.516 GB, free: 11 MB / 1.214 GB
Notification: Performance of NFScalarize.scalarize: time 0.1284/2.591, allocations: 41.22 MB / 1.556 GB, free: 1.684 MB / 1.245 GB
Notification: Performance of NFVerifyModel.verify: time 0.2108/2.802, allocations: 54.08 MB / 1.609 GB, free: 11.32 MB / 1.308 GB
Notification: Performance of NFConvertDAE.convert: time 0.7657/3.568, allocations: 197.1 MB / 1.802 GB, free: 5.543 MB / 1.495 GB
Notification: Performance of FrontEnd - DAE generated: time 8.352e-06/3.568, allocations: 4 kB / 1.802 GB, free: 5.539 MB / 1.495 GB
Notification: Performance of FrontEnd: time 1.896e-06/3.568, allocations: 0 / 1.802 GB, free: 5.539 MB / 1.495 GB
Notification: Performance of Transformations before backend: time 0.003004/3.571, allocations: 0 / 1.802 GB, free: 5.539 MB / 1.495 GB
Notification: Model statistics after passing the front-end and creating the data structures used by the back-end:
 * Number of equations: 5112
 * Number of variables: 5112
Notification: Performance of Generate backend data structure: time 1.648/5.22, allocations: 123.6 MB / 1.922 GB, free: 313.9 MB / 1.511 GB
Notification: Performance of prepare preOptimizeDAE: time 0.0001117/5.22, allocations: 12.72 kB / 1.922 GB, free: 313.9 MB / 1.511 GB
Notification: Performance of preOpt normalInlineFunction (simulation): time 0.03758/5.257, allocations: 11.69 MB / 1.934 GB, free: 302.5 MB / 1.511 GB
Notification: Performance of preOpt evaluateParameters (simulation): time 0.2312/5.489, allocations: 104.1 MB / 2.035 GB, free: 199.4 MB / 1.511 GB
Notification: Performance of preOpt simplifyIfEquations (simulation): time 0.001749/5.49, allocations: 1.833 MB / 2.037 GB, free: 197.5 MB / 1.511 GB
Notification: Performance of preOpt expandDerOperator (simulation): time 0.006198/5.497, allocations: 2.57 MB / 2.04 GB, free: 195 MB / 1.511 GB
Notification: Performance of preOpt clockPartitioning (simulation): time 0.08666/5.583, allocations: 51.89 MB / 2.09 GB, free: 142.6 MB / 1.511 GB
Notification: Performance of preOpt findStateOrder (simulation): time 0.0007339/5.584, allocations: 43.91 kB / 2.09 GB, free: 142.6 MB / 1.511 GB
Notification: Performance of preOpt replaceEdgeChange (simulation): time 0.004508/5.589, allocations: 0.719 MB / 2.091 GB, free: 141.9 MB / 1.511 GB
Notification: Performance of preOpt inlineArrayEqn (simulation): time 0.0005241/5.589, allocations: 0.6033 MB / 2.092 GB, free: 141.3 MB / 1.511 GB
Notification: Performance of preOpt removeEqualRHS (simulation): time 0.06954/5.659, allocations: 44.7 MB / 2.135 GB, free: 96.56 MB / 1.511 GB
Warning: The model contains alias variables with redundant start and/or conflicting nominal values. It is recommended to resolve the conflicts, because otherwise the system could be hard to solve. To print the conflicting alias sets and the chosen candidates please use -d=aliasConflicts.
Notification: Performance of preOpt removeSimpleEquations (simulation): time 0.714/6.373, allocations: 206.1 MB / 2.337 GB, free: 13.13 MB / 1.636 GB
Notification: Performance of preOpt comSubExp (simulation): time 0.1736/6.546, allocations: 41.88 MB / 2.378 GB, free: 3.348 MB / 1.668 GB
Notification: Performance of preOpt resolveLoops (simulation): time 0.1535/6.7, allocations: 35.66 MB / 2.412 GB, free: 15.68 MB / 1.714 GB
Notification: Performance of preOpt evalFunc (simulation): time 1.836/8.536, allocations: 107 MB / 2.517 GB, free: 0.5583 GB / 1.777 GB
Notification: Performance of preOpt encapsulateWhenConditions (simulation): time 0.04495/8.581, allocations: 34.9 MB / 2.551 GB, free: 0.548 GB / 1.777 GB
Notification: Performance of preOpt simplifyInStream (simulation): time 0.03474/8.616, allocations: 6.36 MB / 2.557 GB, free: 0.5475 GB / 1.777 GB
Notification: Performance of pre-optimization done (n=2580): time 5.715e-05/8.616, allocations: 4.031 kB / 2.557 GB, free: 0.5475 GB / 1.777 GB
Notification: Performance of matching and sorting (n=2652): time 15.26/23.87, allocations: 3.339 GB / 5.896 GB, free: 86.01 MB / 1.902 GB
Notification: Performance of inlineWhenForInitialization (initialization): time 0.003693/23.88, allocations: 3.339 MB / 5.899 GB, free: 83.19 MB / 1.902 GB
Notification: Performance of selectInitializationVariablesDAE (initialization): time 1.072/24.95, allocations: 222.7 MB / 6.117 GB, free: 0.5935 GB / 1.902 GB
Notification: Performance of collectPreVariables (initialization): time 0.006556/24.95, allocations: 2.715 MB / 6.119 GB, free: 0.5922 GB / 1.902 GB
Notification: Performance of collectInitialEqns (initialization): time 0.1056/25.06, allocations: 44.72 MB / 6.163 GB, free: 0.561 GB / 1.902 GB
Notification: Performance of collectInitialBindings (initialization): time 0.01439/25.07, allocations: 8.026 MB / 6.171 GB, free: 0.5581 GB / 1.902 GB
Notification: Performance of simplifyInitialFunctions (initialization): time 0.03807/25.11, allocations: 23.34 MB / 6.194 GB, free: 0.5366 GB / 1.902 GB
Notification: Performance of setup shared object (initialization): time 5.241e-05/25.11, allocations: 309.2 kB / 6.194 GB, free: 0.5363 GB / 1.902 GB
Notification: Performance of preBalanceInitialSystem (initialization): time 0.0761/25.19, allocations: 56.73 MB / 6.249 GB, free: 492.4 MB / 1.902 GB
Notification: Performance of partitionIndependentBlocks (initialization): time 0.09758/25.29, allocations: 73.65 MB / 6.321 GB, free: 414.5 MB / 1.902 GB
Notification: Performance of analyzeInitialSystem (initialization): time 48.55/73.84, allocations: 134.5 MB / 6.453 GB, free: 276 MB / 1.902 GB
Notification: Performance of solveInitialSystemEqSystem (initialization): time 0.0005028/73.84, allocations: 91.69 kB / 6.453 GB, free: 275.9 MB / 1.902 GB
Notification: Performance of matching and sorting (n=17454) (initialization): time 10.01/83.85, allocations: 191.6 MB / 6.64 GB, free: 83.68 MB / 1.902 GB
Notification: Performance of prepare postOptimizeDAE: time 0.0006549/83.85, allocations: 195.4 kB / 6.64 GB, free: 83.48 MB / 1.902 GB
Notification: Performance of postOpt simplifyComplexFunction (initialization): time 0.0007494/83.85, allocations: 344 kB / 6.64 GB, free: 83.14 MB / 1.902 GB
Notification: Performance of postOpt tearingSystem (initialization): time 0.01508/83.87, allocations: 6.706 MB / 6.647 GB, free: 76.43 MB / 1.902 GB
Notification: Performance of postOpt solveSimpleEquations (initialization): time 0.0262/83.89, allocations: 6.307 MB / 6.653 GB, free: 70.11 MB / 1.902 GB
Notification: Performance of postOpt calculateStrongComponentJacobians (initialization): time 0.02036/83.91, allocations: 14.77 MB / 6.667 GB, free: 55.24 MB / 1.902 GB
Notification: Performance of postOpt simplifyAllExpressions (initialization): time 0.06149/83.97, allocations: 1.974 MB / 6.669 GB, free: 53.27 MB / 1.902 GB
Notification: Performance of postOpt collapseArrayExpressions (initialization): time 0.006504/83.98, allocations: 1.708 MB / 6.671 GB, free: 51.56 MB / 1.902 GB
Notification: Performance of preBalanceInitialSystem (initialization_lambda0): time 0.7476/84.73, allocations: 114.9 MB / 6.783 GB, free: 0.5925 GB / 1.902 GB
Notification: Performance of partitionIndependentBlocks (initialization_lambda0): time 0.09993/84.83, allocations: 73.42 MB / 6.855 GB, free: 0.5442 GB / 1.902 GB
Notification: Performance of analyzeInitialSystem (initialization_lambda0): time 48.47/133.3, allocations: 134 MB / 6.986 GB, free: 420.1 MB / 1.902 GB
Notification: Performance of solveInitialSystemEqSystem (initialization_lambda0): time 0.0005782/133.3, allocations: 92 kB / 6.986 GB, free: 420 MB / 1.902 GB
Notification: Performance of matching and sorting (n=17454) (initialization_lambda0): time 7.47/140.8, allocations: 191.1 MB / 7.172 GB, free: 232.3 MB / 1.902 GB
Notification: Performance of prepare postOptimizeDAE: time 0.0006134/140.8, allocations: 191.4 kB / 7.173 GB, free: 232.1 MB / 1.902 GB
Notification: Performance of postOpt simplifyComplexFunction (initialization): time 0.0007244/140.8, allocations: 349.2 kB / 7.173 GB, free: 231.7 MB / 1.902 GB
Notification: Performance of postOpt tearingSystem (initialization): time 0.01506/140.8, allocations: 6.702 MB / 7.18 GB, free: 225 MB / 1.902 GB
Notification: Performance of postOpt solveSimpleEquations (initialization): time 0.0259/140.8, allocations: 6.299 MB / 7.186 GB, free: 218.7 MB / 1.902 GB
Notification: Performance of postOpt calculateStrongComponentJacobians (initialization): time 0.01891/140.8, allocations: 13.3 MB / 7.199 GB, free: 205.4 MB / 1.902 GB
Notification: Performance of postOpt simplifyAllExpressions (initialization): time 0.06439/140.9, allocations: 2.234 MB / 7.201 GB, free: 203.1 MB / 1.902 GB
Notification: Performance of postOpt collapseArrayExpressions (initialization): time 0.006841/140.9, allocations: 1.693 MB / 7.202 GB, free: 201.4 MB / 1.902 GB
Notification: Model statistics after passing the back-end for initialization:

....

Notification: Performance of prepare postOptimizeDAE: time 0.01991/140.9, allocations: 7.775 MB / 7.21 GB, free: 193.8 MB / 1.902 GB
Notification: Performance of postOpt lateInlineFunction (simulation): time 0.02839/141, allocations: 9.541 MB / 7.219 GB, free: 184.2 MB / 1.902 GB
Notification: Performance of postOpt wrapFunctionCalls (simulation): time 9.768/150.7, allocations: 1.958 GB / 9.178 GB, free: 376.7 MB / 1.949 GB
Notification: Performance of postOpt inlineArrayEqn (simulation): time 0.0001349/150.7, allocations: 166.7 kB / 9.178 GB, free: 376.6 MB / 1.949 GB
Notification: Performance of postOpt constantLinearSystem (simulation): time 0.0001622/150.7, allocations: 29.05 kB / 9.178 GB, free: 376.5 MB / 1.949 GB
Notification: Performance of postOpt simplifysemiLinear (simulation): time 9.967/160.7, allocations: 1.946 GB / 11.12 GB, free: 0.6391 GB / 1.981 GB
Notification: Performance of postOpt removeSimpleEquations (simulation): time 9.318/170, allocations: 2.029 GB / 13.15 GB, free: 72.04 MB / 1.981 GB
Notification: Performance of postOpt simplifyComplexFunction (simulation): time 0.0001699/170, allocations: 29.14 kB / 13.15 GB, free: 72.01 MB / 1.981 GB
Notification: Performance of postOpt solveSimpleEquations (simulation): time 0.008187/170, allocations: 1.379 MB / 13.15 GB, free: 70.88 MB / 1.981 GB
Notification: Performance of postOpt tearingSystem (simulation): time 0.008473/170, allocations: 2.823 MB / 13.16 GB, free: 68.63 MB / 1.981 GB
Notification: Performance of postOpt inputDerivativesUsed (simulation): time 0.002261/170, allocations: 0.5717 MB / 13.16 GB, free: 68.23 MB / 1.981 GB
Notification: Performance of postOpt calculateStrongComponentJacobians (simulation): time 0.05608/170.1, allocations: 47.87 MB / 13.2 GB, free: 24.84 MB / 1.981 GB
Notification: Performance of postOpt calculateStateSetsJacobians (simulation): time 2.691e-05/170.1, allocations: 47.61 kB / 13.2 GB, free: 24.79 MB / 1.981 GB
Notification: Performance of postOpt symbolicJacobian (simulation): time 9.792/179.9, allocations: 2.002 GB / 15.21 GB, free: 268.5 MB / 1.996 GB
Notification: Performance of postOpt removeConstants (simulation): time 0.06139/179.9, allocations: 23.04 MB / 15.23 GB, free: 246.6 MB / 1.996 GB
Notification: Performance of postOpt simplifyTimeIndepFuncCalls (simulation): time 0.03303/180, allocations: 2.305 MB / 15.23 GB, free: 244.7 MB / 1.996 GB
Notification: Performance of postOpt simplifyAllExpressions (simulation): time 0.04917/180, allocations: 0.8645 MB / 15.23 GB, free: 244.2 MB / 1.996 GB
Notification: Performance of postOpt findZeroCrossings (simulation): time 0.003504/180, allocations: 1.05 MB / 15.23 GB, free: 243.5 MB / 1.996 GB
Notification: Performance of postOpt collapseArrayExpressions (simulation): time 0.002844/180, allocations: 0.8067 MB / 15.23 GB, free: 242.9 MB / 1.996 GB
Notification: Performance of sorting global known variables: time 0.3482/180.4, allocations: 152.2 MB / 15.38 GB, free: 99.57 MB / 1.996 GB
Notification: Performance of sort global known variables: time 1.058e-06/180.4, allocations: 1.219 kB / 15.38 GB, free: 99.57 MB / 1.996 GB
Notification: Performance of remove unused functions: time 0.1305/180.5, allocations: 28.93 MB / 15.41 GB, free: 70.82 MB / 1.996 GB

...

Notification: Performance of Backend phase and start with SimCode phase: time 0.01685/180.5, allocations: 6.964 MB / 15.42 GB, free: 64.74 MB / 1.996 GB
Notification: Performance of simCode: created initialization part: time 0.8997/181.4, allocations: 211.1 MB / 15.62 GB, free: 0.625 GB / 1.996 GB
Notification: Performance of simCode: created event and clocks part: time 4.954e-05/181.4, allocations: 14.75 kB / 15.62 GB, free: 0.625 GB / 1.996 GB
Notification: Performance of simCode: created simulation system equations: time 0.04697/181.5, allocations: 39.19 MB / 15.66 GB, free: 0.5937 GB / 1.996 GB
Notification: Performance of simCode: created of all other equations (e.g. parameter, nominal, assert, etc): time 0.1357/181.6, allocations: 16.14 MB / 15.68 GB, free: 0.5812 GB / 1.996 GB
Notification: Performance of simCode: created linear, non-linear and system jacobian parts: time 0.5775/182.2, allocations: 296 MB / 15.97 GB, free: 301.1 MB / 1.996 GB
Notification: Performance of simCode: some other stuff during SimCode phase: time 0.161/182.3, allocations: 65.26 MB / 16.03 GB, free: 235.7 MB / 1.996 GB
Notification: Performance of simCode: alias equations: time 0.1738/182.5, allocations: 75.4 MB / 16.11 GB, free: 160.3 MB / 1.996 GB
Notification: Performance of simCode: all other stuff during SimCode phase: time 0.02298/182.5, allocations: 3.597 MB / 16.11 GB, free: 156.7 MB / 1.996 GB
Notification: Performance of SimCode: time 1.29e-06/182.5, allocations: 0 / 16.11 GB, free: 156.7 MB / 1.996 GB
Notification: Performance of Templates: time 14.69/197.2, allocations: 1.105 GB / 17.21 GB, free: 475.3 MB / 1.997 GB
casella commented 5 months ago

@mwetter this could be due to the initial conditions not being fully specified, i.e., not enough fixed = true and/or initial equations to completely determine the initial values of states (both continuous and discrete) and fixed = false parameters.

In this case the tool apply some heuristics to identify additional variables to which fixed = true is applied. This is of course not portable across tools, that may legitimately apply different heuristics, hence leading to different initial conditions and simulation results.

This is what you see in Dymola in that case: immagine

and this is what you see in OMC: immagine

I suspect that the slow part is due to applying this heuristics, which however should be avoided by eventually providing all the initial conditions explicitly. Can you please check?

mwetter commented 5 months ago

@casella : This model has no unspecified initial conditions, but there are various conflicting start values and nominal values for temperature and specific enthalpy as Modelica.Units.SI.Temperature and Modelica.Media uses different defaults, and they differ from the start values used as default in the fluid volumes in Buildings. Not sure if this causes such large performance implications.

casella commented 5 months ago

I don't think so.

@phannebohm, @kabdelhak could you please profile analyzeInitialSystem (initialization) and analyzeInitialSystem (initialization_lambda0) and figure out where (most of) the time spent by the algorithm is?