Initial add of execution profiling debug code. This code is only included in the build if the __FCEU_PROFILER_ENABLE__ macro is set.

src/CMakeLists.txt

@@ -22,6 +22,12 @@ if ( ${QHELP} )
 	add_definitions( -D_USE_QHELP )
 endif()
 
+if ( ${FCEU_PROFILER_ENABLE} )
+	message( STATUS "FCEU Profiler Enabled")
+	add_definitions( -D__FCEU_PROFILER_ENABLE__ )
+endif()
+	
+
 if ( ${QT6} )
 	find_package( Qt6 REQUIRED COMPONENTS Widgets OpenGL OpenGLWidgets ${QtHelpModule})
   	add_definitions( ${Qt6Widgets_DEFINITIONS} ${Qt6Help_DEFINITIONS} ${Qt6OpenGLWidgets_DEFINITIONS} )
@@ -309,6 +315,7 @@ set(SRC_CORE
   	${CMAKE_CURRENT_SOURCE_DIR}/nsf.cpp
   	${CMAKE_CURRENT_SOURCE_DIR}/oldmovie.cpp
   	${CMAKE_CURRENT_SOURCE_DIR}/palette.cpp
+  	${CMAKE_CURRENT_SOURCE_DIR}/profiler.cpp
   	${CMAKE_CURRENT_SOURCE_DIR}/ppu.cpp
   	${CMAKE_CURRENT_SOURCE_DIR}/sound.cpp
   	${CMAKE_CURRENT_SOURCE_DIR}/state.cpp

src/drivers/Qt/ConsoleWindow.cpp

@@ -54,6 +54,7 @@
 #include "../../movie.h"
 #include "../../wave.h"
 #include "../../state.h"
+#include "../../profiler.h"
 #include "../../version.h"
 #include "common/os_utils.h"
 
@@ -4484,6 +4485,7 @@ int consoleWin_t::getPeriodicInterval(void)
 
 void consoleWin_t::transferVideoBuffer(void)
 {
+	FCEU_PROFILE_FUNC(prof, "VideoXfer");
 	if ( nes_shm->blitUpdated )
 	{
 		nes_shm->blitUpdated = 0;
@@ -4525,6 +4527,7 @@ void consoleWin_t::emuFrameFinish(void)
 
 void consoleWin_t::updatePeriodic(void)
 {
+	FCEU_PROFILE_FUNC(prof, "updatePeriodic");
 	static bool eventProcessingInProg = false;
 
 	if ( eventProcessingInProg )

src/fceu.cpp

@@ -36,6 +36,7 @@
 #include "unif.h"
 #include "cheat.h"
 #include "palette.h"
+#include "profiler.h"
 #include "state.h"
 #include "movie.h"
 #include "video.h"
@@ -734,6 +735,7 @@ extern unsigned int frameAdvHoldTimer;
 
 ///Skip may be passed in, if FRAMESKIP is #defined, to cause this to emulate more than one frame
 void FCEUI_Emulate(uint8 **pXBuf, int32 **SoundBuf, int32 *SoundBufSize, int skip) {
+	FCEU_PROFILE_FUNC(prof, "Emulate Single Frame");
 	//skip initiates frame skip if 1, or frame skip and sound skip if 2
 	FCEU_MAYBE_UNUSED int r;
 	int ssize;

src/profiler.cpp

@@ -0,0 +1,257 @@
+/* FCE Ultra - NES/Famicom Emulator
+ *
+ * Copyright notice for this file:
+ *  Copyright (C) 2002 Xodnizel
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301  USA
+ */
+// profiler.cpp
+//
+#ifdef __FCEU_PROFILER_ENABLE__
+
+#include <stdio.h>
+
+#include "utils/mutex.h"
+#include "profiler.h"
+
+namespace FCEU
+{
+static thread_local profilerFuncMap threadProfileMap;
+
+class profilerManager
+{
+	public:
+		profilerManager(void)
+		{
+			printf("profilerManager Constructor\n");
+			if (pLog == nullptr)
+			{
+				pLog = stdout;
+			}
+		}
+
+		~profilerManager(void)
+		{
+			printf("profilerManager Destructor\n");
+			{
+				autoScopedLock aLock(threadListMtx);
+				threadList.clear();
+			}
+
+			if (pLog && (pLog != stdout))
+			{
+				fclose(pLog); pLog = nullptr;
+			}
+		}
+
+		int addThreadProfiler( profilerFuncMap *m )
+		{
+			autoScopedLock aLock(threadListMtx);
+			threadList.push_back(m);
+			return 0;
+		}
+
+		int removeThreadProfiler( profilerFuncMap *m, bool shouldDestroy = false )
+		{
+			int result = -1;
+			autoScopedLock aLock(threadListMtx);
+
+			for (auto it = threadList.begin(); it != threadList.end(); it++)
+			{
+				if (*it == m )
+				{
+					threadList.erase(it);
+					if (shouldDestroy)
+					{
+						delete m;
+					}
+					result = 0;
+					break;
+				}
+			}
+			return result;
+		}
+
+		static FILE *pLog;
+	private:
+
+		mutex  threadListMtx;
+		std::list <profilerFuncMap*> threadList;
+
+};
+FILE *profilerManager::pLog = nullptr;
+
+static profilerManager  pMgr;
+
+//-------------------------------------------------------------------------
+//---- Time Stamp Record
+//-------------------------------------------------------------------------
+void timeStampRecord::readNew(void)
+{
+#if defined(__linux__) || defined(__APPLE__) || defined(__unix__)
+	clock_gettime( CLOCK_REALTIME, &ts );
+#else
+	ts = 0;
+#endif
+}
+
+//-------------------------------------------------------------------------
+//---- Function Profile Record
+//-------------------------------------------------------------------------
+funcProfileRecord::funcProfileRecord(const char *fileNameStringLiteral,
+				     const int   fileLineNumber,
+				     const char *funcNameStringLiteral,
+				     const char *commentStringLiteral)
+
+	: fileLineNum(fileLineNumber), fileName(fileNameStringLiteral),
+	  funcName(funcNameStringLiteral), comment(commentStringLiteral)
+{
+	min.zero();
+	max.zero();
+	sum.zero();
+	numCalls = 0;
+	recursionCount = 0;
+}
+//-------------------------------------------------------------------------
+void funcProfileRecord::reset(void)
+{
+	min.zero();
+	max.zero();
+	sum.zero();
+	numCalls = 0;
+}
+//-------------------------------------------------------------------------
+double funcProfileRecord::average(void)
+{
+	double avg = 0.0;
+
+	if (numCalls)
+	{
+		avg = sum.toSeconds() / static_cast<double>(numCalls);
+	}
+	return avg;
+}
+//-------------------------------------------------------------------------
+//---- Profile Scoped Function Class
+//-------------------------------------------------------------------------
+profileFuncScoped::profileFuncScoped(const char *fileNameStringLiteral,
+				     const int   fileLineNumber,
+				     const char *funcNameStringLiteral,
+				     const char *commentStringLiteral)
+{
+	rec = nullptr;
+
+	//if (threadProfileMap == nullptr)
+	//{
+	//	threadProfileMap = new profilerFuncMap();
+	//}
+
+	rec = threadProfileMap.findRecord( fileNameStringLiteral, fileLineNumber,
+						funcNameStringLiteral, commentStringLiteral, true);
+
+	if (rec)
+	{
+		threadProfileMap.pushStack(rec);
+		start.readNew();
+		rec->numCalls++;
+		rec->recursionCount++;
+	}
+}
+//-------------------------------------------------------------------------
+profileFuncScoped::~profileFuncScoped(void)
+{
+	if (rec)
+	{
+		timeStampRecord ts, dt;
+		ts.readNew();
+		dt = ts - start;
+
+		rec->sum += dt;
+		if (dt < rec->min) rec->min = dt;
+		if (dt > rec->max) rec->max = dt;
+
+		rec->recursionCount--;
+
+		//printf("%s: %u  %f  %f  %f  %f\n", rec->funcName, rec->numCalls, dt.toSeconds(), rec->average(), rec->min.toSeconds(), rec->max.toSeconds());
+		threadProfileMap.popStack(rec);
+	}
+}
+//-------------------------------------------------------------------------
+//---- Profile Function Record Map
+//-------------------------------------------------------------------------
+profilerFuncMap::profilerFuncMap(void)
+{
+	printf("profilerFuncMap Constructor: %p\n", this);
+	pMgr.addThreadProfiler(this);
+}
+//-------------------------------------------------------------------------
+profilerFuncMap::~profilerFuncMap(void)
+{
+	printf("profilerFuncMap Destructor: %p\n", this);
+	pMgr.removeThreadProfiler(this);
+
+	for (auto it = _map.begin(); it != _map.end(); it++)
+	{
+		delete it->second;
+	}
+	_map.clear();
+}
+//-------------------------------------------------------------------------
+void profilerFuncMap::pushStack(funcProfileRecord *rec)
+{
+	stack.push_back(rec);
+}
+//-------------------------------------------------------------------------
+void profilerFuncMap::popStack(funcProfileRecord *rec)
+{
+	stack.pop_back();
+}
+//-------------------------------------------------------------------------
+funcProfileRecord *profilerFuncMap::findRecord(const char *fileNameStringLiteral,
+					       const int   fileLineNumber,
+					       const char *funcNameStringLiteral,
+					       const char *commentStringLiteral,
+					       bool create)
+{
+	char lineString[64];
+	funcProfileRecord *rec = nullptr;
+
+	sprintf( lineString, ":%i", fileLineNumber);
+
+	std::string fname(fileNameStringLiteral);
+
+	fname.append( lineString );
+
+	auto it = _map.find(fname);
+
+	if (it != _map.end())
+	{
+		rec = it->second;
+	}
+	else if (create)
+	{
+		fprintf( pMgr.pLog, "Creating Function Profile Record: %s  %s\n", fname.c_str(), funcNameStringLiteral);
+
+		rec = new funcProfileRecord( fileNameStringLiteral, fileLineNumber,
+						funcNameStringLiteral, commentStringLiteral);
+
+		_map[fname] = rec;
+	}
+	return rec;
+}
+//-------------------------------------------------------------------------
+//
+}
+#endif //  __FCEU_PROFILER_ENABLE__

src/profiler.h

@@ -0,0 +1,220 @@
+/* FCE Ultra - NES/Famicom Emulator
+ *
+ * Copyright notice for this file:
+ *  Copyright (C) 2002 Xodnizel
+ *
+ * This program is free software; you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License as published by
+ * the Free Software Foundation; either version 2 of the License, or
+ * (at your option) any later version.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program; if not, write to the Free Software
+ * Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA  02110-1301  USA
+ */
+// profiler.h
+
+#pragma once
+
+/*
+ *  This module is intended for debug use only. This allows for high precision timing of function
+ *  execution. This functionality is not included in the build unless __FCEU_PROFILER_ENABLE__
+ *  is defined. To check timing on a particular function, add FCEU_PROFILE_FUNC macro to the top
+ *  of the function body in the following manner.
+ *  FCEU_PROFILE_FUNC(prof, "String Literal comment, whatever I want it to say")
+ *  When __FCEU_PROFILER_ENABLE__ is not defined, the FCEU_PROFILE_FUNC macro evaluates to nothing
+ *  so it won't break the regular build by having it used in code.
+ */
+#ifdef __FCEU_PROFILER_ENABLE__
+
+#include <stdint.h>
+#include <string>
+#include <vector>
+#include <list>
+#include <map>
+
+
+#if defined(__linux__) || defined(__APPLE__) || defined(__unix__)
+#include <time.h>
+#endif
+
+namespace FCEU
+{
+	struct timeStampRecord
+	{
+#if defined(__linux__) || defined(__APPLE__) || defined(__unix__)
+		struct timespec ts;
+
+		timeStampRecord& operator = (const timeStampRecord& in)
+		{
+			ts = in.ts;
+			return *this;
+		}
+
+		timeStampRecord& operator += (const timeStampRecord& op)
+		{
+			ts.tv_sec  += op.ts.tv_sec;
+			ts.tv_nsec += op.ts.tv_nsec;
+
+			if (ts.tv_nsec >= 1000000000)
+			{
+				ts.tv_nsec -= 1000000000;
+				ts.tv_sec++;	
+			}
+			return *this;
+		}
+
+		timeStampRecord operator + (const timeStampRecord& op)
+		{
+			timeStampRecord res;
+
+			res.ts.tv_sec  = ts.tv_sec  + op.ts.tv_sec;
+			res.ts.tv_nsec = ts.tv_nsec + op.ts.tv_nsec;
+
+			if (res.ts.tv_nsec >= 1000000000)
+			{
+				res.ts.tv_nsec -= 1000000000;
+				res.ts.tv_sec++;	
+			}
+			return res;
+		}
+
+		timeStampRecord operator - (const timeStampRecord& op)
+		{
+			timeStampRecord res;
+
+			res.ts.tv_sec  = ts.tv_sec  - op.ts.tv_sec;
+			res.ts.tv_nsec = ts.tv_nsec - op.ts.tv_nsec;
+
+			if (res.ts.tv_nsec < 0)
+			{
+				res.ts.tv_nsec += 1000000000;
+				res.ts.tv_sec--;	
+			}
+			return res;
+		}
+
+		bool operator > (const timeStampRecord& op)
+		{
+			bool res = false;
+			if (ts.tv_sec == op.ts.tv_sec)
+			{
+				res = (ts.tv_nsec > op.ts.tv_nsec);
+			}
+			else if (ts.tv_sec > op.ts.tv_sec)
+			{
+				res = (ts.tv_sec > op.ts.tv_sec);
+			}
+			return res;
+		}
+
+		bool operator < (const timeStampRecord& op)
+		{
+			bool res = false;
+			if (ts.tv_sec == op.ts.tv_sec)
+			{
+				res = (ts.tv_nsec < op.ts.tv_nsec);
+			}
+			else if (ts.tv_sec > op.ts.tv_sec)
+			{
+				res = (ts.tv_sec < op.ts.tv_sec);
+			}
+			return res;
+		}
+
+		void zero(void)
+		{
+			ts.tv_sec = 0;
+			ts.tv_nsec = 0;
+		}
+
+		double toSeconds(void)
+		{
+			double sec = static_cast<double>(ts.tv_sec) + ( static_cast<double>(ts.tv_nsec) * 1.0e-9 );
+			return sec;
+		}
+#else	// WIN32
+		uint64_t ts;
+#endif
+
+		void readNew(void);
+
+		//timeStampRecord& operator = (timeStampRecord&);
+	};
+
+	struct funcProfileRecord
+	{
+		const int   fileLineNum;
+		const char *fileName;
+		const char *funcName;
+		const char *comment;
+
+		timeStampRecord min;
+		timeStampRecord max;
+		timeStampRecord sum;
+		unsigned int numCalls;
+		unsigned int recursionCount;
+
+		funcProfileRecord(const char *fileNameStringLiteral,
+				  const int   fileLineNumber,
+				  const char *funcNameStringLiteral,
+				  const char *commentStringLiteral);
+
+		void reset(void);
+
+		double average(void);
+	};
+
+	struct profileFuncScoped
+	{
+		funcProfileRecord *rec;
+		timeStampRecord start;
+
+		profileFuncScoped(const char *fileNameStringLiteral,
+				  const int   fileLineNumber,
+				  const char *funcNameStringLiteral,
+				  const char *commentStringLiteral);
+
+		~profileFuncScoped(void);
+	};
+
+	class profilerFuncMap
+	{
+		public:
+			profilerFuncMap();
+			~profilerFuncMap();
+
+			funcProfileRecord *findRecord(const char *fileNameStringLiteral,
+						      const int   fileLineNumber,
+						      const char *funcNameStringLiteral,
+						      const char *commentStringLiteral,
+						      bool create = false);
+
+			void pushStack(funcProfileRecord *rec);
+			void popStack(funcProfileRecord *rec);
+		private:
+			std::map<std::string, funcProfileRecord*> _map;
+
+			std::vector <funcProfileRecord*> stack;
+	};
+}
+
+#if  defined(__PRETTY_FUNCTION__)
+#define  __FCEU_PROFILE_FUNC_NAME__  __PRETTY_FUNCTION__
+#else
+#define  __FCEU_PROFILE_FUNC_NAME__  __func__
+#endif
+
+#define  FCEU_PROFILE_FUNC(id, comment)   FCEU::profileFuncScoped  id( __FILE__, __LINE__, __FCEU_PROFILE_FUNC_NAME__, comment )
+
+#else  // __FCEU_PROFILER_ENABLE__ not defined
+
+#define  FCEU_PROFILE_FUNC(id, comment)   
+
+#endif // __FCEU_PROFILER_ENABLE__
+

src/utils/mutex.cpp

@@ -60,6 +60,15 @@ autoScopedLock::autoScopedLock( mutex *mtx )
 	}
 }
 
+autoScopedLock::autoScopedLock( mutex &mtx )
+{
+	m = &mtx;
+	if (m)
+	{
+		m->lock();
+	}
+}
+
 autoScopedLock::~autoScopedLock(void)
 {
 	if (m)

src/utils/mutex.h

@@ -32,6 +32,7 @@ namespace FCEU
 	{
 		public:
 			autoScopedLock( mutex *mtx );
+			autoScopedLock( mutex &mtx );
 			~autoScopedLock(void);
 
 		private: