Howto:Exposing Subsystems to Nasal

Work in progress This article or section will be worked on in the upcoming hours or days. See history for the latest developments.

Objective

Document how existing FlightGear subsystems (i.e. those inheriting from SGSubsystem) can be exposed to Nasal space to make certain information available to Nasal space.

Focus

See Resource Tracking for FlightGear for the main article about this subject.

This article will specifically cover how to access the FlightGear event manager (SGEventMgr) and the listener API (SGPropertyChangeListener) to track registration and invocation of Nasal callbacks per frame.

Background

The main mechanism for triggering scripted Nasal code to be executed within the FlightGear main loop are so called listeners (Nasal callbacks that are stored in a property-specific vector/list, that get executed in a for-each loop whenever a property is modified), and timers, which represent "delays" (typically in seconds or milliseconds) after which a timer expires and fires its callback to be executed.

Accordingly, this means that Nasal callbacks will be either invoked by the events subsystem (timers) or by whatever subsystem modifies a property that has a Nasal listener bound to it, given that nature of the Nasal garbage collector (GC), this may make frame rates less determinstic/predictable.

Unfortunately, these two mechanisms are also rather low-level and tedious/error-prone to use correctly, so that code (Nasal callbacks) may be triggered accidently, and unnecessarily, which ultimately eats up considerable resources while creating a frame, sooner or later causing frame stuttering.

This would typically be the case when a function is invoked "too often", i.e. more often than necessary, without the programmer being aware of it - e.g. consider callbacks that are registered to be invoked multiple times:

var foo = func() {
 settimer(foo, 0);
 settimer(foo, 0);
}
foo();

While the example shown above is trivial, and straightforward to fix, the underlynig problem is a very common one in scripted FlightGear code.

Equally, listeners are a constant source of trouble, because people tend to register callbacks too often (i.e. spread across multiple functions/files):

var foo = func() {
}
setlistener("/sim/signals/fdm-initialized", foo);
setlistener("/sim/signals/fdm-initialized", foo);
setlistener("/sim/signals/fdm-initialized", foo);

What this will do, is execute the function 3 times whenever the property is modified.

What needs to be kept in mind here that these are very much contrived examples, and that the code in question is often much more complex, and that such bugs may depend on certain features being in use - e.g. when using reset/re-init, many modules won't behave properly, so that redundant listeners may be registered.

Even more unfortunate is the fact that FlightGear does not currently provide any mechanisms/APIs to look behind the scenes, i.e. to see how often a callback is actually executed, and where the callback is registered to be executed.

This article intends to document the steps required to expose meta information about timers and listeners to scripting space so that a Nasal/Canvas bsed UI (dialog) can be displayed with a list of active callbacks, and their runtime characteristics.

However, the underlying timer/listener APIs are not specific to Nasal scripting but also commonly used elsewhere (in fact, in most other subsystems), and they are also infamous for buggy C++ code that similarly affected FlightGear performance.

This will include patches to all 3 repositories of FlightGear, i.e. SimGear, FlightGear and fgdata.

Approach

We will be providing additional methods to obtain access to otherwise private fields/data (members) and make those available to FGNasalSys.

Roadmap

• extend the destructors of the timer/listener objects to dump creation/destruction and invocation info to the log via SG_LOG Not done
• extend SGTimerQueue to provide methods for getting the size of the queue Not done
• extend SGEventMgr to dump that info to the console via the SG_LOG macro Not done
• add a counter to keep track of timers registered via settimer/maketimer Not done
• add a counter to keep track of listeners registered via setlistener Not done
• add a per-frame resetting counter to keep track of callback invocations per frame Not done

Patching

SimGear

For starters, we will just add some debugging statements to the event manager. The event manager maintains two queues for timers, one for timers intended to work with simulation time, and one with realtime (i.e. those also executing when paused). These timers are fields/members of the SGEventMgr class which inherits from SGSubsystem, they are accessible as _simQueue and _rtQueue, using the interface of the SGTimerQueue class, the size of the queue is stored in the private _numEntries field (int), which can be made accessible by adding a public getter method, which in turn can then be used by the SGEventMgr subsystem to access the size of each queue:

diff --git a/simgear/structure/event_mgr.cxx b/simgear/structure/event_mgr.cxx
index 2e4f7b7..97848b4 100644
--- a/simgear/structure/event_mgr.cxx
+++ b/simgear/structure/event_mgr.cxx
@@ -24,9 +24,26 @@ void SGEventMgr::add(const std::string& name, SGCallback* cb,
     
     SGTimerQueue* q = simtime ? &_simQueue : &_rtQueue;
 
+    SG_LOG(SG_GENERAL, SG_ALERT, "== Inserting timer into queue" <<
+	"\t type:" << name << std::endl <<
+	"\t interval:" << interval <<std::endl <<
+	"\t delay:" << delay <<std::endl <<
+	"\t repeated:" << repeat <<std::endl <<
+	"\t simtime/realtime:" << simtime <<"/"<<!simtime
+	<< std::endl);
+
+    info();
     q->insert(t, delay);
 }
 
