Added profiler per thread logging.

src/drivers/Qt/AviRecord.cpp

@@ -2580,6 +2580,7 @@ int FCEUD_AviGetFormatOpts( std::vector <std::string> &formatList )
 AviRecordDiskThread_t::AviRecordDiskThread_t( QObject *parent )
 	: QThread(parent)
 {
+	setObjectName( QString("AviRecordDiskThread") );
 }
 //----------------------------------------------------
 AviRecordDiskThread_t::~AviRecordDiskThread_t(void)

src/drivers/Qt/ConsoleWindow.cpp

@@ -125,6 +125,13 @@ consoleWin_t::consoleWin_t(QWidget *parent)
 
 	printf("Running on Platform: %s\n", QGuiApplication::platformName().toStdString().c_str() );
 
+	QThread *thread = QThread::currentThread();
+
+	if (thread)
+	{
+		thread->setObjectName( QString("MainThread") );
+	}
+
 	QApplication::setStyle( new fceuStyle() );
 
 	initHotKeys();
@@ -4604,6 +4611,9 @@ void consoleWin_t::updatePeriodic(void)
 
 	updateCounter++;
 
+#ifdef __FCEU_PROFILER_ENABLE__
+		FCEU_profiler_log_thread_activity();
+#endif
    return;
 }
 
@@ -4614,6 +4624,7 @@ emulatorThread_t::emulatorThread_t( QObject *parent )
 	pself = 0;
 	#endif
 
+	setObjectName( QString("EmulationThread") );
 }
 
 #if defined(__linux__) 

src/drivers/Qt/TraceLogger.cpp

@@ -2507,6 +2507,7 @@ void QTraceLogView::paintEvent(QPaintEvent *event)
 TraceLogDiskThread_t::TraceLogDiskThread_t( QObject *parent )
 	: QThread(parent)
 {
+	setObjectName( QString("TraceLogDiskThread") );
 }
 //----------------------------------------------------
 TraceLogDiskThread_t::~TraceLogDiskThread_t(void)

src/drivers/Qt/fceuWrapper.cpp

@@ -53,6 +53,7 @@
 #include "../../cheat.h"
 #include "../../movie.h"
 #include "../../state.h"
+#include "../../profiler.h"
 #include "../../version.h"
 
 #ifdef _S9XLUA_H
@@ -1465,6 +1466,9 @@ int  fceuWrapperUpdate( void )
 
 		emulatorHasMutex = 0;
 
+#ifdef __FCEU_PROFILER_ENABLE__
+		FCEU_profiler_log_thread_activity();
+#endif
 		while ( SpeedThrottle() )
 		{
 			// Input device processing is in main thread
@@ -1478,6 +1482,9 @@ int  fceuWrapperUpdate( void )
 
 		emulatorHasMutex = 0;
 
+#ifdef __FCEU_PROFILER_ENABLE__
+		FCEU_profiler_log_thread_activity();
+#endif
 		msleep( 100 );
 	}
 	return 0;

src/profiler.cpp

@@ -23,6 +23,10 @@
 
 #include <stdio.h>
 
+#ifdef __QT_DRIVER__
+#include <QThread>
+#endif
+
 #if defined(__linux__) || defined(__APPLE__) || defined(__unix__)
 #include <unistd.h>
 #endif
