Add render time logging

07th-mod · Jun 12, 2021 · 1f68960 · 1f68960
1 parent 638338b
commit 1f68960
Show file tree

Hide file tree

Showing 7 changed files with 58 additions and 1 deletion.
diff --git a/src/Ponscripter.cpp b/src/Ponscripter.cpp
@@ -72,6 +72,7 @@ static void optionHelp()
     printf("      --disable-cpu-gfx\tdo not use Altivec graphics "
            "acceleration routines\n");
 #endif
+    printf("      --record-render-time\tRecord render times to the given csv file\n");
     printf("      --enable-wheeldown-advance\tadvance the text on mouse "
            "wheeldown event\n");
 //    printf("      --nsa-offset offset\tuse byte offset x when reading "
@@ -189,6 +190,11 @@ static void parseOptions(int argc, char **argv, PonscripterLabel &ons,
                 printf("disabling CPU accelerated graphics routines\n");
             }
 #endif
+            else if (!strcmp(argv[0] + 1, "-record-render-time")) {
+                argc--;
+                argv++;
+                ons.recordRenderTimes(argv[0]);
+            }
             else if (!strcmp(argv[0] + 1, "-disable-rescale")) {
                 ons.disableRescale();
             }

diff --git a/src/PonscripterLabel.cpp b/src/PonscripterLabel.cpp
@@ -606,6 +606,7 @@ PonscripterLabel::PonscripterLabel()
 {
     AnimationInfo::gfx = AcceleratedGraphicsFunctions::accelerated();
 
+    renderTimesFile      = NULL;
     disable_rescale_flag = false;
     edit_flag            = false;
     fullscreen_mode      = false;
@@ -722,6 +723,15 @@ void PonscripterLabel::disableCpuGfx()
 }
 
 
