Added some performance logging capabilities and socket cleanup for new broadcast thread sockets

source/glest_game/game/commander.cpp

@@ -234,13 +234,17 @@ void Commander::updateNetwork(){
 
 		GameNetworkInterface *gameNetworkInterface= NetworkManager::getInstance().getGameNetworkInterface();
 
+		perfTimer.start();
 		//update the keyframe
 		gameNetworkInterface->updateKeyframe(world->getFrameCount());
+		SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] gameNetworkInterface->updateKeyframe for %d took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,world->getFrameCount(),perfTimer.getMillis());
 
+		perfTimer.start();
 		//give pending commands
 		for(int i= 0; i < gameNetworkInterface->getPendingCommandCount(); ++i){
 			giveNetworkCommand(gameNetworkInterface->getPendingCommand(i));
 		}
+		SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] giveNetworkCommand took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,perfTimer.getMillis());
 		gameNetworkInterface->clearPendingCommands();
 	}
 }
@@ -254,7 +258,6 @@ void Commander::giveNetworkCommandSpecial(const NetworkCommand* networkCommand)
                 case ncstRotateUnit: {
                     SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d] found ncstRotateUnit [%d]\n",__FILE__,__FUNCTION__,__LINE__,networkCommand->getTargetId());
 
-                    //!!!
                     int unitTypeId = networkCommand->getUnitId();
                     int factionIndex = networkCommand->getUnitTypeId();
                     int rotateAmount = networkCommand->getTargetId();

source/glest_game/game/commander.h

@@ -17,12 +17,14 @@
 #include "vec.h"
 #include "selection.h"
 #include "command_type.h"
+#include "platform_util.h"
 
 using std::vector;
 
 namespace Glest{ namespace Game{
 
 using Shared::Graphics::Vec2i;
+using Shared::Platform::Chrono;
 
 class World;
 class Unit;
@@ -42,6 +44,7 @@ private:
 
 private:
     World *world;
+	Chrono perfTimer;
 
 public:
     void init(World *world);

source/glest_game/game/game.cpp

@@ -848,9 +848,9 @@ void Game::render2d(){
 	renderer.renderChatManager(&chatManager);
 
     //debug info
-	if(config.getBool("DebugMode")){
-        string str;
 	
+    string str;
+	if(config.getBool("DebugMode") || difftime(time(NULL),lastRenderLog2d) >= 1){
 		str+= "MouseXY: " + intToStr(mouseX) + "," + intToStr(mouseY)+"\n";
 		str+= "PosObjWord: " + intToStr(gui.getPosObjWorld().x) + "," + intToStr(gui.getPosObjWorld().y)+"\n";
 		str+= "Render FPS: "+intToStr(lastRenderFps)+"\n";
@@ -880,7 +880,9 @@ void Game::render2d(){
 			}
 			str+="\n";
 		}
+	}
 
+	if(config.getBool("DebugMode")){
 		renderer.renderText(
 			str, coreData.getMenuFontNormal(),
 			Vec3f(1.0f), 10, 500, false);
@@ -902,6 +904,11 @@ void Game::render2d(){
 
     //2d mouse
 	renderer.renderMouse2d(mouseX, mouseY, mouse2d, gui.isSelectingPos()? 1.f: 0.f);
+
+	if(difftime(time(NULL),lastRenderLog2d) >= 1) {
+		lastRenderLog2d = time(NULL);
+		SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d Statistics: %s\n",__FILE__,__FUNCTION__,__LINE__,str.c_str());
+	}
 }
 
 

source/glest_game/game/game.h

@@ -77,6 +77,7 @@ private:
 	ParticleSystem *weatherParticleSystem;
 	GameSettings gameSettings;
 	Vec2i lastMousePos;
+	time_t lastRenderLog2d;
 
 public:
     Game(Program *program, const GameSettings *gameSettings);

source/glest_game/main/main.cpp

@@ -262,6 +262,7 @@ SystemFlags debugger;
 int glestMain(int argc, char** argv){
 	SystemFlags::enableNetworkDebugInfo		= true;
     SystemFlags::enableDebugText			= true;
+	SystemFlags::enablePerformanceDebugInfo	= false;
 
 	MainWindow *mainWindow= NULL;
 	Program *program= NULL;
@@ -273,13 +274,14 @@ int glestMain(int argc, char** argv){
 
 		SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
 
-		SystemFlags::enableNetworkDebugInfo = config.getBool("DebugNetwork","0");
+		SystemFlags::enableNetworkDebugInfo = config.getBool("DebugNetwork","false");
-		SystemFlags::enableDebugText = config.getBool("DebugMode","0");
+		SystemFlags::enableDebugText = config.getBool("DebugMode","false");
 		debugLogFile = config.getString("DebugLogFile","");
         if(getGameReadWritePath() != "") {
             debugLogFile = getGameReadWritePath() + debugLogFile;
         }
 		SystemFlags::debugLogFile = debugLogFile.c_str();
+		SystemFlags::enablePerformanceDebugInfo	= config.getBool("DebugPerformance","false");
 
 		NetworkInterface::setDisplayMessageFunction(ExceptionHandler::DisplayMessage);
 		

source/glest_game/network/client_interface.cpp

@@ -36,7 +36,7 @@ namespace Glest{ namespace Game{
 // =====================================================
 
 const int ClientInterface::messageWaitTimeout= 10000;	//10 seconds
-const int ClientInterface::waitSleepTime= 50;
+const int ClientInterface::waitSleepTime= 10;
 
 ClientInterface::ClientInterface(){
 	clientSocket= NULL;
@@ -353,13 +353,21 @@ void ClientInterface::updateKeyframe(int frameCount)
 		{
 			case nmtCommandList:
 			    {
+				Chrono chrono;
+				chrono.start();
+
+				int waitCount = 0;
 				//make sure we read the message
 				NetworkMessageCommandList networkMessageCommandList;
-				while(!receiveMessage(&networkMessageCommandList))
+				while(receiveMessage(&networkMessageCommandList) == false)
 				{
 					sleep(waitSleepTime);
+					waitCount++;
 				}
 
+				SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] receiveMessage took %d msecs, waitCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),waitCount);
+
+				chrono.start();
 				//check that we are in the right frame
 				if(networkMessageCommandList.getFrameCount() != frameCount)
 				{
@@ -378,6 +386,8 @@ void ClientInterface::updateKeyframe(int frameCount)
 					pendingCommands.push_back(*networkMessageCommandList.getCommand(i));
 				}
 
+				SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] transfer network commands took %d msecs\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis());
+
 				done= true;
 			}
 			break;
@@ -574,6 +584,7 @@ void ClientInterface::waitForMessage()
 	Chrono chrono;
 	chrono.start();
 
+	int waitLoopCount = 0;
 	while(getNextMessageType(true) == nmtInvalid)
 	{
 		if(!isConnected())
@@ -597,7 +608,10 @@ void ClientInterface::waitForMessage()
 		}
 
 		sleep(waitSleepTime);
+		waitLoopCount++;
 	}
+
+	SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] waiting took %d msecs, waitLoopCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),waitLoopCount);
 }
 
 void ClientInterface::quitGame(bool userManuallyQuit)