@@ -37,6 +41,7 @@
 
 namespace FCEU
 {
+static thread_local profileExecVector execList;
 static thread_local profilerFuncMap threadProfileMap;
 
 FILE *profilerManager::pLog = nullptr;
@@ -64,10 +69,8 @@ void timeStampRecord::readNew(void)
 {
 #if defined(__linux__) || defined(__APPLE__) || defined(__unix__)
 	clock_gettime( CLOCK_REALTIME, &ts );
-#elif defined(WIN32)
-	QueryPerformanceCounter((LARGE_INTEGER*)&ts);
 #else
-	ts = 0;
+	QueryPerformanceCounter((LARGE_INTEGER*)&ts);
 #endif
 	tsc = rdtsc();
 }
@@ -121,16 +124,19 @@ funcProfileRecord::funcProfileRecord(const char *fileNameStringLiteral,
 	: fileLineNum(fileLineNumber), fileName(fileNameStringLiteral),
 	  funcName(funcNameStringLiteral), comment(commentStringLiteral)
 {
-	min.zero();
+	min.fromSeconds(9);
 	max.zero();
 	sum.zero();
 	numCalls = 0;
 	recursionCount = 0;
+
+	threadProfileMap.addRecord( fileNameStringLiteral, fileLineNumber,
+					funcNameStringLiteral, commentStringLiteral, this);
 }
 //-------------------------------------------------------------------------
 void funcProfileRecord::reset(void)
 {
-	min.zero();
+	min.fromSeconds(9);
 	max.zero();
 	sum.zero();
 	numCalls = 0;
@@ -149,20 +155,9 @@ double funcProfileRecord::average(void)
 //-------------------------------------------------------------------------
 //---- Profile Scoped Function Class
 //-------------------------------------------------------------------------
-profileFuncScoped::profileFuncScoped(const char *fileNameStringLiteral,
+profileFuncScoped::profileFuncScoped( funcProfileRecord *recordIn )
-				     const int   fileLineNumber,
-				     const char *funcNameStringLiteral,
-				     const char *commentStringLiteral)
 {
-	rec = nullptr;
+	rec = recordIn;
-
-	//if (threadProfileMap == nullptr)
-	//{
-	//	threadProfileMap = new profilerFuncMap();
-	//}
-
-	rec = threadProfileMap.findRecord( fileNameStringLiteral, fileLineNumber,
-						funcNameStringLiteral, commentStringLiteral, true);
 
 	if (rec)
 	{
@@ -181,17 +176,70 @@ profileFuncScoped::~profileFuncScoped(void)
 		ts.readNew();
 		dt = ts - start;
 
+		rec->last = dt;
 		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());
+		execList._vec.push_back(*rec);
+
 		threadProfileMap.popStack(rec);
 	}
 }
 //-------------------------------------------------------------------------
+//---- Profile Execution Vector
+//-------------------------------------------------------------------------
+profileExecVector::profileExecVector(void)
+{
+	_vec.reserve( 10000 );
+
+	char threadName[128];
+	char fileName[256];
+
+	strcpy( threadName, "MainThread");
+
+#ifdef __QT_DRIVER__
+	QThread *thread = QThread::currentThread();
+
+	if (thread)
+	{
+		//printf("Thread: %s\n", thread->objectName().toStdString().c_str());
+		strcpy( threadName, thread->objectName().toStdString().c_str());
+	}
+#endif
+	sprintf( fileName, "fceux-profile-%s.log", threadName);
+
+	logFp = ::fopen(fileName, "w");
+
+	if (logFp == nullptr)
+	{
+		printf("Error: Failed to create profiler logfile: %s\n", fileName);
+	}
+}
+//-------------------------------------------------------------------------
+profileExecVector::~profileExecVector(void)
+{
+	if (logFp)
+	{
+		::fclose(logFp);
+	}
+}
+//-------------------------------------------------------------------------
+void profileExecVector::update(void)
+{
+	size_t n = _vec.size();
+
+	for (size_t i=0; i<n; i++)
+	{
+		funcProfileRecord &rec = _vec[i];
+
+		fprintf( logFp, "%s: %u  %f  %f  %f  %f\n", rec.funcName, rec.numCalls, rec.last.toSeconds(), rec.average(), rec.min.toSeconds(), rec.max.toSeconds());
+	}
+	_vec.clear();
+}
+//-------------------------------------------------------------------------
 //---- Profile Function Record Map
 //-------------------------------------------------------------------------
 profilerFuncMap::profilerFuncMap(void)
@@ -207,15 +255,15 @@ profilerFuncMap::~profilerFuncMap(void)
 	//printf("profilerFuncMap Destructor: %p\n", this);
 	pMgr.removeThreadProfiler(this);
 
-	{
+	//{
-		autoScopedLock aLock(_mapMtx);
+	//	autoScopedLock aLock(_mapMtx);
 
-		for (auto it = _map.begin(); it != _map.end(); it++)
+	//	for (auto it = _map.begin(); it != _map.end(); it++)
-		{
+	//	{
-			delete it->second;
+	//		delete it->second;
-		}
+	//	}
-		_map.clear();
+	//	_map.clear();
-	}
+	//}
 }
 //-------------------------------------------------------------------------
 void profilerFuncMap::pushStack(funcProfileRecord *rec)
@@ -228,6 +276,26 @@ void profilerFuncMap::popStack(funcProfileRecord *rec)
 	stack.pop_back();
 }
 //-------------------------------------------------------------------------
