Board index FlightGear Development Nasal

Nasal Callback tracking (timers & listeners)

Nasal is the scripting language of FlightGear.

Nasal Callback tracking (timers & listeners)

Postby Hooray » Tue Feb 02, 2016 2:04 pm

http://sourceforge.net/p/flightgear/mai ... /34810857/
Thorsten wrote:it's relatively easy to do bad things
unintentionally. Like tie a bit of code to an FDM property and run updates
of a display 120 times per second rather than the 30 times you actually
need. Like start a loop multiple times so that you update the same
property 30 times per frame rather than the one time you actually need.

It's actually pretty hard to catch these things, because the code is
formally okay, does the right thing and just eats more performance than
necessary, and there's no simple output telling you that you're running 30
loops rather than the one you expect. The only way I've found is to clock
down loops and print to console inside them - when you clock them per
second and see 30 messages printed each second, you know that something is
afoot...

So it's really not impossible to come up with aircraft Nasal that ends up
using a hundred times more performance than it has to. Unfortunately,
better CPU utilization is not really the way to attack these problems
though....


given that this obviously a recurring problem, I was wondering what we could do abot this - so I started prototyping a Nasal/Canvas-based UI to for displaying active Nasal callbacks (i.e. timers & listeners).

And I think it would be a good idea to gather some feedback to determine what kind of data would be useful and how it should be ideally represented - obviously, the screenshot below is not much more than a mockup (well, it is working Nasal code, just the data that is shown is arbitrary) - but otherwise, exposing the SGEventMgr logic at the Nasal level to provide a list of active events, including their callbacks (and location in Nasal code, i.e. filename and line number) is relatively straightforward.

So what else do we need to come up with an intuitive "task monitor" that shows Nasal callbacks registered in the form of timers and callbacks ?

Should we differentiate between aircraft and scenery code, between different sub-modules ? Technically, that would be possible to do, because we will need to patch some C++ code anyway - i.e. roughly 50-100 lines of code in both SG and FG will need to be touched to expose the SGEventMgr queues to scripting space (or even just in the form of live properties that are updated each frame)


http://wiki.flightgear.org/Howto:Troubl ... _Callbacks
Image
Please don't send support requests by PM, instead post your questions on the forum so that all users can contribute and benefit
Thanks & all the best,
Hooray
Help write next month's newsletter !
pui2canvas | MapStructure | Canvas Development | Programming resources
Hooray
 
Posts: 11317
Joined: Tue Mar 25, 2008 8:40 am

Re: Nasal Callback tracking (timers & listeners)

Postby Johan G » Sat Feb 06, 2016 4:52 pm

Considering that Thorsten is one of the more experienced Nasal coders, one for sure can wonder about the mess an inexperienced coder may cause.
Low-level flying — It's all fun and games till someone looses an engine. (Paraphrased from a YouTube video)
Improving the Dassault Mirage F1 (Wiki, Forum, GitLab. Work in slow progress)
Johan G
Moderator
 
Posts: 5437
Joined: Fri Aug 06, 2010 5:33 pm
Location: Sweden
Callsign: SE-JG
IRC name: Johan_G
Version: 3.0.0
OS: Windows 7, 32 bit

Re: Nasal Callback tracking (timers & listeners)

Postby Thorsten » Sat Feb 06, 2016 5:24 pm

Nice one!

I think the information condensed is how often we really run a particular function per frame - say how often did XXX_loop() get called via a settimer/ maketimer/ ... every frame?

one for sure can wonder about the mess an inexperienced coder may cause.


Plenty possibly - but it may take a while to show up. I suspect this is behind aircraft performance deteriorating steadily over a few hours.
Thorsten
 
Posts: 10635
Joined: Mon Nov 02, 2009 8:33 am

Re: Nasal Callback tracking (timers & listeners)

Postby Hooray » Sat Feb 06, 2016 5:38 pm

We cannot really/easily identify "loops" per se - i.e. as far as I remember (Philosopher may correct me if I am wrong), we have to use what's available via die(), aka naRuntimeError, which really only provides 1) filename/path and 2) line number.

