Here's plain text results from a ~7 minutes session with AI traffic (the VOR addings are when I changed range, it ended up at like 100 or something):
Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000209 s AddingsymboloftypeVORAddingsymboloftypeVORFound0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000181 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000213 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000190 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000177 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000163 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000178 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000185 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000184 s unknownvasi/papiconfiguration,count=1Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000184 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000162 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000168 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000168 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000191 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000190 s Found0TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000204 s Found1TrafficModel's inrangeout of2total.AddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.020064 s AddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORAddingsymboloftypeVORFound1TrafficModel's inrangeout of2total.MapStructureLayerUpdate:TFC--> 0.000521 s Found2TrafficModel's inrangeout of3total.AddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.001753 s Found2TrafficModel's inrangeout of3total.MapStructureLayerUpdate:TFC--> 0.000857 s Found2TrafficModel's inrangeout of3total.MapStructureLayerUpdate:TFC--> 0.000869 s Found2TrafficModel's inrangeout of3total.MapStructureLayerUpdate:TFC--> 0.000965 s DeletingsymboloftypeVORFound2TrafficModel's inrangeout of3total.MapStructureLayerUpdate:TFC--> 0.000846 s Found3TrafficModel's inrangeout of4total.AddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.001852 s DeletingsymboloftypeVORFound10TrafficModel's inrangeout of11total.AddingsymboloftypeTFCAddingsymboloftypeTFCAddingsymboloftypeTFCAddingsymboloftypeTFCAddingsymboloftypeTFCAddingsymboloftypeTFCAddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.017275 s Found14TrafficModel's inrangeout of15total.AddingsymboloftypeTFCAddingsymboloftypeTFCAddingsymboloftypeTFCAddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.009611 s Found15TrafficModel's inrangeout of16total.AddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.005657 s Found16TrafficModel's inrangeout of17total.AddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.008162 s Found18TrafficModel's inrangeout of19total.AddingsymboloftypeTFCAddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.008917 s Found19TrafficModel's inrangeout of20total.AddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.007914 s DeletingsymboloftypeVORFound19TrafficModel's inrangeout of20total.MapStructureLayerUpdate:TFC--> 0.006404 s Found19TrafficModel's inrangeout of20total.MapStructureLayerUpdate:TFC--> 0.006764 s Found21TrafficModel's inrangeout of22total.AddingsymboloftypeTFCAddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.011313 s Found21TrafficModel's inrangeout of22total.MapStructureLayerUpdate:TFC--> 0.007419 s Found22TrafficModel's inrangeout of23total.AddingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.009538 s Found1TrafficModel's inrangeout of23total.DeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCDeletingsymboloftypeTFCMapStructureLayerUpdate:TFC--> 0.002367 s DeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORDeletingsymboloftypeVORFound1TrafficModel's inrangeout of23total.MapStructureLayerUpdate:TFC--> 0.001452 s Found1TrafficModel's inrangeout of23total.MapStructureLayerUpdate:TFC--> 0.001557 s Found1TrafficModel's inrangeout of24total.MapStructureLayerUpdate:TFC--> 0.001645 s Found1TrafficModel's inrangeout of24total.MapStructureLayerUpdate:TFC--> 0.001520 s Found1TrafficModel's inrangeout of24total.MapStructureLayerUpdate:TFC--> 0.001702 s
So it's never getting over about 0.02 seconds, even when adding models - is that good enough?
Numbers as low as 18ms are obviously a no-brainer and not going to cause issues. But this is only measuring a certain part of the framework, I was also focused on SymbolLayer.Controller.update() so far - but I prepared the whole thing such that I can now add additional benchmarks by adding ~10 lines of Nasal code, as long as it's a Nasal class inside MapStructure.nas that is - i.e. some other potential hot spots are draw() routines in .symbol files, also searchCmd and positioned queries could be measured separately. What I have done is simply add a class that wraps callbacks in between two systime() statements and write things to the tree via setprop -so straightforward and extensible. Anyway, there's more going on here obviously - like I said elsewhere, performance is actually pretty good in "standalone" mode here, i.e. absent a 747/777 resource hog. But regardless of that, we're gonna have to look into using instanced symbols, i.e. caching - no matter if it's the existing texture-map based system, or something else that TheTom/Zakalawe come up with during the 3.2 release cycle. I have also asked TheTom to consider adding optional SGTimeStamp::now() based benchmarking to Canvas::Element, so that we can look right behind the scenes. And those positioned APIs are an obvious hot spot, too. --Hooray (talk) 19:24, 17 February 2014 (UTC)
This basically profiles a whole layer update from the Nasal side, including searchCmd/geo.PositonedDiff and adding/removing symbols the the property tree (dunno if the Canvas listeners trigger C++ changes there too). So this includes drawing callbacks - an honestly, I wouldn't expect any impact except for maybe SVG loading. And yeah, it definitely seems reasonable, and pretty steady - from about 1 ms at 2 models to about 8-18 at 40 models. The worse impact is from AI traffic subsystem! (During a run with the B-1B, that was clearly taking several times as much work as the other subsystems, according to the system monitor.) I'll also enable map-wide update benchmarking, see what numbers that brings. It will make it easier to see what caching and other optimizations bring. —Philosopher (talk) 20:18, 17 February 2014 (UTC)
I don't think we are going to over-optimize this. Typically, a range of ~50-100 nm will be set, with roughly 3-5 layers, each showing probably 20-30 symbols. Now,an aircraft will normally have two NDs - and given the generic nature of MapStructure layers, they may also be used in GUI dialogs (map-canvas), so realistically we may be having 3-5 "maps" running at most, each having about ~5 layers and maybe 50-100 symbols in total per map. So, supporting symbol-instancing would be a low-hanging fruit and worthwhile to investigate in my opinion, TheTom and Zakalawe also mentioned this several times - so it makes sense. SVG loading itself should only take place during initialization, if SVGs are currently loaded while running, something is wrong and is straightforward to optimize, even without using cached raster images stored in a texture map. BTW: For testing purposes, I'd suggest to use the route manager to set up a flight between several waypoints and then use the flight recorder to replay the whole thing afterwards - you can then use "time warp" to finish the test flight within just a few seconds, even without having the aircraft loaded; if in doubt, wrap the whole map.update() thing in between fgcommand("profiler-start") and you'll get a conclusive profile to see what's going on under the hood. Profiling-wise, I started to add a few more hooks - some will require C++ patches: supporting additional profiling hooks --Hooray (talk) 20:31, 17 February 2014 (UTC)
Units, ms, in "standalone" mode - and I even disabled the other canvases to make sure that there's no other Nasal code running having an impact here, so this is just a CanvasWidget GUI dialog updating a few layers. TFC is currently averaging ~30-40 ms here, but sometimes spiking up to 60-80 (with typically ~60 active TrafficModels/aircraft found), I was wondering if we should turn some of those TFC.lcontroller-temporaries into instance variables to see if that has any effect. Also, instead of removing objects, we could add old objects to a pool (vector of empty objects) and just update them later on, whereas pool size would be kept at ~150% of active objects - i.e. pseudo GC'ing. Once things are restructured accordingly, there should be very little going on in terms of alloc/realloc/free actually. However, I guess that the WPT/FIX lcontroller may be even more interesting in this aspect - i.e. reusing resources. --Hooray (talk) 20:52, 17 February 2014 (UTC)
The real question is just how constant these delays are - i.e. we want to have a constant frame spacing, and it should be as low as possible. A handful of layers could quickly slow down things ...
Currently, I am inclined to make the caching scheme a priority to help reduce "canvas pressure" by using instanced symbols, especially the "heavy" layers should benefit here (i.e. WPT/FIX), but also any conventional layer that's shown with a huge range (>=100nm). Splitting loops across frames would be another worthwhile consideration, but that would be better to look into if everything else fails - i.e. Nasal/C++ space optimizations of low-hanging fruits. We could also look into reducing "canvas pressure" by hiding elements rather than deleting them directly, so that deletion takes place at a later time - using a pseudo-scheduler that watches the frame spacing property and only runs certain jobs if the frame spacing is lower than ~30-50ms - possibly with a return-early option that makes sure that a certain max delay isn't exceeded.
