diff --git a/source/glest_game/game/game.cpp b/source/glest_game/game/game.cpp index 5a484ec3d..28c9a438a 100644 --- a/source/glest_game/game/game.cpp +++ b/source/glest_game/game/game.cpp @@ -339,7 +339,7 @@ void Game::init() void Game::update(){ //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); - // a) Updates non dependant on speed + // a) Updates non dependent on speed //misc updateFps++; @@ -416,19 +416,27 @@ void Game::updateCamera(){ // ==================== render ==================== //render -void Game::render(){ +void Game::render() { + Chrono chrono; + chrono.start(); + //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); renderFps++; render3d(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d render3d() took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); render2d(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d render3d() took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); Renderer::getInstance().swapBuffers(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d render3d() took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); } @@ -820,55 +828,86 @@ void Game::quitGame(){ // ==================== render ==================== void Game::render3d(){ + Chrono chrono; + chrono.start(); + //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); Renderer &renderer= Renderer::getInstance(); //init //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); renderer.reset3d(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); + //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.computeVisibleQuad(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); + //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.loadGameCameraMatrix(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); + //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.setupLighting(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //shadow map //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderShadowsToTexture(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //clear buffers //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.clearBuffers(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //surface //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderSurface(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //selection circles //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderSelectionEffects(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //units //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderUnits(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //objects //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderObjects(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //water //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderWater(); renderer.renderWaterEffects(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //particles //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderParticleManager(rsGame); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); //mouse 3d //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s Line: %d]\n",__FILE__,__FUNCTION__,__LINE__); + chrono.start(); renderer.renderMouse3d(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d renderFps = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,renderFps,chrono.getMillis()); } void Game::render2d(){ diff --git a/source/glest_game/graphics/renderer.cpp b/source/glest_game/graphics/renderer.cpp index 4417d20a1..1ffd108fd 100644 --- a/source/glest_game/graphics/renderer.cpp +++ b/source/glest_game/graphics/renderer.cpp @@ -1241,6 +1241,9 @@ void Renderer::renderSurface(){ } void Renderer::renderObjects(){ + Chrono chrono; + chrono.start(); + const World *world= game->getWorld(); const Map *map= world->getMap(); @@ -1248,6 +1251,9 @@ void Renderer::renderObjects(){ const Texture2D *fowTex= world->getMinimap()->getFowTexture(); Vec3f baseFogColor= world->getTileset()->getFogColor()*computeLightColor(world->getTimeFlow()->getTime()); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); + glPushAttrib(GL_ENABLE_BIT | GL_COLOR_BUFFER_BIT | GL_FOG_BIT | GL_LIGHTING_BIT | GL_TEXTURE_BIT); if(shadows==sShadowMapping){ @@ -1259,15 +1265,22 @@ void Renderer::renderObjects(){ static_cast(modelRenderer)->setDuplicateTexCoords(true); enableProjectiveTexturing(); } + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); glActiveTexture(baseTexUnit); glEnable(GL_COLOR_MATERIAL); glAlphaFunc(GL_GREATER, 0.5f); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); + modelRenderer->begin(true, true, false); int thisTeamIndex= world->getThisTeamIndex(); + int loopCount1 = 0; + int loopCount2 = 0; PosQuadIterator pqi(map, visibleQuad, Map::cellScale); while(pqi.next()){ const Vec2i pos= pqi.getPos(); @@ -1300,16 +1313,23 @@ void Renderer::renderObjects(){ pointCount+= objModel->getVertexCount(); glPopMatrix(); - + loopCount2++; } } + + loopCount1++; } modelRenderer->end(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d loopCount1 = %d loopCount2 = %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,loopCount1,loopCount2,chrono.getMillis()); + chrono.start(); + //restore static_cast(modelRenderer)->setDuplicateTexCoords(true); glPopAttrib(); + + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); } void Renderer::renderWater(){ @@ -2119,6 +2139,8 @@ void Renderer::computeSelected(Selection::UnitContainer &units, const Vec2i &pos // ==================== shadows ==================== void Renderer::renderShadowsToTexture(){ + Chrono chrono; + chrono.start(); if(shadows==sProjected || shadows==sShadowMapping){ @@ -2126,6 +2148,9 @@ void Renderer::renderShadowsToTexture(){ if(shadowMapFrame==0){ + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); + assertGl(); glPushAttrib(GL_ENABLE_BIT | GL_CURRENT_BIT | GL_COLOR_BUFFER_BIT | GL_VIEWPORT_BIT | GL_POLYGON_BIT); @@ -2141,6 +2166,9 @@ void Renderer::renderShadowsToTexture(){ glClear(GL_COLOR_BUFFER_BIT); } + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); + //clear color buffer // //set viewport, we leave one texel always in white to avoid problems @@ -2181,6 +2209,8 @@ void Renderer::renderShadowsToTexture(){ glTranslatef(static_cast(-pos.x), 0, static_cast(-pos.z)); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); } else{ //non directional light @@ -2197,21 +2227,35 @@ void Renderer::renderShadowsToTexture(){ glLoadIdentity(); glRotatef(-90, -1, 0, 0); glTranslatef(-nearestLightPos.x, -nearestLightPos.y-2, -nearestLightPos.z); + + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); } if(shadows==sShadowMapping){ glEnable(GL_POLYGON_OFFSET_FILL); glPolygonOffset(1.0f, 0.001f); + + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); } //render 3d renderUnitsFast(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); + renderObjectsFast(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); //read color buffer glBindTexture(GL_TEXTURE_2D, shadowMapHandle); glCopyTexSubImage2D(GL_TEXTURE_2D, 0, 0, 0, 0, 0, shadowTextureSize, shadowTextureSize); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); + //get elemental matrices Matrix4f matrix1; matrix1[0]= 0.5f; matrix1[4]= 0.f; matrix1[8]= 0.f; matrix1[12]= 0.5f; @@ -2233,6 +2277,9 @@ void Renderer::renderShadowsToTexture(){ glMatrixMode(GL_PROJECTION); glPushMatrix(); + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); + //compute texture matrix glLoadMatrixf(matrix1.ptr()); glMultMatrixf(matrix2.ptr()); @@ -2245,8 +2292,13 @@ void Renderer::renderShadowsToTexture(){ glPopAttrib(); assertGl(); + + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); + chrono.start(); } } + + if(chrono.getMillis() > 0) SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); } diff --git a/source/glest_game/main/main.cpp b/source/glest_game/main/main.cpp index 27ef910ca..eac5d5459 100644 --- a/source/glest_game/main/main.cpp +++ b/source/glest_game/main/main.cpp @@ -305,10 +305,18 @@ int glestMain(int argc, char** argv){ if(debugWorldSynchLogFile == "") { debugWorldSynchLogFile = debugLogFile; } + string debugPerformanceLogFile = config.getString("DebugLogFilePerformance",""); + if(debugPerformanceLogFile == "") { + debugPerformanceLogFile = debugLogFile; + } + string debugNetworkLogFile = config.getString("DebugLogFileNetwork",""); + if(debugNetworkLogFile == "") { + debugNetworkLogFile = debugLogFile; + } SystemFlags::getSystemSettingType(SystemFlags::debugSystem).debugLogFileName = debugLogFile; - SystemFlags::getSystemSettingType(SystemFlags::debugNetwork).debugLogFileName = debugLogFile; - SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).debugLogFileName = debugLogFile; + SystemFlags::getSystemSettingType(SystemFlags::debugNetwork).debugLogFileName = debugNetworkLogFile; + SystemFlags::getSystemSettingType(SystemFlags::debugPerformance).debugLogFileName = debugPerformanceLogFile; SystemFlags::getSystemSettingType(SystemFlags::debugWorldSynch).debugLogFileName = debugWorldSynchLogFile; printf("Startup settings are: debugSystem [%d], debugNetwork [%d], debugPerformance [%d], debugWorldSynch [%d]\n", diff --git a/source/glest_game/main/program.cpp b/source/glest_game/main/program.cpp index d045172fa..465759c54 100644 --- a/source/glest_game/main/program.cpp +++ b/source/glest_game/main/program.cpp @@ -182,23 +182,25 @@ void Program::keyPress(char c){ } void Program::loop(){ - - SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__); + Chrono chrono; + chrono.start(); //render assert(programState != NULL); programState->render(); - SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__); + SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d programState->render took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); //update camera + chrono.start(); while(updateCameraTimer.isTime()){ programState->updateCamera(); } - SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__); + SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d programState->updateCamera took msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); //update world + chrono.start(); while(updateTimer.isTime()){ //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__); @@ -218,14 +220,15 @@ void Program::loop(){ //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__); } - //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__); + SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); //fps timer + chrono.start(); while(fpsTimer.isTime()){ programState->tick(); } - //SystemFlags::OutputDebug(SystemFlags::debugSystem,"In [%s::%s %d]\n",__FILE__,__FUNCTION__,__LINE__); + SystemFlags::OutputDebug(SystemFlags::debugPerformance,"In [%s::%s] Line: %d msecs: %d\n",__FILE__,__FUNCTION__,__LINE__,chrono.getMillis()); } void Program::resize(SizeState sizeState){ diff --git a/source/shared_lib/sources/platform/common/platform_common.cpp b/source/shared_lib/sources/platform/common/platform_common.cpp index c1d4a1800..8bbd94eae 100644 --- a/source/shared_lib/sources/platform/common/platform_common.cpp +++ b/source/shared_lib/sources/platform/common/platform_common.cpp @@ -574,16 +574,18 @@ string extractFileFromDirectoryPath(string filename) string extractDirectoryPathFromFile(string filename) { - size_t lastDirectory_Win = filename.find_last_of('\\'); - size_t lastDirectory_Lin = filename.find_last_of('/'); - size_t lastDirectory = (lastDirectory_Winp(); + currentDebugLog.mutex->p(); (*currentDebugLog.fileStream) << "[" << szBuf2 << "] " << szBuf; (*currentDebugLog.fileStream).flush(); - //currentDebugLog.mutex->v(); + currentDebugLog.mutex->v(); } // output to console else {