source/glest_game/network/network_interface.cpp

@@ -63,6 +63,9 @@ NetworkMessageType NetworkInterface::getNextMessageType(bool checkHasDataFirst)
 
             SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s] socket->getDataToRead() iPeek = %d, messageType = %d\n",__FILE__,__FUNCTION__,iPeek,messageType);
         }
+		else {
+			SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s] PEEK WARNING, socket->getDataToRead() messageType = %d, dataSize = %d\n",__FILE__,__FUNCTION__,messageType,dataSize);
+		}
 
         //sanity check new message type
         if(messageType<0 || messageType>=nmtCount){

source/glest_game/network/server_interface.cpp

@@ -227,6 +227,8 @@ void ServerInterface::update()
 }
 
 void ServerInterface::updateKeyframe(int frameCount){
+	Chrono chrono;
+	chrono.start();
 
 	NetworkMessageCommandList networkMessageCommandList(frameCount);
 
@@ -241,8 +243,12 @@ void ServerInterface::updateKeyframe(int frameCount){
 		}
 	}
 
+	SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] build command list took %d msecs, networkMessageCommandList.getCommandCount() = %d, frameCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),networkMessageCommandList.getCommandCount(),frameCount);
+
 	//broadcast commands
 	broadcastMessage(&networkMessageCommandList);
