Opened 5 years ago
Closed 5 years ago
#5771 closed defect (fixed)
Bogus CSE in power plant models using Modelica.Media
| Reported by: | Francesco Casella | Owned by: | Karim Adbdelhak |
|---|---|---|---|
| Priority: | high | Milestone: | 1.16.0 |
| Component: | Backend | Version: | |
| Keywords: | Cc: | Andreas Heuermann, giovanni.mangola@… |
Description
Please consider the attached test case. I ran it with the performance logger, and discovered several weird things that gobble up a lot of time.
The first one is the following assignment
(assign) fWPH_11_1.flowSTEAM.drdp[1] := if noEvent(Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).region == 3) then Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho * (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cv * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho + Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).pt) / (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho ^ 2.0 * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).pd * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cv + Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).T * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).pt ^ 2.0) else if noEvent(Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).region == 4) then Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho * (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cv / Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).dpT + 1.0) / (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).dpT * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).T) else (-Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho ^ 2.0) * (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).vp * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cp - Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).vt / Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho + Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).T * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).vt ^ 2.0) / Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cp
What I see here is many time the same function call with different field accessors, like f(a,b,c).x, f(a,b,c).y, f(a,b,c).z. I'm not sure what this notation exactly means, i.e., if this is a shorthand meaning that the function (returning a record) is only called once and then the record fields are only accessed, or if the function is actually called several times with the same arguments, each time taking one output and throwing away everything else.
However, I would expect the function Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0) to be called only once, the result stored in a $cse auxiliary variable and then the various field retrived from the $cse variable. Why isn't this happening? Can you please check?
Another weird thing is seeing these two assignments:
$cse45 := Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, fWPH_11_1.flowSTEAM.htilde[2], 0, 0); $cse33 := Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, fWPH_11_1.flowSTEAM.htilde[2], 0, 0);
Aren't $cse45 and $cse33 exactly the same?
I guess we have a lot of margin for improvement here :)
Attachments (3)
Change History (18)
by , 5 years ago
| Attachment: | TestTotal.mo added |
|---|
comment:1 by , 5 years ago
| Cc: | added |
|---|
by , 5 years ago
follow-ups: 3 4 comment:2 by , 5 years ago
comment:3 by , 5 years ago
Replying to Karim.Abdelhak:
You are right,
$cse33and$cse45should be the same. I am not quite sure why it is not detected, but it seems like this is the only case where this happens.
Confirmed. This should be solved but it's not critical, at least not for this test case.
follow-up: 5 comment:4 by , 5 years ago
Replying to Karim.Abdelhak:
This is done for every call seperately. I think our
$csemodule is just not capable to do these record things.
Why not?
I mean, Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0) has already been singled out as $cse31. Why don't we get $cse31.rho, $cse31.cp etc.?
This happens in other parts of this model, e.g.
345/347 (16): $cse54 = Modelica.Media.Water.IF97_Utilities.waterBaseProp_pT(fWPH_11_1.nusseltCondenser.p, fWPH_11_1.nusseltCondenser.Tc[2], 0) [unknown |0|0|0|0|] 318/320 (1): fWPH_11_1.nusseltCondenser.condensate_state[2].d = $cse54.rho [dynamic |0|0|0|0|] 319/321 (1): fWPH_11_1.nusseltCondenser.condensate_state[2].h = $cse54.h [dynamic |0|0|0|0|]
I assumed that once the preOpt function wrapFunctionCalls is executed, there should be no function calls left except in $cse definition equations. Maybe some of this function calls are expanded later in the pipeline and we need to call wrapFunctionCalls again at some other point.
Getting CSE on all these IF97_Utilities.waterBaseProp_ph function calls is essential for the efficient code generation of models using the water/steam model, i.e., pretty much all thermal power generation systems using a steam cycle. I thought we already had this feature since 2017, but it seems there are still a few corner cases left.
comment:5 by , 5 years ago
Replying to casella:
Replying to Karim.Abdelhak:
This is done for every call seperately. I think our
$csemodule is just not capable to do these record things.
Why not?
That is a very good question, right now i have no clue. I was not aware that it actually works on other functions. Is it possible that Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph has special properties which could prevent that? Is that function call maybe in a special context, like inside of another function? I will try to investigate that, do you have an idea for a minimal model where this happens?
EDIT: Maybe there is some problem with the ordering. I think it would be possible that in the case where it works the $cse was generated first and afterwards split up (or smth. like that). Maybe it does not work if we split first and than replace, does Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph have a special iniline tag?
comment:6 by , 5 years ago
waterBaseProp_ph and waterBaseProp_pT have a very similar structure and no annotations.
Those functions are always called inside other functions. In the case reported in this ticket, the outer function call is Medium.setState_ph(p, inStream(steam_in.h_outflow)). That calls setState_phX (which is inlined), which calls density_ph and temperature_ph (both inlined), which call IF97_Utilities.rho_ph and IF97_Utilities.T_ph (both inlined), which call T_props_ph and rho.props.ph, both late inlined, and both with a derivative annotation and with an argument calling the same waterBaseProp_ph with the same inputs.
Note that only waterBaseProp_ph is the function that does the actual work and return a record, the other higher-level functions basically select a variable of the record and return it, or possibly perform some basic computations like in the case reported in this ticket, using variables from the record.
The idea is that eventually you may have several functions calling waterBaseProp_ph with the same arguments, but you shouldn't worry about performance because they will be CSE'd out. Unless they aren't...
comment:7 by , 5 years ago
I also checked the -d=optdaedump ouptut. The wrapFunctionCalls method is indeed only called during the post-optimization, right after lateInlineFunction. After that step, $cse variables show up in the equation list. In some cases the waterBaseProp_ph function is called only once and then the fields from the $cse variable are used, in others the function is called multiple times.
The weird thing is that I actually found these equations in the dump after wrapFunctionCalls:
$cse31 = Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0) [unknown |0|0|0|0|] $cse45 = Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, fWPH_11_1.flowSTEAM.htilde[2], 0, 0) [unknown |0|0|0|0|] fWPH_11_1.flowSTEAM.drdp[1] = if noEvent(Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).region == 3) then Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho * (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cv * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho + Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).pt) / (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho ^ 2.0 * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).pd * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cv + Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).T * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).pt ^ 2.0) else if noEvent(Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).region == 4) then Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho * (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cv / Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).dpT + 1.0) / (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).dpT * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).T) else (-Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho ^ 2.0) * (Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).vp * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cp - Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).vt / Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).rho + Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).T * Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).vt ^ 2.0) / Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, STEAMin.h, 0, 0).cp [dynamic |0|0|0|0|] fWPH_11_1.flowSTEAM.drdp[3] = if noEvent($cse45.region == 3) then $cse45.rho * ($cse45.cv * $cse45.rho + $cse45.pt) / ($cse45.rho ^ 2.0 * $cse45.pd * $cse45.cv + $cse45.T * $cse45.pt ^ 2.0) else if noEvent($cse45.region == 4) then $cse45.rho * ($cse45.rho * $cse45.cv / $cse45.dpT + 1.0) / ($cse45.dpT * $cse45.T) else (-$cse45.rho ^ 2.0) * ($cse45.vp * $cse45.cp - $cse45.vt / $cse45.rho + $cse45.T * $cse45.vt ^ 2.0) / $cse45.cp [dynamic |0|0|0|0|]
The two cases look nearly identical, but while the second one is dealt with correctly, the first one is not.
The only difference is that the second input to the first waterBaseProp_ph function call is the parameter STEAMin.h, while the second input to the second waterBaseProp_ph function call is the state variable fWPH_11_1.flowSTEAM.htilde[2].
I'm not sure if this holds the key to understand why CSE is used in one case and not in the other, or if the wrapFunctionCalls algorithm just behaves erratically. Anyway, I hope this help you nailing down this nasty issue.
comment:8 by , 5 years ago
I found a fix with PR662. It seems like the problem was in the if expression. The then and else expression were not checked previously, i updated that. The function call Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph(fWPH_11_1.nusseltCondenser.p, fWPH_11_1.flowSTEAM.htilde[2], 0, 0) seems to appear somewhere else in the model and was therefore recognized and replaced. The replacement module was already capable of traversing if expressions.
Unfortunately it only made a small difference:
before: timeTotal = 9.883094420999999 after: timeTotal = 9.50874598
I guess the main problem is the one from #5770.
Hopefully the tests on PR662 run fine and i can just push it. Thank you for your initial work on identifying the problem Francesco!
comment:9 by , 5 years ago
I had to change PR662 a little bit. Processing the then and else expressions seems to cause issues. Instead i updated the handling of noEvent, in this case it also worked. I maybe have to look into that then and else case again.
It produced an even better time, but still not what we are aiming for:
timeTotal = 9.287706139000001
comment:10 by , 5 years ago
@Karim, can you run the test case with the profiler with --profiling=all and check what are the functions that gobble up the majority of the time? Please be aware that about half of the computational effort is spent during initialization.
comment:11 by , 5 years ago
I ran the test with --profiling= all and attached the result file. the PR is merged in the master you can also test some things if you like.
I don't really know how to efficiently scan this, but what i can see is that this seems to have the biggest impact:
{"name":"Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph","ncall":85933,"time":1.543558418,"maxTime":1.090899494},
comment:12 by , 5 years ago
I scanned it manually, here are the bottlenecks:
"Modelica.Media.Water.IF97_Utilities.waterBaseProp_ph","ncall":85933,"time":1.543558418
{"id":367,"ncall":116,"time":0.667294648,"maxTime":0.667358818},
{"id":1507,"ncall":134,"time":0.774191837,"maxTime":0.774266051},
{"id":1828,"ncall":59825,"time":2.506879379,"maxTime":0.057569746},
Now, waterBaseProp_ph is inevitably going to take some time in this kind of models. The question is, if 85933 calls are justified, since we have a fairly small model that is simulated in steady state. I guess these calls are caused by the block 1828, which is iterating a lot of times because of some yet unidentified issue.
I don't know what are the three blocks doing, but you can double-check easily and focus on optimizing them. The first two have very slow iterations, the third has too many iterations and we need to understand why.
comment:13 by , 5 years ago
We ran a test on a larger model that showed over six million calls to waterBaseProps_ph during initialization, taking 60 s whereby Dymola only takes 4. It seems that the fix was applied to regular equations only, which explains this performance degradation.
The fix should be applied to initial and initial-lambda0 equations as well.
@Karim will try to do that on 30-31 Jan.
comment:15 by , 5 years ago
| Resolution: | → fixed |
|---|---|
| Status: | new → closed |
I re-checked the results of CSE both on the simple and full examples, and I no longer see bogus duplicated $cse variables. The remaining issues are covered in #3921.
You are right,
$cse33and$cse45should be the same. I am not quite sure why it is not detected, but it seems like this is the only case where this happens. I posted the full$cselist underneath.The former problem is far more relevant i think, the way it is formulated it will indeed call the function several times. An example from the generated c-code:
This is done for every call seperately. I think our
$csemodule is just not capable to do these record things. I will try to come up with an easy model that does not work and try to fix it.