getElementAnnotation is very slow on Buildings models

[Francesco Casella]

Opening Buildings.Applications.DataCenters.ChillerCooled.Equipment.Validation.CoolingCoilHumidifyingHeating_ClosedLoop in OMEdit on my i7 laptop using the latest nightly build took about three minutes, which is unacceptably slow.

I picked the slowest API calls, which I report here

getElementAnnotations(Buildings.Fluid.Sources.BaseClasses.PartialSource_Xi_C) 19:57:19:001
{{Evaluate=true, HideResult=true, Dialog("Advanced","Parameters",true,false,false,-,-,-,-,"",false)},{Evaluate=true, HideResult=true, Dialog("General","Conditional inputs",true,false,false,-,-,-,-,"",false)},{Evaluate=true, HideResult=true, Dialog("General","Conditional inputs",true,false,false,-,-,-,-,"",false)},{Dialog("General","Fixed inputs",false,false,false,-,-,-,-,"",false)},{Dialog("General","Fixed inputs",false,false,false,-,-,-,-,"",false)},{Placement(true,-,-,-140.0,-60.0,-100.0,-20.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-140.0,-60.0,-100.0,-20.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-140.0,-100.0,-100.0,-60.0,-,-,-,-,-,-,-,)}} 19:57:23:582
#s#; 4.581000; 41.208000; 'getElementAnnotations(Buildings.Fluid.Sources.BaseClasses.PartialSource_Xi_C)'

getElementAnnotations(Buildings.Fluid.Sources.Boundary_pT) 19:57:23:604
{{Evaluate=true, HideResult=true, Dialog("General","Conditional inputs",true,false,false,-,-,-,-,"",false)},{Dialog("General","Fixed inputs",true,false,false,-,-,-,-,"",false)},{Evaluate=true, HideResult=true, Dialog("General","Conditional inputs",true,false,false,-,-,-,-,"",false)},{Dialog("General","Fixed inputs",true,false,false,-,-,-,-,"",false)},{Placement(true,-,-,-140.0,60.0,-100.0,100.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-140.0,20.0,-100.0,60.0,-,-,-,-,-,-,-,)},{},{},{},{}} 19:57:28:052
#s#; 4.448000; 45.661000; 'getElementAnnotations(Buildings.Fluid.Sources.Boundary_pT)'

getElementAnnotations(Buildings.Fluid.FixedResistances.PressureDrop) 19:57:28:259
{{Evaluate=true, Dialog("General","Transition to laminar",true,false,false,-,-,-,-,"",false)},{},{Evaluate=true},{}} 19:57:32:916
#s#; 4.656000; 50.431000; 'getElementAnnotations(Buildings.Fluid.FixedResistances.PressureDrop)'

