From afaea86abdedcb4ee0a50ea6b5e5d395556f5f90 Mon Sep 17 00:00:00 2001 From: mjbudd77 Date: Mon, 30 Nov 2020 22:29:51 -0500 Subject: [PATCH] Added a frame timing statistics window to the Qt tools. Allows user to enable frame timing statistical calculations and view the output on a window in realtime. Is used to verify emulator is getting the proper clock interrupts from the OS and thus check that emulation timing is deterministic. --- src/CMakeLists.txt | 1 + src/drivers/Qt/ConsoleWindow.cpp | 20 +++ src/drivers/Qt/ConsoleWindow.h | 1 + src/drivers/Qt/FrameTimingStats.cpp | 265 ++++++++++++++++++++++++++++ src/drivers/Qt/FrameTimingStats.h | 55 ++++++ src/drivers/Qt/InputConf.cpp | 2 +- src/drivers/Qt/sdl-throttle.cpp | 100 +++++++++-- src/drivers/Qt/throttle.h | 41 +++++ 8 files changed, 469 insertions(+), 16 deletions(-) create mode 100644 src/drivers/Qt/FrameTimingStats.cpp create mode 100644 src/drivers/Qt/FrameTimingStats.h diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index b866e492..7abe867e 100644 --- a/src/CMakeLists.txt +++ b/src/CMakeLists.txt @@ -435,6 +435,7 @@ set(SRC_DRIVERS_SDL ${CMAKE_CURRENT_SOURCE_DIR}/drivers/Qt/GamePadConf.cpp ${CMAKE_CURRENT_SOURCE_DIR}/drivers/Qt/HotKeyConf.cpp ${CMAKE_CURRENT_SOURCE_DIR}/drivers/Qt/TimingConf.cpp + ${CMAKE_CURRENT_SOURCE_DIR}/drivers/Qt/FrameTimingStats.cpp ${CMAKE_CURRENT_SOURCE_DIR}/drivers/Qt/PaletteConf.cpp ${CMAKE_CURRENT_SOURCE_DIR}/drivers/Qt/GuiConf.cpp ${CMAKE_CURRENT_SOURCE_DIR}/drivers/Qt/MoviePlay.cpp diff --git a/src/drivers/Qt/ConsoleWindow.cpp b/src/drivers/Qt/ConsoleWindow.cpp index c7654d4a..69089ba8 100644 --- a/src/drivers/Qt/ConsoleWindow.cpp +++ b/src/drivers/Qt/ConsoleWindow.cpp @@ -37,6 +37,7 @@ #include "Qt/MoviePlay.h" #include "Qt/MovieOptions.h" #include "Qt/TimingConf.h" +#include "Qt/FrameTimingStats.h" #include "Qt/LuaControl.h" #include "Qt/CheatsConf.h" #include "Qt/GameGenie.h" @@ -654,6 +655,14 @@ void consoleWin_t::createMainMenu(void) toolsMenu->addAction(ramWatchAct); + // Tools -> Frame Timing + act = new QAction(tr("Frame Timing ..."), this); + //act->setShortcut( QKeySequence(tr("Shift+F7"))); + act->setStatusTip(tr("Open Frame Timing Window")); + connect(act, SIGNAL(triggered()), this, SLOT(openTimingStatWin(void)) ); + + toolsMenu->addAction(act); + //----------------------------------------------------------------------- // Debug debugMenu = menuBar()->addMenu(tr("Debug")); @@ -1303,6 +1312,17 @@ void consoleWin_t::openTimingConfWin(void) tmConfWin->show(); } +void consoleWin_t::openTimingStatWin(void) +{ + FrameTimingDialog_t *tmStatWin; + + //printf("Open Timing Statistics Window\n"); + + tmStatWin = new FrameTimingDialog_t(this); + + tmStatWin->show(); +} + void consoleWin_t::openMovieOptWin(void) { MovieOptionsDialog_t *win; diff --git a/src/drivers/Qt/ConsoleWindow.h b/src/drivers/Qt/ConsoleWindow.h index bf9f83c5..fb89af72 100644 --- a/src/drivers/Qt/ConsoleWindow.h +++ b/src/drivers/Qt/ConsoleWindow.h @@ -183,6 +183,7 @@ class consoleWin_t : public QMainWindow void openPaletteConfWin(void); void openGuiConfWin(void); void openTimingConfWin(void); + void openTimingStatWin(void); void openMovieOptWin(void); void openCodeDataLogger(void); void openTraceLogger(void); diff --git a/src/drivers/Qt/FrameTimingStats.cpp b/src/drivers/Qt/FrameTimingStats.cpp new file mode 100644 index 00000000..ac35fa83 --- /dev/null +++ b/src/drivers/Qt/FrameTimingStats.cpp @@ -0,0 +1,265 @@ +// FrameTimingStats.cpp +// +#include +#include +#include +#include + +#include +#include +#include + +#include "Qt/main.h" +#include "Qt/dface.h" +#include "Qt/input.h" +#include "Qt/config.h" +#include "Qt/keyscan.h" +#include "Qt/throttle.h" +#include "Qt/fceuWrapper.h" +#include "Qt/FrameTimingStats.h" + +//---------------------------------------------------------------------------- +FrameTimingDialog_t::FrameTimingDialog_t(QWidget *parent) + : QDialog( parent ) +{ + QVBoxLayout *mainLayout, *vbox; + QHBoxLayout *hbox; + QGroupBox *frame; + QTreeWidgetItem *item; + QPushButton *resetBtn; + struct frameTimingStat_t stats; + + getFrameTimingStats( &stats ); + + setWindowTitle("Frame Timing Statistics"); + + resize( 512, 512 ); + + mainLayout = new QVBoxLayout(); + vbox = new QVBoxLayout(); + frame = new QGroupBox( tr("Timing Statistics") ); + frame->setLayout( vbox ); + + tree = new QTreeWidget(); + vbox->addWidget( tree ); + + tree->setColumnCount(4); + + item = new QTreeWidgetItem(); + item->setText( 0, tr( "Parameter" ) ); + item->setText( 1, tr( "Target" ) ); + item->setText( 2, tr( "Current" ) ); + item->setText( 3, tr( "Minimum" ) ); + item->setText( 4, tr( "Maximum" ) ); + item->setTextAlignment( 0, Qt::AlignLeft); + item->setTextAlignment( 1, Qt::AlignCenter); + item->setTextAlignment( 2, Qt::AlignCenter); + item->setTextAlignment( 3, Qt::AlignCenter); + item->setTextAlignment( 4, Qt::AlignCenter); + + tree->setHeaderItem( item ); + tree->header()->setSectionResizeMode( QHeaderView::Stretch ); + tree->header()->setSectionResizeMode( 0, QHeaderView::ResizeToContents ); + + frameTimeAbs = new QTreeWidgetItem(); + frameTimeDel = new QTreeWidgetItem(); + frameTimeWork = new QTreeWidgetItem(); + frameTimeIdle = new QTreeWidgetItem(); + frameTimeWorkPct = new QTreeWidgetItem(); + frameTimeIdlePct = new QTreeWidgetItem(); + frameLateCount = new QTreeWidgetItem(); + + tree->addTopLevelItem( frameTimeAbs ); + tree->addTopLevelItem( frameTimeDel ); + tree->addTopLevelItem( frameTimeWork ); + tree->addTopLevelItem( frameTimeIdle ); + tree->addTopLevelItem( frameTimeWorkPct ); + tree->addTopLevelItem( frameTimeIdlePct ); + tree->addTopLevelItem( frameLateCount ); + + frameTimeAbs->setFlags( Qt::ItemIsEnabled | Qt::ItemNeverHasChildren ); + frameTimeDel->setFlags( Qt::ItemIsEnabled | Qt::ItemNeverHasChildren ); + + frameTimeAbs->setText( 0, tr("Frame Period ms") ); + frameTimeDel->setText( 0, tr("Frame Delta ms") ); + frameTimeWork->setText( 0, tr("Frame Work ms") ); + frameTimeIdle->setText( 0, tr("Frame Idle ms") ); + frameTimeWorkPct->setText( 0, tr("Frame Work %") ); + frameTimeIdlePct->setText( 0, tr("Frame Idle %") ); + frameLateCount->setText( 0, tr("Frame Late Count") ); + + frameTimeAbs->setTextAlignment( 0, Qt::AlignLeft); + frameTimeDel->setTextAlignment( 0, Qt::AlignLeft); + frameTimeWork->setTextAlignment( 0, Qt::AlignLeft); + frameTimeIdle->setTextAlignment( 0, Qt::AlignLeft); + frameTimeWorkPct->setTextAlignment( 0, Qt::AlignLeft); + frameTimeIdlePct->setTextAlignment( 0, Qt::AlignLeft); + frameLateCount->setTextAlignment( 0, Qt::AlignLeft); + + for (int i=0; i<4; i++) + { + frameTimeAbs->setTextAlignment( i+1, Qt::AlignCenter); + frameTimeDel->setTextAlignment( i+1, Qt::AlignCenter); + frameTimeWork->setTextAlignment( i+1, Qt::AlignCenter); + frameTimeIdle->setTextAlignment( i+1, Qt::AlignCenter); + frameTimeWorkPct->setTextAlignment( i+1, Qt::AlignCenter); + frameTimeIdlePct->setTextAlignment( i+1, Qt::AlignCenter); + frameLateCount->setTextAlignment( i+1, Qt::AlignCenter); + } + + hbox = new QHBoxLayout(); + timingEnable = new QCheckBox( tr("Enable Timing Statistics Calculations") ); + resetBtn = new QPushButton( tr("Reset") ); + + timingEnable->setChecked( stats.enabled ); + + hbox->addWidget( timingEnable ); + hbox->addWidget( resetBtn ); + + connect( timingEnable, SIGNAL(stateChanged(int)), this, SLOT(timingEnableChanged(int)) ); + connect( resetBtn , SIGNAL(clicked(void)) , this, SLOT(resetTimingClicked(void)) ); + + mainLayout->addLayout( hbox ); + mainLayout->addWidget( frame ); + + setLayout( mainLayout ); + + updateTimingStats(); + + updateTimer = new QTimer( this ); + + connect( updateTimer, &QTimer::timeout, this, &FrameTimingDialog_t::updatePeriodic ); + + updateTimer->start( 200 ); // 5hz + +} +//---------------------------------------------------------------------------- +FrameTimingDialog_t::~FrameTimingDialog_t(void) +{ + printf("Destroy Frame Timing Window\n"); + updateTimer->stop(); +} +//---------------------------------------------------------------------------- +void FrameTimingDialog_t::closeEvent(QCloseEvent *event) +{ + printf("Frame Timing Close Window Event\n"); + done(0); + deleteLater(); + event->accept(); +} +//---------------------------------------------------------------------------- +void FrameTimingDialog_t::closeWindow(void) +{ + //printf("Close Window\n"); + done(0); + deleteLater(); +} +//---------------------------------------------------------------------------- +void FrameTimingDialog_t::updateTimingStats(void) +{ + char stmp[128]; + struct frameTimingStat_t stats; + + getFrameTimingStats( &stats ); + + // Absolute + sprintf( stmp, "%.3f", stats.frameTimeAbs.tgt * 1e3 ); + frameTimeAbs->setText( 1, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeAbs.cur * 1e3 ); + frameTimeAbs->setText( 2, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeAbs.min * 1e3 ); + frameTimeAbs->setText( 3, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeAbs.max * 1e3 ); + frameTimeAbs->setText( 4, tr(stmp) ); + + // Delta + sprintf( stmp, "%.3f", stats.frameTimeDel.tgt * 1e3 ); + frameTimeDel->setText( 1, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeDel.cur * 1e3 ); + frameTimeDel->setText( 2, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeDel.min * 1e3 ); + frameTimeDel->setText( 3, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeDel.max * 1e3 ); + frameTimeDel->setText( 4, tr(stmp) ); + + // Work + sprintf( stmp, "lt %.3f", stats.frameTimeWork.tgt * 1e3 ); + frameTimeWork->setText( 1, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeWork.cur * 1e3 ); + frameTimeWork->setText( 2, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeWork.min * 1e3 ); + frameTimeWork->setText( 3, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeWork.max * 1e3 ); + frameTimeWork->setText( 4, tr(stmp) ); + + // Idle + sprintf( stmp, "gt %.3f", stats.frameTimeIdle.tgt * 1e3 ); + frameTimeIdle->setText( 1, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeIdle.cur * 1e3 ); + frameTimeIdle->setText( 2, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeIdle.min * 1e3 ); + frameTimeIdle->setText( 3, tr(stmp) ); + + sprintf( stmp, "%.3f", stats.frameTimeIdle.max * 1e3 ); + frameTimeIdle->setText( 4, tr(stmp) ); + + // Work % + sprintf( stmp, "lt %.1f", 100.0 * stats.frameTimeWork.tgt / stats.frameTimeAbs.tgt ); + frameTimeWorkPct->setText( 1, tr(stmp) ); + + sprintf( stmp, "%.1f", 100.0 * stats.frameTimeWork.cur / stats.frameTimeAbs.tgt ); + frameTimeWorkPct->setText( 2, tr(stmp) ); + + sprintf( stmp, "%.1f", 100.0 * stats.frameTimeWork.min / stats.frameTimeAbs.tgt ); + frameTimeWorkPct->setText( 3, tr(stmp) ); + + sprintf( stmp, "%.1f", 100.0 * stats.frameTimeWork.max / stats.frameTimeAbs.tgt ); + frameTimeWorkPct->setText( 4, tr(stmp) ); + + // Idle % + sprintf( stmp, "gt %.1f", 100.0 * stats.frameTimeIdle.tgt / stats.frameTimeAbs.tgt ); + frameTimeIdlePct->setText( 1, tr(stmp) ); + + sprintf( stmp, "%.1f", 100.0 * stats.frameTimeIdle.cur / stats.frameTimeAbs.tgt ); + frameTimeIdlePct->setText( 2, tr(stmp) ); + + sprintf( stmp, "%.1f", 100.0 * stats.frameTimeIdle.min / stats.frameTimeAbs.tgt ); + frameTimeIdlePct->setText( 3, tr(stmp) ); + + sprintf( stmp, "%.1f", 100.0 * stats.frameTimeIdle.max / stats.frameTimeAbs.tgt ); + frameTimeIdlePct->setText( 4, tr(stmp) ); + + // Late Count + sprintf( stmp, "%u", stats.lateCount ); + frameLateCount->setText( 1, tr("0") ); + frameLateCount->setText( 2, tr(stmp) ); + + tree->viewport()->update(); +} +//---------------------------------------------------------------------------- +void FrameTimingDialog_t::updatePeriodic(void) +{ + updateTimingStats(); +} +//---------------------------------------------------------------------------- +void FrameTimingDialog_t::timingEnableChanged(int state) +{ + setFrameTimingEnable( state != Qt::Unchecked ); +} +//---------------------------------------------------------------------------- +void FrameTimingDialog_t::resetTimingClicked(void) +{ + resetFrameTiming(); +} +//---------------------------------------------------------------------------- diff --git a/src/drivers/Qt/FrameTimingStats.h b/src/drivers/Qt/FrameTimingStats.h new file mode 100644 index 00000000..b63a778f --- /dev/null +++ b/src/drivers/Qt/FrameTimingStats.h @@ -0,0 +1,55 @@ +// FrameTimingStats.h +// + +#pragma once + +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include "Qt/main.h" + +class FrameTimingDialog_t : public QDialog +{ + Q_OBJECT + + public: + FrameTimingDialog_t(QWidget *parent = 0); + ~FrameTimingDialog_t(void); + + protected: + void closeEvent(QCloseEvent *event); + + QTimer *updateTimer; + QCheckBox *timingEnable; + QTreeWidgetItem *frameTimeAbs; + QTreeWidgetItem *frameTimeDel; + QTreeWidgetItem *frameTimeWork; + QTreeWidgetItem *frameTimeWorkPct; + QTreeWidgetItem *frameTimeIdle; + QTreeWidgetItem *frameTimeIdlePct; + QTreeWidgetItem *frameLateCount; + + QTreeWidget *tree; + + private: + void updateTimingStats(void); + + public slots: + void closeWindow(void); + private slots: + void updatePeriodic(void); + void resetTimingClicked(void); + void timingEnableChanged(int state); + +}; diff --git a/src/drivers/Qt/InputConf.cpp b/src/drivers/Qt/InputConf.cpp index ddf2912d..56d88a23 100644 --- a/src/drivers/Qt/InputConf.cpp +++ b/src/drivers/Qt/InputConf.cpp @@ -238,7 +238,7 @@ InputConfDialog_t::~InputConfDialog_t(void) //---------------------------------------------------------------------------- void InputConfDialog_t::closeEvent(QCloseEvent *event) { - printf("Hot Key Close Window Event\n"); + printf("Input Config Close Window Event\n"); done(0); deleteLater(); event->accept(); diff --git a/src/drivers/Qt/sdl-throttle.cpp b/src/drivers/Qt/sdl-throttle.cpp index f94612b8..9729fc89 100644 --- a/src/drivers/Qt/sdl-throttle.cpp +++ b/src/drivers/Qt/sdl-throttle.cpp @@ -19,8 +19,12 @@ static const double Normal = 1.0; // 1x speed (around 60 fps on NTSC) static uint32 frameLateCounter = 0; static double Lasttime=0, Nexttime=0, Latetime=0; static double desired_frametime = (1.0 / 60.099823); -static double frameDeltaMin = 99999.0; -static double frameDeltaMax = 0.0; +static double frameDeltaCur = 0.0; +static double frameDeltaMin = 1.0; +static double frameDeltaMax = 0.0; +static double frameIdleCur = 0.0; +static double frameIdleMin = 1.0; +static double frameIdleMax = 0.0; static bool keepFrameTimeStats = false; static int InFrame = 0; double g_fpsScale = Normal; // used by sdl.cpp @@ -87,7 +91,7 @@ static void setTimer( double hz ) Lasttime = getHighPrecTimeStamp(); Nexttime = Lasttime + desired_frametime; - Latetime = Nexttime + desired_frametime; + Latetime = Nexttime + (desired_frametime*0.50); } #endif @@ -110,6 +114,61 @@ int setTimingMode( int mode ) return 0; } +void setFrameTimingEnable( bool enable ) +{ + keepFrameTimeStats = enable; +} + +int getFrameTimingStats( struct frameTimingStat_t *stats ) +{ + stats->enabled = keepFrameTimeStats; + stats->lateCount = frameLateCounter; + + stats->frameTimeAbs.tgt = desired_frametime; + stats->frameTimeAbs.cur = frameDeltaCur; + stats->frameTimeAbs.min = frameDeltaMin; + stats->frameTimeAbs.max = frameDeltaMax; + + stats->frameTimeDel.tgt = 0.0; + stats->frameTimeDel.cur = frameDeltaCur - desired_frametime; + stats->frameTimeDel.min = frameDeltaMin - desired_frametime; + stats->frameTimeDel.max = frameDeltaMax - desired_frametime; + + stats->frameTimeIdle.tgt = desired_frametime * 0.50; + stats->frameTimeIdle.cur = frameIdleCur; + stats->frameTimeIdle.min = frameIdleMin; + stats->frameTimeIdle.max = frameIdleMax; + + stats->frameTimeWork.tgt = desired_frametime - stats->frameTimeIdle.tgt; + stats->frameTimeWork.cur = desired_frametime - frameIdleCur; + stats->frameTimeWork.min = desired_frametime - frameIdleMax; + stats->frameTimeWork.max = desired_frametime - frameIdleMin; + + if ( stats->frameTimeWork.cur < 0 ) + { + stats->frameTimeWork.cur = 0; + } + if ( stats->frameTimeWork.min < 0 ) + { + stats->frameTimeWork.min = 0; + } + if ( stats->frameTimeWork.max < 0 ) + { + stats->frameTimeWork.max = 0; + } + + return 0; +} + +void resetFrameTiming(void) +{ + frameLateCounter = 0; + frameDeltaMax = 0.0; + frameDeltaMin = 1.0; + frameIdleMax = 0.0; + frameIdleMin = 1.0; +} + /* LOGMUL = exp(log(2) / 3) * * This gives us a value such that if we do x*=LOGMUL three times, @@ -177,23 +236,24 @@ SpeedThrottle(void) return 0; /* Done waiting */ } double time_left; - double cur_time; + double cur_time, idleStart; double frame_time = desired_frametime; + double halfFrame = 0.500 * frame_time; double quarterFrame = 0.250 * frame_time; - cur_time = getHighPrecTimeStamp(); + idleStart = cur_time = getHighPrecTimeStamp(); if (Lasttime < 1.0) { Lasttime = cur_time; - Latetime = Lasttime + frame_time; + Latetime = Lasttime + 2.0*frame_time; } if (!InFrame) { InFrame = 1; Nexttime = Lasttime + frame_time; - Latetime = Nexttime + frame_time; + Latetime = Nexttime + halfFrame; } if (cur_time >= Nexttime) @@ -266,30 +326,40 @@ SpeedThrottle(void) { if ( keepFrameTimeStats ) { - double frameDelta; - frameDelta = (cur_time - Lasttime); + frameDeltaCur = (cur_time - Lasttime); - if ( frameDelta < frameDeltaMin ) + if ( frameDeltaCur < frameDeltaMin ) { - frameDeltaMin = frameDelta; + frameDeltaMin = frameDeltaCur; } - if ( frameDelta > frameDeltaMax ) + if ( frameDeltaCur > frameDeltaMax ) { - frameDeltaMax = frameDelta; + frameDeltaMax = frameDeltaCur; + } + + frameIdleCur = (cur_time - idleStart); + + if ( frameIdleCur < frameIdleMin ) + { + frameIdleMin = frameIdleCur; + } + if ( frameIdleCur > frameIdleMax ) + { + frameIdleMax = frameIdleCur; } //printf("Frame Delta: %f us min:%f max:%f \n", frameDelta * 1e6, frameDeltaMin * 1e6, frameDeltaMax * 1e6 ); //printf("Frame Sleep Time: %f Target Error: %f us\n", time_left * 1e6, (cur_time - Nexttime) * 1e6 ); } Lasttime = Nexttime; Nexttime = Lasttime + frame_time; - Latetime = Nexttime + frame_time; + Latetime = Nexttime + halfFrame; if ( cur_time >= Nexttime ) { Lasttime = cur_time; Nexttime = Lasttime + frame_time; - Latetime = Nexttime + frame_time; + Latetime = Nexttime + halfFrame; } return 0; /* Done waiting */ } diff --git a/src/drivers/Qt/throttle.h b/src/drivers/Qt/throttle.h index 410ebff9..5a69b408 100644 --- a/src/drivers/Qt/throttle.h +++ b/src/drivers/Qt/throttle.h @@ -3,3 +3,44 @@ int SpeedThrottle(void); void RefreshThrottleFPS(void); int getTimingMode(void); int setTimingMode(int mode); + + +struct frameTimingStat_t +{ + + struct { + double tgt; + double cur; + double min; + double max; + } frameTimeAbs; + + struct { + double tgt; + double cur; + double min; + double max; + } frameTimeDel; + + struct { + double tgt; + double cur; + double min; + double max; + } frameTimeWork; + + struct { + double tgt; + double cur; + double min; + double max; + } frameTimeIdle; + + unsigned int lateCount; + + bool enabled; +}; + +void resetFrameTiming(void); +void setFrameTimingEnable( bool enable ); +int getFrameTimingStats( struct frameTimingStat_t *stats );