From 1f6896089c60a09d650869567d0a54e872af09b4 Mon Sep 17 00:00:00 2001 From: TellowKrinkle Date: Fri, 11 Jun 2021 19:55:04 -0500 Subject: [PATCH] Add render time logging --- src/Ponscripter.cpp | 6 ++++++ src/PonscripterLabel.cpp | 10 ++++++++++ src/PonscripterLabel.h | 13 ++++++++++++- src/PonscripterLabel_effect.cpp | 2 ++ src/PonscripterLabel_event.cpp | 24 ++++++++++++++++++++++++ src/PonscripterLabel_image.cpp | 2 ++ src/PonscripterLabel_text.cpp | 2 ++ 7 files changed, 58 insertions(+), 1 deletion(-) diff --git a/src/Ponscripter.cpp b/src/Ponscripter.cpp index cdb6da69..9343cddf 100644 --- 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 index da5c37e9..c784416c 100644 --- 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 index b86ebb41..7aa14316 100644 --- 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 index 5c8be3cd..39a2a275 100644 --- 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 index d37f090c..de5b0418 100644 --- 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 index 41bcd091..d526917f 100644 --- 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 index 189aa7e7..41c0605b 100644 --- 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