getElementAnnotations(Buildings.Fluid.Sensors.TemperatureTwoPort) 19:57:34:153
{{Placement(true,0.0,110.0,10.0,-10.0,-10.0,10.0,270.0,-,-,-,-,-,-,)},{Dialog("General","Initialization",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("General","Heat transfer",true,false,false,-,-,-,-,"",false)},{Dialog("General","Heat transfer",false,false,false,-,-,-,-,"",false)},{Dialog("General","Heat transfer",false,false,false,-,-,-,-,"",false)},{},{},{},{},{}} 19:57:38:850
#s#; 4.697000; 56.206000; 'getElementAnnotations(Buildings.Fluid.Sensors.TemperatureTwoPort)'

getElementAnnotations(Buildings.Applications.DataCenters.ChillerCooled.Equipment.BaseClasses.PartialCoolingCoilHumidifyingHeating) 19:57:41:186
{{HideResult=true},{Dialog("Heat transfer","Cooling coil",true,false,false,-,-,-,-,"",false)},{Dialog("Heat transfer","Cooling coil",true,false,false,-,-,-,-,"",false)},{Dialog("Heat transfer","Cooling coil",true,false,false,-,-,-,-,"",false)},{Dialog("Heat transfer","Cooling coil",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog(error)},{Dialog(error)},{Dialog(error)},{Dialog("General","Valve",true,false,false,-,-,-,-,"",false)},{Dialog("General","Valve",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Valve",true,false,false,-,-,-,-,"",false)},{Dialog(error)},{Dialog(error)},{Dialog(error)},{Dialog("General","Fan",true,false,false,-,-,-,-,"",false)},{Dialog("General","Fan",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Fan",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Fan",true,false,false,-,-,-,-,"",false)},{Dialog(error)},{Dialog(error)},{Dialog(error)},{Placement(true,-,-,-80.0,80.0,-60.0,100.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-140.0,10.0,-100.0,50.0,-,-,-,-120.0,30.0,-100.0,50.0,)},{Placement(true,-,-,-140.0,-70.0,-100.0,-30.0,-,-,-,-120.0,-50.0,-100.0,-30.0,)},{Placement(true,-20.0,-110.0,-10.0,-10.0,10.0,10.0,-90.0,-,-,-,-,-,-,)},{Placement(true,-,-,100.0,30.0,120.0,50.0,-,-,-,100.0,30.0,120.0,50.0,)},{Placement(true,-,-,-140.0,-70.0,-100.0,-30.0,-,-,-,-120.0,-50.0,-100.0,-30.0,)},{Placement(true,-,-,60.0,-64.0,80.0,-44.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-50.0,-70.0,-70.0,-50.0,-,-,-,-,-,-,-,)},{Placement(true,80.0,-10.0,10.0,10.0,-10.0,-10.0,270.0,-,-,-,-,-,-,)}} 19:59:01:937
#s#; 80.751000; 139.084000; 'getElementAnnotations(Buildings.Applications.DataCenters.ChillerCooled.Equipment.BaseClasses.PartialCoolingCoilHumidifyingHeating)'

getElementAnnotations(Buildings.Fluid.HeatExchangers.DryCoilCounterFlow) 19:59:03:052
{{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("General","Geometry",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("Heat transfer","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Heat transfer","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Heat transfer","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Heat transfer","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Experimental","Parameters",true,false,false,-,-,-,-,"",false)},{},{},{},{},{},{Placement(true,-,-,-60.0,70.0,-40.0,90.0,-,-,-,-,-,-,-,)},{Evaluate=true},{Evaluate=true},{Placement(true,-,-,-58.0,54.0,-46.0,66.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-80.0,54.0,-68.0,66.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,58.0,-66.0,44.0,-54.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,82.0,-66.0,70.0,-54.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-18.0,84.0,-6.0,96.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-18.0,62.0,-6.0,74.0,-,-,-,-,-,-,-,)},{},{Placement(true,-,-,0.0,0.0,20.0,20.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,4.0,82.0,18.0,98.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,4.0,60.0,18.0,76.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-80.0,78.0,-66.0,88.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-80.0,72.0,-66.0,82.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,0.0,34.0,20.0,54.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,20.0,-40.0,0.0,-20.0,-,-,-,-,-,-,-,)}} 19:59:10:231
#s#; 7.178000; 147.267000; 'getElementAnnotations(Buildings.Fluid.HeatExchangers.DryCoilCounterFlow)'

getElementAnnotations(Buildings.Fluid.Interfaces.FourPortHeatMassExchanger) 19:59:10:469
{{HideResult=true},{Dialog("Dynamics","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Nominal condition",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 1",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 1",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 1",false,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 1",false,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 1",false,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 2",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 2",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 2",false,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 2",false,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Medium 2",false,false,false,-,-,-,-,"",false)},{},{},{Placement(true,-,-,-10.0,70.0,10.0,50.0,-,-,-,-,-,-,-,)},{Placement(true,2.0,-60.0,-10.0,10.0,10.0,-10.0,180.0,-,-,-,-,-,-,)},{Placement(true,-,-,-80.0,70.0,-60.0,90.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,80.0,-90.0,60.0,-70.0,-,-,-,-,-,-,-,)},{},{},{},{},{},{},{},{}} 19:59:15:935
#s#; 5.465000; 152.870000; 'getElementAnnotations(Buildings.Fluid.Interfaces.FourPortHeatMassExchanger)'

getElementAnnotations(Buildings.Fluid.Interfaces.LumpedVolumeDeclarations) 19:59:15:996
{{choices(error)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",false,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",false,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",false,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Parameters",true,false,false,-,-,-,-,"",false)}} 19:59:20:542
#s#; 4.546000; 157.446000; 'getElementAnnotations(Buildings.Fluid.Interfaces.LumpedVolumeDeclarations)'

getElementAnnotations(Buildings.Fluid.HeatExchangers.BaseClasses.PartialHexElement) 19:59:21:165
{{HideResult=true, Evaluate=true, Dialog("Advanced","Parameters",true,false,false,-,-,-,-,"",false)},{HideResult=true, Evaluate=true, Dialog("Advanced","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{},{Placement(true,-40.0,100.0,-20.0,-20.0,20.0,20.0,270.0,-,-,-,-,-,-,)},{Placement(true,40.0,-100.0,-20.0,-20.0,20.0,20.0,90.0,-,-,-,-,-,-,)},{Placement(true,-82.0,0.0,-10.0,-10.0,10.0,10.0,90.0,-,-,-,-,-,-,)},{Placement(true,-,-,-50.0,50.0,-30.0,70.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-50.0,-30.0,-30.0,-50.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-10.0,90.0,10.0,110.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-10.0,-110.0,10.0,-90.0,-,-,-,-,-,-,-,)}} 19:59:26:833
#s#; 5.668000; 163.471000; 'getElementAnnotations(Buildings.Fluid.HeatExchangers.BaseClasses.PartialHexElement)'

getElementAnnotations(Buildings.Fluid.Movers.BaseClasses.PartialFlowMachine) 19:59:27:254
{{choicesAllMatching=true, Placement(true,-,-,52.0,60.0,72.0,80.0,-,-,-,-,-,-,-,)},{Dialog("General","Control",true,false,false,-,-,-,-,"",false)},{Dialog("General","Control",false,false,false,-,-,-,-,"",false)},{Dialog("General","Control",false,false,false,-,-,-,-,"",false)},{},{},{},{Dialog("Dynamics","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Filtered speed",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Filtered speed",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Filtered speed",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Filtered speed",true,false,false,-,-,-,-,"",false)},{Placement(true,0.0,120.0,-20.0,-20.0,20.0,20.0,270.0,-,-,-,-,-,-,)},{Placement(true,-,-,100.0,60.0,120.0,80.0,-,-,-,100.0,60.0,120.0,80.0,)},{Placement(true,-,-,100.0,80.0,120.0,100.0,-,-,-,100.0,80.0,120.0,100.0,)},{Placement(true,-,-,-70.0,-110.0,-50.0,-90.0,-,-,-,-10.0,-78.0,10.0,-58.0,)},{},{},{},{},{},{},{},{},{Evaluate=true},{},{},{},{},{},{Placement(true,-,-,-80.0,40.0,-60.0,60.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-80.0,70.0,-60.0,90.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-50.0,60.0,-30.0,40.0,-,-,-,-,-,-,-,)},{Placement(true,-10.0,50.0,-10.0,-10.0,10.0,10.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-70.0,0.0,-90.0,20.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,20.0,81.0,34.0,95.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-4.0,74.0,-16.0,86.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,40.0,-10.0,60.0,10.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,20.0,-80.0,40.0,-60.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,50.0,-90.0,70.0,-70.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-14.0,-104.0,-34.0,-84.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-90.0,-74.0,-70.0,-54.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-50.0,10.0,-30.0,-10.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,58.0,-27.0,43.0,-14.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,-32.0,-68.0,-12.0,-48.0,-,-,-,-,-,-,-,)}} 19:59:32:500
#s#; 5.246000; 168.907000; 'getElementAnnotations(Buildings.Fluid.Movers.BaseClasses.PartialFlowMachine)'

getElementAnnotations(Buildings.Applications.DataCenters.ChillerCooled.Equipment.CoolingCoilHumidifyingHeating) 19:59:35:056
{{Dialog("General","Valve",true,false,false,-,-,-,-,"",false)},{Dialog("General","Valve",true,false,false,-,-,-,-,"",false)},{Dialog(error)},{Dialog("General","Electric heater",true,false,false,-,-,-,-,"",false)},{Dialog("General","Electric heater",true,false,false,-,-,-,-,"",false)},{Dialog("General","Humidifier",true,false,false,-,-,-,-,"",false)},{Dialog("General","Humidifier",true,false,false,-,-,-,-,"",false)},{Dialog(error)},{},{},{},{},{},{Placement(true,18.0,-110.0,-10.0,-10.0,10.0,10.0,-90.0,-,-,-,-,-,-,)},{Placement(true,-,-,-140.0,-40.0,-100.0,0.0,-,-,-,-120.0,-20.0,-100.0,0.0,)},{Placement(true,-,-,-140.0,-20.0,-100.0,20.0,-,-,-,-120.0,0.0,-100.0,20.0,)},{Placement(true,-,-,-60.0,-4.0,-40.0,16.0,-,-,-,-,-,-,-,)},{Placement(true,20.0,-60.0,-10.0,10.0,10.0,-10.0,180.0,-,-,-,-,-,-,)},{Placement(true,-22.0,-60.0,10.0,-10.0,-10.0,10.0,-,-,-,-,-,-,-,)},{Placement(true,-10.0,10.0,-10.0,-10.0,10.0,10.0,-,-,-,-,-,-,-,)},{}} 19:59:54:097
#s#; 19.041000; 190.100000; 'getElementAnnotations(Buildings.Applications.DataCenters.ChillerCooled.Equipment.CoolingCoilHumidifyingHeating)'

getElementAnnotations(Buildings.Fluid.Interfaces.PrescribedOutlet) 19:59:55:012
{{Evaluate=true, Dialog("General","Parameters",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("General","Parameters",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("General","Parameters",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("General","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("General","Nominal condition",true,false,false,-,-,-,-,"",false)},{Dialog("Dynamics","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",true,false,false,-,-,-,-,"",false)},{Dialog("Initialization","Parameters",false,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Evaluate=true, Dialog("Dynamics","Equations",true,false,false,-,-,-,-,"",false)},{Evaluate=true},{Evaluate=true},{Placement(true,-120.0,90.0,20.0,-20.0,-20.0,20.0,180.0,-110.0,80.0,10.0,-10.0,-10.0,10.0,180.0)},{Placement(true,-120.0,50.0,20.0,-20.0,-20.0,20.0,180.0,-110.0,40.0,10.0,-10.0,-10.0,10.0,180.0)},{Placement(true,-,-,100.0,70.0,120.0,90.0,-,-,-,-,-,-,-,)},{Placement(true,-,-,100.0,30.0,120.0,50.0,-,-,-,-,-,-,-,)},{},{Evaluate=true},{Evaluate=true},{Evaluate=true},{Evaluate=true},{},{},{},{},{},{},{},{},{},{},{},{},{},{},{}} 19:59:59:753
#s#; 4.741000; 195.689000; 'getElementAnnotations(Buildings.Fluid.Interfaces.PrescribedOutlet)'

One call takes 80 seconds, and the next eleven take another minute or so.

This should be drastically improved to make the Buildings library usable in OMEdit

[Francesco Casella]

Ticket retargeted after milestone closed

[Per Östlund]

The issue here seems to be that the nfAPI wasn't used. It takes about 3 seconds to process the 12 getElementAnnotations-calls on my machine with -d=nfAPI, compared to about 80 seconds with the old frontend.

There's certainly room for improvement still, but making sure the nfAPI is used should at least be a massive step in the right direction. I'm not sure what the situation with the nfAPI is though.

[Francesco Casella]

I'm not sure if I had nfAPI enabled in OMEdit when I opened this ticket. I now do, I just retried, and it took about 20 s to open the diagram. Better than 80, but still quite annoying. Particularly because you don't have any kind of feedback, you see the hourglass turning, and it could be another 5 seconds or 5 minutes, no way to tell until it's over.

BTW, the first time I tried I didn't get any feedback for over 4 minutes, then I terminated OMEdit and restarted from scratch, to get it done in 20 s. It looks like memory management and memory fragmentation play a significant role.

Bottome line: we don't need orders of magnitude of improvement for this ticket, but a factor 4 would be really nice.

Regarding nfAPI, it was introduced as optional, and off by default. When you install a new version, you carry on the old settings. Except for some feature that @adeas31 has set on by default in 1.17.0, I don't remember exactly which ones. Maybe we should do it also for nfAPI?

[Per Östlund]

I improved the performance in ​#7906.

The issue now is not so much that individual API calls are slow, but that OMEdit makes around 2700 API calls when opening the model. About 1200 of these are

errors:=getMessagesStringInternal();
size(errors,1);

that's used to fetch any messages that occurred during the previous API call, and this takes about 6-7 ms each time for some reason.

Changing this to use countMessages() to first check if there are even any messages to fetch brings the time to open the model from 7.5s down to 4.6s for me. Removing the check completely shaves off another second, so there's still some room for improvement there.

Improving the time further will require either reducing the number of API calls that OMEdit makes, or speeding up the API in general.

[Per Östlund]

I forgot that I also improved getInheritedClasses unrelated to this ticket, without that fix it takes about 12.3s to open the model. So with both fixes that's a speedup of a factor of about 2.7, which is not quite 4 but maybe good enough for now?

[Per Östlund]

adeas31 informed me that countMessages can be called through the OMC interface instead of using sendCommand, which I've implemented in ​#7907. This almost shaves of the second I mentioned earlier, bringing the time down to 3.7s for me.

[Francesco Casella]

@perost, when I originally opened this ticket I had to wait for three minutes, which was simply unacceptable. After half a minute or so, most people would think that OMEdit just hanged, kill the process, and get generally annoyed by the tool.

Now, 3.7 s is not super-fast, but definitely ok for normal use. Most people would not find this upsetting.

We are planning to continue the work with LBL next year with a focus on performance, we may want to further improve the GUI responsiveness at that point. For the time being this performance looks good to me.

@mwetter, you may check this with the next nightly build and add comments on the ​mirror ticket on GitHub, this one is only open for developers.