From f1abe148ea1f0513229d59126d4a57056b4bf69b Mon Sep 17 00:00:00 2001 From: Mark Vejvoda Date: Mon, 11 Nov 2013 04:46:49 +0000 Subject: [PATCH] - bugfix for background crc thread shutdown - more performance monitoring and better output of only warnings --- source/glest_game/game/game.cpp | 106 ++++++------------ source/glest_game/game/game.h | 1 + source/glest_game/world/world.cpp | 32 +++++- .../platform/common/simple_threads.cpp | 6 + 4 files changed, 69 insertions(+), 76 deletions(-) diff --git a/source/glest_game/game/game.cpp b/source/glest_game/game/game.cpp index 4acb9eee..433a2fc9 100644 --- a/source/glest_game/game/game.cpp +++ b/source/glest_game/game/game.cpp @@ -1799,15 +1799,11 @@ void Game::update() { (NetworkManager::getInstance().getGameNetworkInterface() != NULL && NetworkManager::getInstance().getGameNetworkInterface()->getQuit())); - //if(pendingQuitError) printf("#1 pendingQuitError = %d, quitPendingIndicator = %d, errorMessageBox.getEnabled() = %d\n",pendingQuitError,quitPendingIndicator,errorMessageBox.getEnabled()); - if(pendingQuitError == true && (this->masterserverMode == true || (mainMessageBox.getEnabled() == false && errorMessageBox.getEnabled() == false))) { if(SystemFlags::getSystemSettingType(SystemFlags::debugSystem).enabled) SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__); - //printf("#2 pendingQuitError = %d, quitPendingIndicator = %d, errorMessageBox.getEnabled() = %d\n",pendingQuitError,quitPendingIndicator,errorMessageBox.getEnabled()); - quitTriggeredIndicator = true; return; } @@ -1846,7 +1842,6 @@ void Game::update() { int updateLoops= getUpdateLoops(); // Temp speed boost when player first joins an in progress game - //if(this->initialResumeSpeedLoops == true && updateLoops == 1) { if(this->initialResumeSpeedLoops == true) { printf("Resume In Progress Game: %d\n",__LINE__); @@ -1855,34 +1850,12 @@ void Game::update() { } chronoGamePerformanceCounts.start(); - //NetworkManager &networkManager= NetworkManager::getInstance(); bool enableServerControlledAI = this->gameSettings.getEnableServerControlledAI(); - //bool isNetworkGame = this->gameSettings.isNetworkGame(); - //NetworkRole role = networkManager.getNetworkRole(); if(role == nrClient && updateLoops == 1 && world.getFrameCount() >= (gameSettings.getNetworkFramePeriod() * 2) ) { ClientInterface *clientInterface = dynamic_cast(networkManager.getClientInterface()); if(clientInterface != NULL) { uint64 lastNetworkFrameFromServer = clientInterface->getCachedLastPendingFrameCount(); -//// if(lastNetworkFrameFromServer > 0 && lastNetworkFrameFromServer > (world.getFrameCount() + gameSettings.getNetworkFramePeriod())+1) { -//// //if(lastNetworkFrameFromServer > 0 && lastNetworkFrameFromServer > world.getFrameCount()) { -//// int frameDifference = ((lastNetworkFrameFromServer - world.getFrameCount()) / gameSettings.getNetworkFramePeriod()) * gameSettings.getNetworkFramePeriod(); -//// -//// //int frameDifference = lastNetworkFrameFromServer - world.getFrameCount(); -// if(framesToCatchUpAsClient==0){ -// if(lastNetworkFrameFromServer > 0 && lastNetworkFrameFromServer > (world.getFrameCount() + gameSettings.getNetworkFramePeriod()/4)) { -// //if(lastNetworkFrameFromServer > 0 && lastNetworkFrameFromServer > world.getFrameCount()) { -// int frameDifference = lastNetworkFrameFromServer - world.getFrameCount(); -// printf("Client will speed up: %d frames lastNetworkFrameFromServer: %lld world.getFrameCount() = %d updateLoops = %d\n",frameDifference,(long long int)lastNetworkFrameFromServer,world.getFrameCount(),updateLoops); -// framesToCatchUpAsClient=frameDifference; -// // done below now: updateLoops += frameDifference; -// } -// } -//// //If client is ahead maybe this fixes it ( by titi ): -// if(updateLoops!=0 && lastNetworkFrameFromServer > 0 && world.getFrameCount() > lastNetworkFrameFromServer && (world.getFrameCount()%GameConstants::updateFps)>38 ){ -// printf("Client will slow down because no message has arrived yet. currentFrame=%d \n",world.getFrameCount()); -// updateLoops = 0; -// } ///////////////////////////////// // TTTT new attempt to make things smoother: @@ -1909,7 +1882,7 @@ void Game::update() { } } if(framesNeededToWaitForServerMessage[index]==-1){ - // calc time waiting for message in milliseconds to frames + // calc time waiting for message in milliseconds to frames int64 timeClientWaitedForLastMessage=clientInterface->getTimeClientWaitedForLastMessage(); if(timeClientWaitedForLastMessage>0){ if(SystemFlags::VERBOSE_MODE_ENABLED) printf("world.getFrameCount():%d index %d Client waited:%d ms\n",world.getFrameCount(),index,(int)timeClientWaitedForLastMessage); @@ -1934,7 +1907,6 @@ void Game::update() { int sumOfTooLateFrames=0; bool cleanupStats=false; - for( int i=0;iallowedMaxFallback){ countOfMessagesReceivedTooEarly++; @@ -1987,9 +1959,7 @@ void Game::update() { } } - - gamePerformanceCounts["CalculateNetorkUpdateLoops"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["CalculateNetorkUpdateLoops"] / 2; - chronoGamePerformanceCounts.stop(); + addGamePerformanceCount("CalculateNetworkUpdateLoops",chronoGamePerformanceCounts.getMillis()); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %lld\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chrono.getMillis()); if(showPerfStats) { @@ -2006,7 +1976,13 @@ void Game::update() { // Check to see if we are playing a network game and if any players // have disconnected? bool isNetworkGame = this->gameSettings.isNetworkGame(); + + chronoGamePerformanceCounts.start(); + ReplaceDisconnectedNetworkPlayersWithAI(isNetworkGame, role); + + addGamePerformanceCount("ReplaceDisconnectedNetworkPlayersWithAI",chronoGamePerformanceCounts.getMillis()); + setupPopupMenus(true); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %lld [after ReplaceDisconnectedNetworkPlayersWithAI]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chrono.getMillis()); @@ -2045,27 +2021,7 @@ void Game::update() { processNetworkSynchChecksIfRequired(); - gamePerformanceCounts["CalculateNetworkCRCSynchChecks"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["CalculateNetworkCRCSynchChecks"] / 2; - chronoGamePerformanceCounts.stop(); - - /* - for(int j = 0; j < world.getFactionCount(); ++j) { - Faction *faction = world.getFaction(j); - - //printf("Faction Index = %d enableServerControlledAI = %d, isNetworkGame = %d, role = %d isCPU player = %d scriptManager.getPlayerModifiers(j)->getAiEnabled() = %d\n",j,enableServerControlledAI,isNetworkGame,role,faction->getCpuControl(enableServerControlledAI,isNetworkGame,role),scriptManager.getPlayerModifiers(j)->getAiEnabled()); - - if( faction->getCpuControl(enableServerControlledAI,isNetworkGame,role) == true && - scriptManager.getPlayerModifiers(j)->getAiEnabled() == true) { - - if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] [i = %d] faction = %d, factionCount = %d, took msecs: %lld [before AI updates]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,i,j,world.getFactionCount(),chrono.getMillis()); - - //printf("Faction Index = %d telling AI to do something pendingQuitError = %d\n",j,pendingQuitError); - if(pendingQuitError == false) aiInterfaces[j]->update(); - - if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s Line: %d] [i = %d] faction = %d, factionCount = %d, took msecs: %lld [after AI updates]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,i,j,world.getFactionCount(),chrono.getMillis()); - } - } - */ + addGamePerformanceCount("CalculateNetworkCRCSynchChecks",chronoGamePerformanceCounts.getMillis()); const bool newThreadManager = Config::getInstance().getBool("EnableNewThreadManager","false"); if(newThreadManager == true) { @@ -2129,8 +2085,7 @@ void Game::update() { } } - gamePerformanceCounts["ProcessAIWorkerThreads"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["ProcessAIWorkerThreads"] / 2; - chronoGamePerformanceCounts.stop(); + addGamePerformanceCount("ProcessAIWorkerThreads",chronoGamePerformanceCounts.getMillis()); } if(showPerfStats) { @@ -2195,8 +2150,7 @@ void Game::update() { if(pendingQuitError == false) world.update(); - gamePerformanceCounts["ProcessWorldUpdate"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["ProcessWorldUpdate"] / 2; - chronoGamePerformanceCounts.stop(); + addGamePerformanceCount("ProcessWorldUpdate",chronoGamePerformanceCounts.getMillis()); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %lld [world update i = %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chrono.getMillis(),i); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) chrono.start(); @@ -2237,8 +2191,7 @@ void Game::update() { if(pendingQuitError == false) commander.signalNetworkUpdate(this); - gamePerformanceCounts["ProcessNetworkUpdate"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["ProcessNetworkUpdate"] / 2; - chronoGamePerformanceCounts.stop(); + addGamePerformanceCount("ProcessNetworkUpdate",chronoGamePerformanceCounts.getMillis()); if(showPerfStats) { sprintf(perfBuf,"In [%s::%s] Line: %d took msecs: " MG_I64_SPECIFIER "\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chronoPerf.getMillis()); @@ -2253,8 +2206,7 @@ void Game::update() { gui.update(); - gamePerformanceCounts["ProcessGUIUpdate"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["ProcessGUIUpdate"] / 2; - chronoGamePerformanceCounts.stop(); + addGamePerformanceCount("ProcessGUIUpdate",chronoGamePerformanceCounts.getMillis()); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %lld [gui updating i = %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chrono.getMillis(),i); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) chrono.start(); @@ -2283,8 +2235,7 @@ void Game::update() { renderer.updateParticleManager(rsGame,avgRenderFps); - gamePerformanceCounts["ProcessParticleManager"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["ProcessParticleManager"] / 2; - chronoGamePerformanceCounts.stop(); + addGamePerformanceCount("ProcessParticleManager",chronoGamePerformanceCounts.getMillis()); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %lld [particle manager updating i = %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chrono.getMillis(),i); if(SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).enabled && chrono.getMillis() > 0) chrono.start(); @@ -2352,8 +2303,7 @@ void Game::update() { perfList.push_back(perfBuf); } - gamePerformanceCounts["ProcessMiscNetwork"] = chronoGamePerformanceCounts.getMillis() + gamePerformanceCounts["ProcessMiscNetwork"] / 2; - chronoGamePerformanceCounts.stop(); + addGamePerformanceCount("ProcessMiscNetwork",chronoGamePerformanceCounts.getMillis()); // START - Handle joining in progress games if(role == nrServer) { @@ -2802,31 +2752,39 @@ void Game::update() { } } +void Game::addGamePerformanceCount(string key,int64 value) { + gamePerformanceCounts[key] = value + gamePerformanceCounts[key] / 2; +} + string Game::getGamePerformanceCounts(bool displayWarnings) const { if(gamePerformanceCounts.empty() == true) { return ""; } - bool displayWarningHeader = true; + bool displayWarningHeader = true; + int WARNING_MILLIS = Config::getInstance().getInt("PerformanceWarningMillis","10"); string result = ""; for(std::map::const_iterator iterMap = gamePerformanceCounts.begin(); iterMap != gamePerformanceCounts.end(); ++iterMap) { + if(iterMap->second < WARNING_MILLIS) { + continue; + } + if(result != "") { result += "\n"; } string perfStat = iterMap->first + " = avg millis: " + intToStr(iterMap->second); if(displayWarnings == true) { - int WARNING_MILLIS = Config::getInstance().getInt("PerformanceWarningMillis","10"); - if(iterMap->second >= WARNING_MILLIS) { - if(displayWarningHeader == true) { - displayWarningHeader = false; - printf("=====================================\nPERFORMANCE WARNINGS for World Frame: %d\n",world.getFrameCount()); - } - - printf("*PERFORMANCE WARNING* %s\n",perfStat.c_str()); + //if(iterMap->second >= WARNING_MILLIS) { + if(displayWarningHeader == true) { + displayWarningHeader = false; + printf("=====================================\nPERFORMANCE WARNINGS for World Frame: %d\n",world.getFrameCount()); } + + printf("*PERFORMANCE WARNING* %s\n",perfStat.c_str()); + //} } result += perfStat; diff --git a/source/glest_game/game/game.h b/source/glest_game/game/game.h index 0be10e00..0c3e43a3 100644 --- a/source/glest_game/game/game.h +++ b/source/glest_game/game/game.h @@ -340,6 +340,7 @@ public: void setDisableSpeedChange(bool value) { disableSpeedChange = value; } string getGamePerformanceCounts(bool displayWarnings) const; + void addGamePerformanceCount(string key,int64 value); bool getRenderInGamePerformance() const { return renderInGamePerformance; } private: diff --git a/source/glest_game/world/world.cpp b/source/glest_game/world/world.cpp index b3a6fad7..aea51096 100644 --- a/source/glest_game/world/world.cpp +++ b/source/glest_game/world/world.cpp @@ -824,12 +824,15 @@ void World::updateAllFactionConsumableCosts() { void World::update() { if(SystemFlags::getSystemSettingType(SystemFlags::debugSystem).enabled) SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__); + bool showPerfStats = Config::getInstance().getBool("ShowPerfStats","false"); Chrono chronoPerf; char perfBuf[8096]=""; std::vector perfList; if(showPerfStats) chronoPerf.start(); + Chrono chronoGamePerformanceCounts; + ++frameCount; //time @@ -853,8 +856,12 @@ void World::update() { if(SystemFlags::getSystemSettingType(SystemFlags::debugSystem).enabled) SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__); // objects on the map from tilesets + if(this->game) chronoGamePerformanceCounts.start(); + updateAllTilesetObjects(); + if(this->game) this->game->addGamePerformanceCount("updateAllTilesetObjects",chronoGamePerformanceCounts.getMillis()); + if(showPerfStats) { sprintf(perfBuf,"In [%s::%s] Line: %d took msecs: " MG_I64_SPECIFIER "\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chronoPerf.getMillis()); perfList.push_back(perfBuf); @@ -862,16 +869,23 @@ void World::update() { //units if(getFactionCount() > 0) { + if(this->game) chronoGamePerformanceCounts.start(); + updateAllFactionUnits(); + if(this->game) this->game->addGamePerformanceCount("updateAllFactionUnits",chronoGamePerformanceCounts.getMillis()); + if(showPerfStats) { sprintf(perfBuf,"In [%s::%s] Line: %d took msecs: " MG_I64_SPECIFIER "\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chronoPerf.getMillis()); perfList.push_back(perfBuf); } //undertake the dead + if(this->game) chronoGamePerformanceCounts.start(); + underTakeDeadFactionUnits(); - //} + + if(this->game) this->game->addGamePerformanceCount("underTakeDeadFactionUnits",chronoGamePerformanceCounts.getMillis()); if(showPerfStats) { sprintf(perfBuf,"In [%s::%s] Line: %d took msecs: " MG_I64_SPECIFIER "\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chronoPerf.getMillis()); @@ -879,9 +893,14 @@ void World::update() { } if(SystemFlags::getSystemSettingType(SystemFlags::debugSystem).enabled) SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__); + //food costs + if(this->game) chronoGamePerformanceCounts.start(); + updateAllFactionConsumableCosts(); + if(this->game) this->game->addGamePerformanceCount("updateAllFactionConsumableCosts",chronoGamePerformanceCounts.getMillis()); + if(showPerfStats) { sprintf(perfBuf,"In [%s::%s] Line: %d took msecs: " MG_I64_SPECIFIER "\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__,chronoPerf.getMillis()); perfList.push_back(perfBuf); @@ -889,9 +908,13 @@ void World::update() { if(SystemFlags::getSystemSettingType(SystemFlags::debugSystem).enabled) SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__); //fow smoothing - if(fogOfWarSmoothing && ((frameCount+1) % (fogOfWarSmoothingFrameSkip+1))==0) { + if(fogOfWarSmoothing && ((frameCount+1) % (fogOfWarSmoothingFrameSkip+1)) == 0) { + if(this->game) chronoGamePerformanceCounts.start(); + float fogFactor= static_cast(frameCount % GameConstants::updateFps) / GameConstants::updateFps; minimap.updateFowTex(clamp(fogFactor, 0.f, 1.f)); + + if(this->game) this->game->addGamePerformanceCount("minimap.updateFowTex",chronoGamePerformanceCounts.getMillis()); } if(showPerfStats) { @@ -911,7 +934,12 @@ void World::update() { if(needToTick == true) { //printf("=========== World is about to be updated, current frameCount = %d\n",frameCount); if(SystemFlags::getSystemSettingType(SystemFlags::debugSystem).enabled) SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",extractFileFromDirectoryPath(__FILE__).c_str(),__FUNCTION__,__LINE__); + + if(this->game) chronoGamePerformanceCounts.start(); + tick(); + + if(this->game) this->game->addGamePerformanceCount("tick",chronoGamePerformanceCounts.getMillis()); } if(showPerfStats) { diff --git a/source/shared_lib/sources/platform/common/simple_threads.cpp b/source/shared_lib/sources/platform/common/simple_threads.cpp index bfcdd359..755eecf6 100644 --- a/source/shared_lib/sources/platform/common/simple_threads.cpp +++ b/source/shared_lib/sources/platform/common/simple_threads.cpp @@ -293,6 +293,9 @@ void FileCRCPreCacheThread::execute() { getQuitStatus() == false;) { sleep(25); } + if(getQuitStatus() == true) { + break; + } } if(SystemFlags::VERBOSE_MODE_ENABLED) printf("\t\tStart Processing CRC for techName [%s]\n",techName.c_str()); @@ -326,6 +329,9 @@ void FileCRCPreCacheThread::execute() { getQuitStatus() == false;) { sleep(25); } + if(getQuitStatus() == true) { + break; + } } if(SystemFlags::VERBOSE_MODE_ENABLED) printf("\t\t\tStart Processing CRC for factionName [%s]\n",factionName.c_str());