+int profilerFuncMap::addRecord(const char *fileNameStringLiteral,
+			      const int   fileLineNumber,
+			      const char *funcNameStringLiteral,
+			      const char *commentStringLiteral,
+			      funcProfileRecord *rec )
+{
+	autoScopedLock aLock(_mapMtx);
+	char lineString[64];
+
+	sprintf( lineString, ":%i", fileLineNumber);
+
+	std::string fname(fileNameStringLiteral);
+
+	fname.append( lineString );
+
+	_map[fname] = rec;
+
+	return 0;
+}
+//-------------------------------------------------------------------------
 funcProfileRecord *profilerFuncMap::findRecord(const char *fileNameStringLiteral,
 					       const int   fileLineNumber,
 					       const char *funcNameStringLiteral,
@@ -363,6 +431,12 @@ int profilerManager::removeThreadProfiler( profilerFuncMap *m, bool shouldDestro
 	return result;
 }
 //-------------------------------------------------------------------------
-//
+} // namespace FCEU
+
+//-------------------------------------------------------------------------
+int FCEU_profiler_log_thread_activity(void)
+{
+	FCEU::execList.update();
+	return 0;
 }
 #endif //  __FCEU_PROFILER_ENABLE__

src/profiler.h

@@ -32,6 +32,7 @@
  */
 #ifdef __FCEU_PROFILER_ENABLE__
 
+#include <stdio.h>
 #include <stdint.h>
 #include <string>
 #include <vector>
@@ -123,7 +124,7 @@ namespace FCEU
 			}
 			else if (ts.tv_sec > op.ts.tv_sec)
 			{
-				res = (ts.tv_sec > op.ts.tv_sec);
+				res = true;
 			}
 			return res;
 		}
@@ -135,9 +136,9 @@ namespace FCEU
 			{
 				res = (ts.tv_nsec < op.ts.tv_nsec);
 			}
-			else if (ts.tv_sec > op.ts.tv_sec)
+			else if (ts.tv_sec < op.ts.tv_sec)
 			{
-				res = (ts.tv_sec < op.ts.tv_sec);
+				res = true;
 			}
 			return res;
 		}
@@ -149,6 +150,13 @@ namespace FCEU
 			tsc = 0;
 		}
 
+		void fromSeconds(unsigned int sec)
+		{
+			ts.tv_sec = sec;
+			ts.tv_nsec = 0;
+			tsc = 0;
+		}
+
 		double toSeconds(void)
 		{
 			double sec = static_cast<double>(ts.tv_sec) + ( static_cast<double>(ts.tv_nsec) * 1.0e-9 );
@@ -213,6 +221,12 @@ namespace FCEU
 			tsc = 0;
 		}
 
+		void fromSeconds(unsigned int sec)
+		{
+			ts = sec * qpcFreq;
+			tsc = 0;
+		}
+
 		double toSeconds(void)
 		{
 			double sec = static_cast<double>(ts) / static_cast<double>(qpcFreq);
@@ -235,6 +249,7 @@ namespace FCEU
 		timeStampRecord min;
 		timeStampRecord max;
 		timeStampRecord sum;
+		timeStampRecord last;
 		unsigned int numCalls;
 		unsigned int recursionCount;
 
@@ -253,20 +268,35 @@ namespace FCEU
 		funcProfileRecord *rec;
 		timeStampRecord start;
 
-		profileFuncScoped(const char *fileNameStringLiteral,
+		profileFuncScoped( funcProfileRecord *recordIn );
-				  const int   fileLineNumber,
-				  const char *funcNameStringLiteral,
-				  const char *commentStringLiteral);
 
 		~profileFuncScoped(void);
 	};
 
+	struct profileExecVector
+	{
+		profileExecVector(void);
+		~profileExecVector(void);
+
+		void update(void);
+
+		std::vector <funcProfileRecord> _vec;
+
+		FILE *logFp;
+	};
+
 	class profilerFuncMap
 	{
 		public:
 			profilerFuncMap();
 			~profilerFuncMap();
 
+			int addRecord(const char *fileNameStringLiteral,
+				      const int   fileLineNumber,
+				      const char *funcNameStringLiteral,
+				      const char *commentStringLiteral,
+				      funcProfileRecord *rec );
+
 			funcProfileRecord *findRecord(const char *fileNameStringLiteral,
 						      const int   fileLineNumber,
 						      const char *funcNameStringLiteral,
@@ -312,7 +342,12 @@ namespace FCEU
 #define  __FCEU_PROFILE_FUNC_NAME__  __func__
 #endif
 
-#define  FCEU_PROFILE_FUNC(id, comment)   FCEU::profileFuncScoped  id( __FILE__, __LINE__, __FCEU_PROFILE_FUNC_NAME__, comment )
+#define  FCEU_PROFILE_FUNC(id, comment)   \
+	static thread_local FCEU::funcProfileRecord  id( __FILE__, __LINE__, __FCEU_PROFILE_FUNC_NAME__, comment ); \
+	FCEU::profileFuncScoped id ## _unique_scope( &id )
+
+
+int FCEU_profiler_log_thread_activity(void);
 
 #else  // __FCEU_PROFILER_ENABLE__ not defined