+void SGEventMgr::info() {
+    SG_LOG(SG_GENERAL, SG_ALERT, "Total Entries in queues" << std::endl << 
+	"\t simtime queue:" << _simQueue.getQueueSize() << std::endl <<
+	"\t realtime queue:" << _rtQueue.getQueueSize() << std::endl
+	);
+}
+
+
 SGTimer::~SGTimer()
 {
     delete callback;
diff --git a/simgear/structure/event_mgr.hxx b/simgear/structure/event_mgr.hxx
index 699522b..0cab8b7 100644
--- a/simgear/structure/event_mgr.hxx
+++ b/simgear/structure/event_mgr.hxx
@@ -38,6 +38,9 @@ public:
     double   nextTime()  { return -_table[0].pri; }
 
     SGTimer* findByName(const std::string& name) const;
+    unsigned int getQueueSize() const {
+		return _numEntries;
+	}
 private:
     // The "priority" is stored as a negative time.  This allows the
     // implementation to treat the "top" of the heap as the largest
@@ -76,6 +79,7 @@ public:
     virtual void update(double delta_time_sec);
     virtual void unbind();
     virtual void shutdown();
+    virtual void info(); // dumps queue info to the console
     
     void setRealtimeProperty(SGPropertyNode* node) { _rtProp = node; }
 
@@ -120,6 +124,11 @@ public:
 
     void removeTask(const std::string& name);
 private:
+
+    typedef std::pair<std::string, int> CallbackInfo; //callback name & number of instances
+    typedef std::map<SGCallback*, CallbackInfo> CallbackMap;
+    CallbackMap _registeredCallbacks;
+
     friend class SGTimer;
 
     void add(const std::string& name, SGCallback* cb,

However, permanently logging all that info to the console/log file can obviously become heavy - so the next thing we are going to do is to use so called property objects to directly expose this information in the form of properties, for each event queue - so that this needs to be implemented at the SGTimerQueue level.

In particular, we need to expose the following information for each queue:

• number of total entries
• number of Nasal callbacks (settimer, maketimer)
• number of other callbacks

FlightGear

Note  In its current form, this patch works perfectly well, but is specific to just the settimer() API, i.e. does not handle NasalTimerObj instances created via maketimer. However, the undelying approach is trivial enough, so can be easily extended. Equally, it would make sense to not just log this info to the console but expose it in the property tree, or even provide dedicated Nasal APIs for getting this info at runtime, i.e. for further processing (think a dedicated GUI dialog)

diff --git a/src/Scripting/NasalSys.cxx b/src/Scripting/NasalSys.cxx
index dcd9965..27eb4c8 100644
--- a/src/Scripting/NasalSys.cxx
+++ b/src/Scripting/NasalSys.cxx
@@ -1307,6 +1307,13 @@ void FGNasalSys::setTimer(naContext c, int argc, naRef* args)
     t->gcKey = gcSave(handler);
     t->nasal = this;
 
+    SG_LOG(SG_NASAL, SG_ALERT, 
+	"Nasal timer registration via settimer():\n"
+	"\tfile: " << naStr_data(naGetSourceFile(c,0)) << 
+	"\tline: " << naGetLine(c,0) << std::endl
+	
+    );
+
     globals->get_event_mgr()->addEvent("NasalTimer",
                                        t, &NasalTimer::timerExpired,
                                        delta.num, simtime);

To make the whole thing more useful, we will lower the logging priority and instead change the name of the added event to include the file name of the Nasal module and the line number where the settimer() call is invoked (which will be primarily useful in conjunction with the simgear patch above):

diff --git a/src/Scripting/NasalSys.cxx b/src/Scripting/NasalSys.cxx
index dcd9965..7f49b18 100644
--- a/src/Scripting/NasalSys.cxx
+++ b/src/Scripting/NasalSys.cxx
@@ -1307,7 +1307,25 @@ void FGNasalSys::setTimer(naContext c, int argc, naRef* args)
     t->gcKey = gcSave(handler);
     t->nasal = this;
 
-    globals->get_event_mgr()->addEvent("NasalTimer",
+    SG_LOG(SG_NASAL, SG_DEBUG, 
+	"Nasal timer registration via settimer():\n"
+	"\tfile: " << naStr_data(naGetSourceFile(c,0)) << 
+	"\tline: " << naGetLine(c,0) << std::endl
+	
+    );
+
+    if(delta.num <= 0.1)
+	SG_LOG(SG_NASAL, SG_ALERT, "Warning: settimer() should rarely be used per-frame !!");
+
+    std::string timerName("NasalTimer: ");
+
+    std::stringstream line;
+    line << naGetLine(c,0);
+
+    timerName += std::string(naStr_data(naGetSourceFile(c,0))) +" via line:"+line.str() ;
+    
+
+    globals->get_event_mgr()->addEvent(timerName,
                                        t, &NasalTimer::timerExpired,
                                        delta.num, simtime);
 }

Next, we can explore logging everything via properties, i.e. so that all this info shows up in the property tree using property objects