From b243264d6b342671b8d055a0c4c5969df609c0a2 Mon Sep 17 00:00:00 2001
From: helixhorned <helixhorned@1a8010ca-5511-0410-912e-c29ae57300e0>
Date: Sat, 13 Jul 2013 21:04:45 +0000
Subject: [PATCH] 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 ++++---
 polymer/eduke32/source/lunatic/lunatic_game.c | 127 +++++++++++++-----
 2 files changed, 125 insertions(+), 50 deletions(-)

diff --git a/polymer/eduke32/source/gameexec.c b/polymer/eduke32/source/gameexec.c
index 8c9218d9f..54550444c 100644
--- a/polymer/eduke32/source/gameexec.c
+++ b/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);
 
-    g_eventTotalMs[iEventID] += gethiticks()-t;
-    g_eventCalls[iEventID]++;
+        // 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,17 +5404,20 @@ 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;
-        g_actorTotalMs[picnum] += t;
-        g_actorMinMs[picnum] = min(g_actorMinMs[picnum], t);
-        g_actorMaxMs[picnum] = max(g_actorMaxMs[picnum], t);
-        g_actorCalls[picnum]++;
+            t = gethiticks()-t;
+            g_actorTotalMs[picnum] += t;
+            g_actorMinMs[picnum] = min(g_actorMinMs[picnum], t);
+            g_actorMaxMs[picnum] = max(g_actorMaxMs[picnum], t);
+            g_actorCalls[picnum]++;
+        }
     }
 #else
     insptr = 4 + (g_tile[vm.g_sp->picnum].execPtr);
@@ -5417,11 +5425,11 @@ void A_Execute(int32_t iActor,int32_t iPlayer,int32_t lDist)
     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;
diff --git a/polymer/eduke32/source/lunatic/lunatic_game.c b/polymer/eduke32/source/lunatic/lunatic_game.c
index c5d9e49df..3c998b81e 100644
--- a/polymer/eduke32/source/lunatic/lunatic_game.c
+++ b/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,43 +79,107 @@ 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_");
 
-    for (i=0; i<MAXEVENTS; i++)
+    // 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)
     {
-        int32_t len = Bstrlen(EventNames[i]+nn);
-        Bassert(len < (int32_t)sizeof(buf));
-        maxlen = max(len, maxlen);
-    }
+        const int32_t baselen = Bstrlen(basefn);
+        const int32_t addnlen = Bstrlen(".actors.csv");  // MUST equal that of ".events.csv"
 
-    OSD_Printf("{\n {\n");
-    OSD_Printf("  -- event times, [event]={ total calls, total time [ms], mean time/call [us] }\n");
-    for (i=0; i<MAXEVENTS; i++)
-        if (g_eventCalls[i])
+        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)
         {
-            int32_t n=Bsprintf(buf, "%s", EventNames[i]+nn);
-
-            for (; n<maxlen; n++)
-                buf[n] = ' ';
-            buf[maxlen] = 0;
-
-            OSD_Printf("  [%s]={ %8d, %10.3f, %10.3f },\n",
-                       buf, g_eventCalls[i], g_eventTotalMs[i],
-                       1000*g_eventTotalMs[i]/g_eventCalls[i]);
+            OSD_Printf("Couldn't open \"%s\" for writing timing data: %s", fullfn, strerror(errno));
+            goto finish;
         }
 
-    OSD_Printf(" },\n\n {\n");
-    OSD_Printf("  -- actor times, [tile]={ total calls, total time [ms], {min,mean,max} time/call [us] }\n");
-    for (i=0; i<MAXTILES; i++)
-        if (g_actorCalls[i])
-            OSD_Printf("  [%5d]={ %8d, %9.3f, %9.3f, %9.3f, %9.3f },\n",
-                       i, g_actorCalls[i], g_actorTotalMs[i],
-                       1000*g_actorMinMs[i],
-                       1000*g_actorTotalMs[i]/g_actorCalls[i],
-                       1000*g_actorMaxMs[i]);
-    OSD_Printf(" },\n}\n");
+        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);
+            Bassert(len < (int32_t)sizeof(buf));
+            maxlen = max(len, maxlen);
+        }
+
+        OSD_Printf("{\n {\n");
+        OSD_Printf("  -- event times, [event]={ total calls, total time [ms], mean time/call [us] }\n");
+        for (i=0; i<MAXEVENTS; i++)
+            if (g_eventCalls[i])
+            {
+                int32_t n=Bsprintf(buf, "%s", EventNames[i]+nn);
+
+                for (; n<maxlen; n++)
+                    buf[n] = ' ';
+                buf[maxlen] = 0;
+
+                OSD_Printf("  [%s]={ %8d, %10.3f, %10.3f },\n",
+                           buf, g_eventCalls[i], g_eventTotalMs[i],
+                           1000*g_eventTotalMs[i]/g_eventCalls[i]);
+            }
+
+        OSD_Printf(" },\n\n {\n");
+        OSD_Printf("  -- actor times, [tile]={ total calls, total time [ms], {min,mean,max} time/call [us] }\n");
+        for (i=0; i<MAXTILES; i++)
+            if (g_actorCalls[i])
+                OSD_Printf("  [%5d]={ %8d, %9.3f, %9.3f, %9.3f, %9.3f },\n",
+                           i, g_actorCalls[i], g_actorTotalMs[i],
+                           1000*g_actorMinMs[i],
+                           1000*g_actorTotalMs[i]/g_actorCalls[i],
+                           1000*g_actorMaxMs[i]);
+        OSD_Printf(" },\n}\n");
+    }
 }
 
 ////////// ERROR REPORTING //////////