However, this can be used to build a list of "active callbacks" that can be associated with their "origin", i.e. where the callback was registered to be invoked via settimer()/maketimer() or setlistener().

The main issue here is that callback "identify" (aka what's provided by the Nasal id() API) may not be too informative when used in conjunction with anonymous functions in the form of:

Code: Select all
settimer( func() {}, 1.0 );


What's available in C++ space are primarily: the event manager subsystem (SGEventMgr) which has two internal "queues" for keeping a list of callbacks that shall be invoked when a certain event (timeout) happens, as well as the property tree interface to register Nasal callbacks via the SGPropertyChangeListener API:

http://api-docs.freeflightsim.org/simge ... ntMgr.html
http://api-docs.freeflightsim.org/simge ... tener.html

At that point, all we have access to is C++ pointers, and pointers to Nasal data structures representing a function, so the best we can currently do is probably logging filename/line number per timer/listener and provide a list of those.

Invocation is a different matter, i.e. we could maintain a counter for each known callback (C/C++ pointer) and reset/increment that per frame to actually determine how often a certain callback is actually invoked per frame/second/minute, analogous to the performance monitor.

From a representation perspective, my suggestion would be to highlight per-frame callbacks in yellow, and everything that gets updated several times per frame (think FDM/AP-coupled coode) would be shown in red.

Doing that will inevitably require patches to the SG/FG side of FGNasalSys, though. But the UI could be coded in Nasal itself, i.e. using the Canvas system.

Equally, it might make sense to gather a total of timers/listeners at different stages of the initialization sequence, i.e. how loading/unloading scenery/aircraft affects the global count of listeners/timers, and how many of those are actually pointing to C++ code vs. Nasal callbacks, and how that is affected by reset/re-init.

Like you say, this is one of the more likely reasons for Nasal performance affecting the main simulation loop, probably even more so than the Nasal GC itself...
Please don't send support requests by PM, instead post your questions on the forum so that all users can contribute and benefit
Thanks & all the best,
Hooray
Help write next month's newsletter !
pui2canvas | MapStructure | Canvas Development | Programming resources
Hooray
 
Posts: 11317
Joined: Tue Mar 25, 2008 8:40 am

Re: Nasal Callback tracking (timers & listeners)

Postby Hooray » Sat Feb 13, 2016 9:38 pm

I have added a section to the wiki article illustrating how to track settimer() registrations using a simple patch (in fact, 5 lines of code) - whenever a callback is registered to be invoked via settimer(), you will get a notification - in addition, the name of the event added to the event manager is augmented using the file name and the line number of the settimer() call, so that callbacks can be tracked more easily (in conjunction with the simgear patch shown in the same article) : http://wiki.flightgear.org/Howto:Exposi ... FlightGear

Next, it would make sense to look at Thorsten's suggestion, i.e. maintaining a counter per callback (and per frame) to track the number of registrations, and invocations/calls, per frame/second/minute (possibly including the duration of the call).

You will be getting notifications in the form of:

Code: Select all
== Inserting timer into queue    type:NasalTimer: $FG_ROOT/Nasal/screen.nas via line:116
         interval:1e-06
         delay:1e-06
         repeated:0
         simtime/realtime:0/1

Total Entries in queues
         simtime queue:7
         realtime queue:5

== Inserting timer into queue    type:NasalTimer: $FG_ROOT/Nasal/screen.nas via line:172
         interval:1e-06
         delay:10
         repeated:0
         simtime/realtime:0/1

Total Entries in queues
         simtime queue:7
         realtime queue:5



In its current form, it's just proof-of-concept, but it should be easy to extend once we have collected a few requirements/useful additions.
Please don't send support requests by PM, instead post your questions on the forum so that all users can contribute and benefit
Thanks & all the best,
Hooray
Help write next month's newsletter !
pui2canvas | MapStructure | Canvas Development | Programming resources
Hooray
 
Posts: 11317
Joined: Tue Mar 25, 2008 8:40 am


Return to Nasal

Who is online

Users browsing this forum: No registered users and 0 guests