+
+	SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] broadcastMessage took %d msecs, networkMessageCommandList.getCommandCount() = %d, frameCount = %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis(),networkMessageCommandList.getCommandCount(),frameCount);
 }
 
 void ServerInterface::waitUntilReady(Checksum* checksum){

source/shared_lib/include/platform/posix/socket.h

@@ -120,7 +120,8 @@ public:
 
 	static string getHostName();
 	static string getIp();
-	bool isSocketValid(PLATFORM_SOCKET *validateSocket=NULL) const;
+	bool isSocketValid() const;
+	static bool isSocketValid(const PLATFORM_SOCKET *validateSocket);
 
 protected:
 	static void throwException(string str);

source/shared_lib/include/util/util.h

@@ -34,11 +34,13 @@ public:
 
     enum DebugType {
         debugSystem,
-        debugNetwork
+        debugNetwork,
+		debugPerformance
     };
 
     static bool enableDebugText;
     static bool enableNetworkDebugInfo;
+	static bool enablePerformanceDebugInfo;
     static const char *debugLogFile;
 
     static void OutputDebug(DebugType type, const char *fmt, ...);

source/shared_lib/sources/platform/posix/socket.cpp

@@ -650,17 +650,21 @@ std::vector<std::string> Socket::getLocalIPAddressList() {
 	return ipList;
 }
 
-bool Socket::isSocketValid(PLATFORM_SOCKET *validateSocket) const {
+bool Socket::isSocketValid() const {
+	return Socket::isSocketValid(&sock);
+}
+
+bool Socket::isSocketValid(const PLATFORM_SOCKET *validateSocket) {
 #ifdef WIN32
 	if(validateSocket == NULL) {
-		return (sock != INVALID_SOCKET);
+		return false;
 	}
 	else {
 		return (*validateSocket != INVALID_SOCKET);
 	}
 #else
 	if(validateSocket == NULL) {
-		return (sock > 0);
+		return false;
 	}
 	else {
 		return (*validateSocket > 0);
@@ -726,7 +730,7 @@ bool Socket::hasDataToRead(std::map<PLATFORM_SOCKET,bool> &socketTriggeredList)
             itermap != socketTriggeredList.end(); itermap++)
         {
         	PLATFORM_SOCKET socket = itermap->first;
-            if(socket > 0)
+            if(Socket::isSocketValid(&socket) == true)
             {
                 FD_SET(socket, &rfds);
                 imaxsocket = max(socket,imaxsocket);
@@ -784,7 +788,7 @@ bool Socket::hasDataToRead(PLATFORM_SOCKET socket)
 {
     bool bResult = false;
 
-    if(socket > 0)
+    if(Socket::isSocketValid(&socket) == true)
     {
         fd_set rfds;
         struct timeval tv;
@@ -1452,6 +1456,15 @@ void BroadCastClientSocketThread::execute() {
 			setRunningStatus(false);
 			SystemFlags::OutputDebug(SystemFlags::debugNetwork,"Broadcast Client thread is exiting\n");
 		}
+
+#ifndef WIN32
+        ::close(bcfd);
+        bcfd = INVALID_SOCKET;
+#else
+        ::closesocket(bcfd);
+        bcfd = -1;
+#endif
+
     }
 
     SystemFlags::OutputDebug(SystemFlags::debugNetwork,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__);
@@ -1725,7 +1738,7 @@ void BroadCastSocketThread::execute() {
 	for( pn = 1; ; pn++ )
 	{
 		for(unsigned int idx = 0; idx < ipList.size() && idx < MAX_NIC_COUNT; idx++) {
-			if( bcfd[idx] > 0  ) {
+			if( Socket::isSocketValid(&bcfd[idx]) == true ) {
 				try {
 					// Send this machine's host name and address in hostname:n.n.n.n format
 					sprintf(buff,"%s",myhostname);
@@ -1779,6 +1792,18 @@ void BroadCastSocketThread::execute() {
 		}
 	}
 
+	for(unsigned int idx = 0; idx < ipList.size() && idx < MAX_NIC_COUNT; idx++) {
+		if( Socket::isSocketValid(&bcfd[idx]) == true ) {
+#ifndef WIN32
+        ::close(bcfd[idx]);
+        bcfd[idx] = INVALID_SOCKET;
+#else
+        ::closesocket(bcfd[idx]);
+        bcfd[idx] = -1;
+#endif
+		}
+	}
+
 	setRunningStatus(false);
 	SystemFlags::OutputDebug(SystemFlags::debugNetwork,"Broadcast thread is exiting\n");
 

source/shared_lib/sources/util/util.cpp

@@ -37,6 +37,8 @@ namespace Shared{ namespace Util{
 
 bool SystemFlags::enableDebugText				= false;
 bool SystemFlags::enableNetworkDebugInfo		= false;
+bool SystemFlags::enablePerformanceDebugInfo	= false;
+
 const char * SystemFlags::debugLogFile			= NULL;
 ofstream SystemFlags::fileStream;
 int SystemFlags::lockFile						= -1;
@@ -83,7 +85,8 @@ void SystemFlags::Close() {
 
 void SystemFlags::OutputDebug(DebugType type, const char *fmt, ...) {
     if((type == debugSystem		 && SystemFlags::enableDebugText == false) ||
-       (type == debugNetwork && SystemFlags::enableNetworkDebugInfo == false)) {
+       (type == debugNetwork	 && SystemFlags::enableNetworkDebugInfo == false ||
+	    type == debugPerformance && SystemFlags::enablePerformanceDebugInfo == false)) {
         return;
     }