+void PonscripterLabel::recordRenderTimes(const char* file) {
+    renderTimesFile = fopen(file, "w");
+    if (!renderTimesFile) {
+        fprintf(stderr, "Failed to open %s to record render times to, disabling\n", file);
+    }
+    fputs("Frame,Type,Time\n", renderTimesFile);
+}
+
+
 void PonscripterLabel::disableRescale()
 {
     disable_rescale_flag = true;

diff --git a/src/PonscripterLabel.h b/src/PonscripterLabel.h
@@ -117,6 +117,7 @@ class PonscripterLabel : public ScriptParser {
     void setPreferredWidth(const char *widthstr);
     void enableButtonShortCut();
     void enableWheelDownAdvance();
+    void recordRenderTimes(const char* file);
     void disableCpuGfx();
     void disableRescale();
     void enableEdit();
@@ -404,13 +405,23 @@ class PonscripterLabel : public ScriptParser {
            ALPHA_BLEND_MULTIPLE       = 2,
            ALPHA_BLEND_FADE_MASK      = 3,
            ALPHA_BLEND_CROSSFADE_MASK = 4 };
-
+public:
+    enum RenderEventType {
+        RENDER_EVENT_UNKNOWN = 0,
+        RENDER_EVENT_TEXT,
+        RENDER_EVENT_EFFECT,
+        RENDER_EVENT_LOAD_IMAGE,
+    };
+    /// For render time logging
+    RenderEventType lastRenderEvent;
+private:
     // ----------------------------------------
     // start-up options
     pstring registry_file;
     pstring dll_file;
     pstring getret_str;
     int    getret_int;
+    FILE*  renderTimesFile;
     bool   enable_wheeldown_advance_flag;
     bool   disable_rescale_flag;
     bool   edit_flag;

diff --git a/src/PonscripterLabel_effect.cpp b/src/PonscripterLabel_effect.cpp
@@ -112,6 +112,8 @@ int PonscripterLabel::setEffect(Effect& effect, bool generate_effect_dst, bool u
 
 int PonscripterLabel::doEffect(Effect& effect, bool clear_dirty_region)
 {
+    if (lastRenderEvent < RENDER_EVENT_EFFECT) { lastRenderEvent = RENDER_EVENT_EFFECT; }
+
     bool first_time = (effect_counter == 0);
 
     int prevduration = effect.duration;

diff --git a/src/PonscripterLabel_event.cpp b/src/PonscripterLabel_event.cpp
@@ -1199,6 +1199,8 @@ Uint32 PonscripterLabel::getRefreshRateDelay() {
 int PonscripterLabel::eventLoop()
 {
     SDL_Event event, tmp_event;
+    Uint32 frameNo = 0;
+    double perfMultiplier = 1000.0/SDL_GetPerformanceFrequency();
 
     /* Note, this rate can change if the window is dragged to a new
        screen or the monitor settings are changed while running.
@@ -1370,6 +1372,11 @@ int PonscripterLabel::eventLoop()
                 last_refresh = current_time;
                 rerender();
 
+                if (renderTimesFile) {
+                    frameNo++;
+                    if (frameNo % 64 == 0) { fflush(renderTimesFile); }
+                }
+
                 /* Refresh time since rerender does take some odd ms */
                 current_time = SDL_GetTicks();
             }
@@ -1386,9 +1393,26 @@ int PonscripterLabel::eventLoop()
             if(SDL_PeepEvents(&tmp_event, 1, SDL_PEEKEVENT, SDL_FIRSTEVENT, SDL_LASTEVENT) == 0) {
                 if(timer_event_flag && timer_event_time <= current_time) {
                     timer_event_flag = false;
+                    Uint64 begin;
+                    if (renderTimesFile) {
+                        begin = SDL_GetPerformanceCounter();
+                        lastRenderEvent = RENDER_EVENT_UNKNOWN;
+                    }
                     if (timerEvent() && timer_event_time <= last_refresh + refresh_delay) {
                         timer_event_time = last_refresh + refresh_delay;
                     }
+                    if (renderTimesFile) {
+                        Uint64 elapsed = SDL_GetPerformanceCounter() - begin;
+                        float msElapsed = elapsed * perfMultiplier;
+                        const char* eventName;
+                        switch (lastRenderEvent) {
+                            case RENDER_EVENT_UNKNOWN:    eventName = "TimerEvent"; break;
+                            case RENDER_EVENT_TEXT:       eventName = "Text";       break;
+                            case RENDER_EVENT_EFFECT:     eventName = "Effect";     break;
+                            case RENDER_EVENT_LOAD_IMAGE: eventName = "ImageLoad";  break;
+                        }
+                        fprintf(renderTimesFile, "%d,%s,%f\n", frameNo, eventName, msElapsed);
+                    }
                 } else if(last_refresh <= current_time && refresh_delay >= (current_time - last_refresh)) {
                     SDL_Delay(std::min(refresh_delay / 3, refresh_delay - (current_time - last_refresh)));
                 }

diff --git a/src/PonscripterLabel_image.cpp b/src/PonscripterLabel_image.cpp
@@ -33,6 +33,8 @@ SDL_Surface *PonscripterLabel::loadImage(const pstring& filename,
 {
     if (!filename) return NULL;
 
+    if (lastRenderEvent < RENDER_EVENT_LOAD_IMAGE) { lastRenderEvent = RENDER_EVENT_LOAD_IMAGE; }
+
     SDL_Surface *tmp = NULL, *tmpb = NULL;
     int location = BaseReader::ARCHIVE_TYPE_NONE;
 

diff --git a/src/PonscripterLabel_text.cpp b/src/PonscripterLabel_text.cpp
@@ -475,6 +475,8 @@ int PonscripterLabel::clickNewPage(bool display_char)
 
 int PonscripterLabel::textCommand()
 {
+    if (lastRenderEvent < RENDER_EVENT_TEXT) { lastRenderEvent = RENDER_EVENT_TEXT; }
+
     if (pretextgosub_label
         && (line_enter_status == 0
             || (line_enter_status == 1