Instrumented Nasal GC

simgear/nasal/code.c

@@ -24,6 +24,21 @@ struct Globals* globals = 0;
 
 static naRef bindFunction(naContext ctx, struct Frame* f, naRef code);
 
+char __name[3000] = { 0 };
+int init = 0;
+void getSource(struct Context* c) {
+    naRef v = naGetSourceFile(c, 0);
+    init = 1;
+    if (!IS_NIL(v))
+        snprintf(__name, 3000, "%s:%d", naStr_data(v), naGetLine(c, 0));
+    else
+        *__name = 0;
+}
+char *getName() {
+    if (init)
+        return __name;
+    return "**";
+}
 #define ERR(c, msg) naRuntimeError((c),(msg))
 void naRuntimeError(naContext c, const char* fmt, ...)
 {
@@ -305,6 +320,7 @@ static void checkNamedArgs(naContext ctx, struct naCode* c, struct naHash* h)
 
 static struct Frame* setupFuncall(naContext ctx, int nargs, int mcall, int named)
 {
+    getSource(ctx);
     naRef *args, func, code, obj = naNil();
     struct Frame* f;
     int opf = ctx->opTop - nargs;
@@ -833,10 +849,14 @@ naRef naGetSourceFile(naContext ctx, int frame)
 {
     naRef f;
     frame = findFrame(ctx, &ctx, frame);
+    if (frame >= 0) {
         f = ctx->fStack[frame].func;
         f = PTR(f).func->code;
+        if (!IS_NIL(f) && PTR(f).code)
             return PTR(f).code->srcFile;
     }
+    return naNil();
+}
 
 char* naGetError(naContext ctx)
 {

simgear/nasal/gc.c

@@ -1,7 +1,6 @@
 #include "nasal.h"
 #include "data.h"
 #include "code.h"
-
 #define MIN_BLOCK_SIZE 32
 
 static void reap(struct naPool* p);
@@ -12,14 +11,17 @@ struct Block {
     char* block;
     struct Block* next;
 };
-
 // Must be called with the giant exclusive lock!
+extern void global_stamp();
+extern int global_elapsedUSec();
+extern char *getName();
 static void freeDead()
 {
     int i;
     for(i=0; i<globals->ndead; i++)
         naFree(globals->deadBlocks[i]);
     globals->ndead = 0;
+    printf("--> freedead (%d) : %d", i, global_elapsedUSec());
 }
 
 static void marktemps(struct Context* c)
@@ -52,6 +54,7 @@ static void garbageCollect()
         marktemps(c);
         c = c->nextAll;
     }
+    printf("--> garbageCollect: %d ", global_elapsedUSec());
 
     mark(globals->save);
     mark(globals->save_hash);
@@ -60,10 +63,13 @@ static void garbageCollect()
     mark(globals->argRef);
     mark(globals->parentsRef);
 
-    // Finally collect all the freed objects
-    for(i=0; i<NUM_NASAL_TYPES; i++)
-        reap(&(globals->pools[i]));
+    printf("m> %d", global_elapsedUSec());
 
+    // Finally collect all the freed objects
+    for (i = 0; i < NUM_NASAL_TYPES; i++) {
+        reap(&(globals->pools[i]));
+        printf(" p(%d)> %d", i, global_elapsedUSec());
+    }
     // Make enough space for the dead blocks we need to free during
     // execution.  This works out to 1 spot for every 2 live objects,
     // which should be limit the number of bottleneck operations
@@ -75,6 +81,7 @@ static void garbageCollect()
         globals->deadBlocks = naAlloc(sizeof(void*) * globals->deadsz);
     }
     globals->needGC = 0;
+    printf(">> %d ", global_elapsedUSec());
 }
 
 void naModLock()
@@ -104,6 +111,7 @@ void naModUnlock()
 // you think about it).
 static void bottleneck()
 {
+    global_stamp();
     struct Globals* g = globals;
     g->bottleneck = 1;
     while(g->bottleneck && g->waitCount < g->nThreads - 1) {
@@ -111,12 +119,16 @@ static void bottleneck()
         UNLOCK(); naSemDown(g->sem); LOCK();
         g->waitCount--;
     }
+    printf("bottleneck wait finished %d usec", global_elapsedUSec());
     if(g->waitCount >= g->nThreads - 1) {
         freeDead();
-        if(g->needGC) garbageCollect();
+        //if(g->needGC) 
+            garbageCollect();
         if(g->waitCount) naSemUp(g->sem, g->waitCount);
         g->bottleneck = 0;
     }
+    char *c = getName();
+    printf("bottleneck finished: %d %s\n", global_elapsedUSec(), c);
 }
 
 void naGC()

simgear/nasal/misc.c

@@ -65,6 +65,7 @@ naRef naStringValue(naContext c, naRef r)
 
 naRef naNew(struct Context* c, int type)
 {
+    getSource(c);
     naRef result;
     if(c->nfree[type] == 0)
         c->free[type] = naGC_get(&globals->pools[type],

simgear/timing/timestamp.cxx

@@ -337,3 +337,21 @@ int SGTimeStamp::elapsedMSec() const
     
     return static_cast<int>((now - *this).toMSecs());
 }
+
+int SGTimeStamp::elapsedUSec() const
+{
+    SGTimeStamp now;
+    now.stamp();
+
+    return static_cast<int>((now - *this).toUSecs());
+}
+extern "C" {
+    SGTimeStamp global_timestamp;
+    void global_stamp() {
+        global_timestamp.stamp();
+    }
+    extern int global_elapsedUSec()
+    {
+        return global_timestamp.elapsedUSec();
+    }
+    }

simgear/timing/timestamp.hxx

@@ -224,6 +224,10 @@ public:
     * elapsed time since the stamp was taken, in msec
     */
     int elapsedMSec() const;
+    /**
+    * elapsed time since the stamp was taken, in usec
+    */
+    int elapsedUSec() const;
 private:
     SGTimeStamp(sec_type sec, nsec_type nsec)
     { setTime(sec, nsec); }