Talk:MapStructure Debugger

From FlightGear wiki
Revision as of 12:47, 19 February 2014 by Hooray (talk | contribs) (→‎Supporting reload() (symbol/scontroller/lcontroller): moved to Talk:MapStructure)
(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)
Jump to navigation Jump to search

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): 

Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000209 s 
Adding symbol of type VOR
Adding symbol of type VOR
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000181 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000213 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000190 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000177 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000163 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000178 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000185 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000184 s 
unknown vasi/papi configuration, count = 1
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000184 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000162 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000168 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000168 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000191 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000190 s 
Found 0 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000204 s 
Found 1 TrafficModel's in range out of 2 total.
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.020064 s 
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Adding symbol of type VOR
Found 1 TrafficModel's in range out of 2 total.
 MapStructure Layer Update: TFC --> 0.000521 s 
Found 2 TrafficModel's in range out of 3 total.
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.001753 s 
Found 2 TrafficModel's in range out of 3 total.
 MapStructure Layer Update: TFC --> 0.000857 s 
Found 2 TrafficModel's in range out of 3 total.
 MapStructure Layer Update: TFC --> 0.000869 s 
Found 2 TrafficModel's in range out of 3 total.
 MapStructure Layer Update: TFC --> 0.000965 s 
Deleting symbol of type VOR
Found 2 TrafficModel's in range out of 3 total.
 MapStructure Layer Update: TFC --> 0.000846 s 
Found 3 TrafficModel's in range out of 4 total.
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.001852 s 
Deleting symbol of type VOR
Found 10 TrafficModel's in range out of 11 total.
Adding symbol of type TFC
Adding symbol of type TFC
Adding symbol of type TFC
Adding symbol of type TFC
Adding symbol of type TFC
Adding symbol of type TFC
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.017275 s 
Found 14 TrafficModel's in range out of 15 total.
Adding symbol of type TFC
Adding symbol of type TFC
Adding symbol of type TFC
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.009611 s 
Found 15 TrafficModel's in range out of 16 total.
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.005657 s 
Found 16 TrafficModel's in range out of 17 total.
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.008162 s 
Found 18 TrafficModel's in range out of 19 total.
Adding symbol of type TFC
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.008917 s 
Found 19 TrafficModel's in range out of 20 total.
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.007914 s 
Deleting symbol of type VOR
Found 19 TrafficModel's in range out of 20 total.
 MapStructure Layer Update: TFC --> 0.006404 s 
Found 19 TrafficModel's in range out of 20 total.
 MapStructure Layer Update: TFC --> 0.006764 s 
Found 21 TrafficModel's in range out of 22 total.
Adding symbol of type TFC
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.011313 s 
Found 21 TrafficModel's in range out of 22 total.
 MapStructure Layer Update: TFC --> 0.007419 s 
Found 22 TrafficModel's in range out of 23 total.
Adding symbol of type TFC
 MapStructure Layer Update: TFC --> 0.009538 s 
Found 1 TrafficModel's in range out of 23 total.
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
Deleting symbol of type TFC
 MapStructure Layer Update: TFC --> 0.002367 s 
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Deleting symbol of type VOR
Found 1 TrafficModel's in range out of 23 total.
 MapStructure Layer Update: TFC --> 0.001452 s 
Found 1 TrafficModel's in range out of 23 total.
 MapStructure Layer Update: TFC --> 0.001557 s 
Found 1 TrafficModel's in range out of 24 total.
 MapStructure Layer Update: TFC --> 0.001645 s 
Found 1 TrafficModel's in range out of 24 total.
 MapStructure Layer Update: TFC --> 0.001520 s 
Found 1 TrafficModel's in range out of 24 total.
 MapStructure Layer Update: 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 ... 

TFC delay:23.06604385375977
DME delay:1.358985900878906
APT delay:47.28198051452637
FIX delay:51.3308048248291
Found 44 TrafficModel's
TFC delay:39.58392143249512
DME delay:1.332044601440429
APT delay:29.22606468200684
FIX delay:33.18905830383301
Found 44 TrafficModel's
TFC delay:62.96110153198242
DME delay:1.390933990478516
APT delay:30.07316589355469
FIX delay:19.70100402832031
Found 44 TrafficModel's
TFC delay:63.38596343994141
DME delay:1.38401985168457
APT delay:31.27121925354004
FIX delay:20.53499221801758
Found 44 TrafficModel's
TFC delay:22.25899696350098
DME delay:1.428127288818359
APT delay:58.71295928955078
FIX delay:34.88421440124512
Found 44 TrafficModel's
TFC delay:23.15378189086914
DME delay:1.250028610229492
APT delay:44.56496238708496
FIX delay:52.22082138061523
Found 44 TrafficModel's
TFC delay:37.63604164123535
DME delay:1.50299072265625
APT delay:32.56201744079589
FIX delay:33.63895416259766
Found 44 TrafficModel's
TFC delay:56.96201324462891
DME delay:1.379013061523438
APT delay:30.82108497619629
FIX delay:20.88594436645508
Found 44 TrafficModel's
TFC delay:37.63890266418457
DME delay:1.370906829833984
APT delay:31.63003921508789
FIX delay:21.68798446655273
Found 44 TrafficModel's

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.

Retrieved from "https://wiki.flightgear.org/w/index.php?title=Talk:MapStructure_Debugger&oldid=67854"