Nasal Events

Summary

• Nasal code is often developed by people who are not primarily software developers
• Often, people end up instantiating multiple loops/callbacks accidently, without really noticing it on fast systems
• In addition, the simulator may instantiate multiple callback instances through signals (i.e. during reset/relocating)
• Multiple rogue Nasal callback instances invoked through timers or listeners may considerably slow down the simulator and require a complete restart on some systems
• This issue is currently very hard to detect, because we only have a single "events" subsystem that shows up in the system monitor
• The system monitor does not provide any info about the number of callbacks, or their nature/origin
• The overhead caused by Nasal callbacks run as through listeners or timers cannot currently be tracked easily or reliably
• end users and aircraft developers would prefer having some form of "process monitor" or watchdog for Nasal processes [1]
• We have currently no way to directly instantiate "singleton callbacks" to make the API more fool-proof
• Furthermore, it would make sense to automatically release/restart certain timers depending on their scope/lifetime (animations, instruments, cockpit, aircraft-reset, environment/weather, GUI reset, I/O reset etc)
• given the plethora of features implemented with Nasal scripting, we need to have a standardized way to categorize callbacks, so that systems can be safely reset to a well-defined state
• Basically, timers could be registered with a scope-specific context, so that timers for different purposes would be stored in categories, so that all timers in a group can be safely shut down, and restarted (imagine restarting the GUI, changing the position, resetting the whole sim or changing the active aircraft) - we would ideally want to be able to maintain callbacks for timers/listeners in corresponding groups, so that other callbacks are not affected
• Addressing this issue, would also make it much more feasible to support resetting the Nasal interpreter and reload scripts, because previously running code could be safely shut down.
• more complex scripts (bombable, local weather, aircraft like the concorde) usually end up implementing their own "scheduler" on top of settimer() - this should be recognized, and a generic schedule facility provided that addresses the shortcomings and challenges presented here
• The new maketimer() API could be extended accordingly

Objective

• Introduce an additional, dedicated "nasal-events" subsystem, that handles just Nasal events - so that the system monitor output is meaningful
• Store meta information for each registered timer (namespace/module, file name, line number)
• extend the new maketimer() API
  • support singleton timers that may only be invoked once
  • register callbacks for timer instantiation/cleanup (ctor/dtor)
  • provide an option to automatically stop timers based on listeners (i.e. /sim/reset)
  • register different types of timers for various scopes (aircraft-session, gui-timer etc)

Background

I noticed an ugly issue with many of our Nasal modules. Not sure if that's a result of changed behaviour years ago, or it's just a common copy & paste issue that just wasn't noticed so far. Problem is, lot's of Nasal modules listen to the property /sim/signals/fdm-initialized to trigger some initialization code. It's fine to do so. However, modules need to be aware that this signal triggers on _every_ simulator reset. So, the connected code executes every time you hit Shift-ESC, use the "Relocate-in-air" or "Relocate-on-ground" dialogs. We had plenty of places were init code connected to "/sim/signals/fdm-initialized" installed a fresh set of listeners or started another timer-driven update loop. This results in performance degrading with every sim reset. — ThorstenB

the main purpose of the event manager is to handle Nasal's settimer() code. So you better look for slow recurring Nasal code. — Melchior FRANZ

Any Nasal timer, even if it's almost empty, will every now and then consume a much larger amount of time than normal. Seems to be a general issue with the Nasal execution engine: could be triggered by Nasal's garbage collector, which every now and then needs to do extra work - and runs within the context of a normal Nasal call. It could also be a result of Nasal's critical sections: other threads may acquire a temporary lock to alter Nasal data structures - which may block the execution of Nasal timers at certain points. — ThorstenB

When evaluating simulation performance, don't get fooled by the frame rate. What's really important to us is the "worst case frame latency". Even if the system is producing a huge average of 100 frames per second, it can still look absolutely crappy, if only a single frame took more than 20-30ms, since that's immediately visible to the human eye (note to self: add a "worst case latency" indicator). So, we're building a real-time system here, and 20-30ms is our timing constraint. — ThorstenB

Nasal needs to run a garbage collection every now and then. This means an extra delay, and may become noticeable, if it causes a frame to violate the timing constraint. _When_ and _where_ in the Nasal code the g/c triggers, is almost random, so you cannot attribute the g/c delay to the point where it happened. The effect depends on two properties: (1) how long does it take, and (2) how often does it happen. These issues are triggered by different properties of the code. If we can keep the delay below the limit, everything is perfect. If we cannot, than we should at least reduce its frequency. One stutter per minute may be acceptable. Once every second looks absolutely intolerable (though you may still get a funky 100fps indication!). — ThorstenB

There's several timers which run at full frame rate, even when the related feature is disabled: fgdata/Nasal/mp_broadcast.nas:146 fgdata/Nasal/redout.nas:93 fgdata/Nasal/wildfire.nas:506 fgdata/Nasal/track_target.nas:194 Even when they're almost doing nothing, it'd still help if they were stopped or at least slowed down, when the related feature was disabled. They affect garbage collection since a lot of (useless) contexts are created and need to be cleared at some point - hence triggering the g/c more often than necessary. — ThorstenB

A bit background on the FG subsystems may be necessary though to really judge what's going on. For example, you'll see the "nasal" subsystem consuming almost no time at all, so it looks great. However, almost all the nasal code runs in timers, and timers are driven by the "events" subsystem. So, to judge Nasal performance, you'll mainly need to look at "events" (and yes, you'll see time being consumed and jitters being produced there). — ThorstenB

The event manager handles timers, and that's almost exclusively used by Nasal. Almost all the Nasal code runs in timers (except for property listeners). So read "events" as the total execution time for Nasal (timers). The timing data shown for the subsystem "nasal" only refers to the execution time of Nasal internal house keeping (i.e. some garbage collection), but not to the execution of actual Nasal code. Indeed misleading. — ThorstenB

Only dialogs which regularly trigger a full redraw (using Nasal timers) cause significant issues. The performance dialog uses "live" properties, so no dialog redraw is required while it stays open. Only the "sort" button triggers a full redraw, hence a jitter. This is why the sort is triggered with a manual button so far, rather than by a periodic timer - the latter had completely spoiled statistics. — ThorstenB

References