Lunatic: output timing results to CSV file, don't time unreg'd events/actors.

The base name is taken from the environment variable LUNATIC_TIMING_BASEFN,
which is suffixed with .actors.csv and .events.csv.

git-svn-id: https://svn.eduke32.com/eduke32@3946 1a8010ca-5511-0410-912e-c29ae57300e0

polymer/eduke32/source/gameexec.c

@@ -48,15 +48,15 @@ Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA  02111-1307, USA.
 # define GAMEEXEC_STATIC static
 #endif
 
+vmstate_t vm;
+
+#if !defined LUNATIC
 enum vmflags_t {
     VM_RETURN       = 0x00000001,
     VM_KILL         = 0x00000002,
     VM_NOEXECUTE    = 0x00000004,
 };
 
-vmstate_t vm;
-
-#if !defined LUNATIC
 int32_t g_tw;
 int32_t g_errorLineNum;
 int32_t g_currentEventExec = -1;
@@ -119,15 +119,19 @@ static void VM_KillIt(int32_t iActor, int32_t iPlayer)
 int32_t VM_OnEvent(int32_t iEventID, int32_t iActor, int32_t iPlayer, int32_t lDist, int32_t iReturn)
 {
 #ifdef LUNATIC
-    const double t = gethiticks();
-
-    // TODO: handling of RETURN gamevar / iReturn / this function's return value
     if (L_IsInitialized(&g_ElState) && El_HaveEvent(iEventID))
-        if (El_CallEvent(&g_ElState, iEventID, iActor, iPlayer, lDist, &iReturn)==1)
-            VM_KillIt(iActor, iPlayer);
+    {
+        const double t = gethiticks();
+        int32_t ret = El_CallEvent(&g_ElState, iEventID, iActor, iPlayer, lDist, &iReturn);
 
+        // NOTE: the run times are those of the called event plus any events
+        // called by it, *not* "self" time.
         g_eventTotalMs[iEventID] += gethiticks()-t;
         g_eventCalls[iEventID]++;
+
+        if (ret == 1)
+            VM_KillIt(iActor, iPlayer);
+    }
 #else
 
     if (apScriptGameEvent[iEventID])
@@ -993,8 +997,9 @@ static int32_t VM_ResetPlayer(int32_t g_p, int32_t g_flags)
             M_ChangeMenu(15000);
         }
         else g_player[g_p].ps->gm = MODE_RESTART;
-
+#if !defined LUNATIC
         g_flags |= VM_NOEXECUTE;
+#endif
     }
     else
     {
@@ -5399,10 +5404,12 @@ void A_Execute(int32_t iActor,int32_t iPlayer,int32_t lDist)
 
 #ifdef LUNATIC
     {
-        double t = gethiticks();
         const int32_t picnum = vm.g_sp->picnum;
 
         if (L_IsInitialized(&g_ElState) && El_HaveActor(picnum))
+        {
+            double t = gethiticks();
+
             killit = (El_CallActor(&g_ElState, picnum, iActor, iPlayer, lDist)==1);
 
             t = gethiticks()-t;
@@ -5411,17 +5418,18 @@ void A_Execute(int32_t iActor,int32_t iPlayer,int32_t lDist)
             g_actorMaxMs[picnum] = max(g_actorMaxMs[picnum], t);
             g_actorCalls[picnum]++;
         }
+    }
 #else
     insptr = 4 + (g_tile[vm.g_sp->picnum].execPtr);
     VM_Execute(1);
     insptr = NULL;
 #endif
 
-    if ((vm.g_flags & VM_KILL)
 #ifdef LUNATIC
-        || killit
+    if (killit)
+#else
+    if (vm.g_flags & VM_KILL)
 #endif
-        )
     {
         VM_KillIt(iActor, iPlayer);
         return;

polymer/eduke32/source/lunatic/lunatic_game.c

@@ -1,6 +1,9 @@
 /* The Lunatic Interpreter, part of EDuke32. Game-side stuff. */
 
 #include <stdint.h>
+#include <stdlib.h>  // getenv
+#include <errno.h>
+#include <string.h>  // strerror
 
 #include <lualib.h>
 #include <lauxlib.h>
@@ -76,10 +79,73 @@ LUNATIC_EXTERN double rand_jkiss_dbl(rng_jkiss_t *s)
 
 void El_PrintTimes(void)
 {
-    int32_t i, maxlen=0;
-    char buf[32];
+    int32_t i;
     const char nn = Bstrlen("EVENT_");
 
+    // Try environment variable specifying the base name (sans ".actors.csv" or
+    // ".events.csv") for a CSV file to output, for further processing in e.g.
+    // GSL shell: http://www.nongnu.org/gsl-shell/
+    const char *basefn = getenv("LUNATIC_TIMING_BASEFN");
+
+    if (basefn != NULL)
+    {
+        const int32_t baselen = Bstrlen(basefn);
+        const int32_t addnlen = Bstrlen(".actors.csv");  // MUST equal that of ".events.csv"
+
+        char *fullfn = Bmalloc(baselen + addnlen + 1);
+        BFILE *outf;
+
+        if (fullfn == NULL)
+            return;
+
+        Bmemcpy(fullfn, basefn, baselen);
+
+        // EVENTS
+        Bmemcpy(fullfn+baselen, ".events.csv", addnlen+1);
+        outf = Bfopen(fullfn, "w");
+        if (outf == NULL)
+        {
+            OSD_Printf("Couldn't open \"%s\" for writing timing data: %s", fullfn, strerror(errno));
+            goto finish;
+        }
+
+        Bfprintf(outf, "evtname,numcalls,total_ms,mean_us\n");  // times in usecs are per-call
+        for (i=0; i<MAXEVENTS; i++)
+            if (g_eventCalls[i])
+                Bfprintf(outf, "%s,%d,%f,%f\n", EventNames[i]+nn, g_eventCalls[i], g_eventTotalMs[i],
+                         1000*g_eventTotalMs[i]/g_eventCalls[i]);
+        Bfclose(outf);
+
+        // ACTORS
+        Bmemcpy(fullfn+baselen, ".actors.csv", addnlen+1);
+        outf = Bfopen(fullfn, "w");
+        if (outf == NULL)
+        {
+            OSD_Printf("Couldn't open \"%s\" for writing timing data: %s", fullfn, strerror(errno));
+            goto finish;
+        }
+
+        Bfprintf(outf, "tilenum,numcalls,total_ms,min_us,mean_us,max_us\n");
+        for (i=0; i<MAXTILES; i++)
+            if (g_actorCalls[i])
+                Bfprintf(outf, "%d,%d,%f,%f,%f,%f\n", i, g_actorCalls[i], g_actorTotalMs[i],
+                         1000*g_actorMinMs[i],
+                         1000*g_actorTotalMs[i]/g_actorCalls[i],
+                         1000*g_actorMaxMs[i]);
+        Bfclose(outf);
+
+        OSD_Printf("Wrote timing data to \"%s.*.csv\"\n", basefn);
+finish:
+        Bfree(fullfn);
+        return;
+    }
+    else
+    {
+        // If not writing out CSV files, print timing data to log instead.
+
+        char buf[32];
+        int32_t maxlen = 0;
+
         for (i=0; i<MAXEVENTS; i++)
         {
             int32_t len = Bstrlen(EventNames[i]+nn);
@@ -114,6 +180,7 @@ void El_PrintTimes(void)
                            1000*g_actorMaxMs[i]);
         OSD_Printf(" },\n}\n");
     }
+}
 
 ////////// ERROR REPORTING //////////
 #define EL_MAXERRORS 20