Search the Community

Hi all, Using the MicroProfiler to ifnd the bottlenecks in our application, I noticed that our swap times were quite long (between 4 and 6ms), but I couldn't see what part of the swap was so slow. So I altered the "do_swap" method in "engine.cpp" to give me a little more detail (starting at line 2777): // waiting of shaders { MICROPROFILE_SCOPEI("Engine","cpu shaders wait",0xffffffff); while(CPUExt::isRunning()) { } } // flush game { MICROPROFILE_SCOPEI("Engine","cpu flush",0xffffffff); long long frame_end = Timer::getWallClockTimeInUSec(); engine.game->flush(max(0.0, Timer::uSec2Sec(frame_end - frame_begin))); // total time total_time = Timer::uSec2Sec(frame_end - frame_begin); } ///////////////////////////////// // statistics ///////////////////////////////// { MICROPROFILE_SCOPEI("Engine","updating statistics",0xffffffff); // disabled if statements, they render Profiler::getValue meaningless for outside use //if(engine.profiler->isEnabled()) { // charts engine.profiler->setValue(engine.profiler->isEnabled(),"Total: ","ms",getTotalTime() * 1000.0f,50.0f,total_color); engine.profiler->setValue(engine.profiler->isEnabled(),"Update: ","ms",getUpdateTime() * 1000.0f,50.0f,update_color); engine.profiler->setValue(engine.profiler->isEnabled(),"Render: ","ms",getRenderTime() * 1000.0f,50.0f,render_color); engine.profiler->setValue(engine.profiler->isEnabled(),"Interface: ","ms",getInterfaceTime() * 1000.0f,50.0f,interface_color); engine.profiler->setValue(engine.profiler->isEnabled(),"Physics: ","ms",engine.physics->getTotalTime() * 1000.0f,50.0f,physics_color); engine.profiler->setValue(engine.profiler->isEnabled(),"Present: ","ms",max((engine.ifps - total_time) * 1000.0f,0.0f),50.0f,present_color); // system memory statistics #ifdef USE_MEMORY engine.profiler->setValue(engine.profiler->isEnabled(),"Heap: ","MB",Memory::getHeapUsage() / (1024.0f * 1024.0f)); engine.profiler->setValue(engine.profiler->isEnabled(),"Memory: ","MB",Memory::getMemoryUsage() / (1024.0f * 1024.0f)); engine.profiler->setValue(engine.profiler->isEnabled(),"System: ","MB",Memory::getSystemUsage() / (1024.0f * 1024.0f)); engine.profiler->setValue(engine.profiler->isEnabled(),"Allocations: ","",Memory::getNumFrameAllocations()); #endif // render counters engine.profiler->setValue(engine.profiler->isEnabled(),"Meshes: ","MB",engine.renders->getMeshVideoMemoryUsage() / (1024.0f * 1024.0f)); engine.profiler->setValue(engine.profiler->isEnabled(),"Textures: ","MB",engine.renders->getTextureVideoMemoryUsage() / (1024.0f * 1024.0f)); engine.profiler->setValue(engine.profiler->isEnabled(),"Samples: ","MB",engine.sounds->getSampleMemoryUsage() / (1024.0f * 1024.0f)); // render profiler counters //if(show_profiler == PROFILER_RENDER) { engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RLights: ","",engine.render->getNumLights()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RShadows: ","",engine.render->getNumShadows()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RReflections: ","",engine.render->getNumReflections()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RProcedurals: ","",engine.render->getNumProcedurals()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RShaders: ","",engine.render->getNumShaders()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RMaterials: ","",engine.render->getNumMaterials()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RTriangles: ","",engine.render->getNumTriangles()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RPrimitives: ","",engine.render->getNumPrimitives()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RSurfaces: ","",engine.render->getNumSurfaces()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RDecals: ","",engine.render->getNumDecals()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RDips: ","",engine.render->getNumDips()); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RMTris/sec: ","",engine.render->getNumTriangles() * engine.app->getFps() / 1000000.0f); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RKSurf/sec: ","",engine.render->getNumSurfaces() * engine.app->getFps() / 1000.0f); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RKDips/sec: ","",engine.render->getNumDips() * engine.app->getFps() / 1000.0f); engine.profiler->setValue(show_profiler == PROFILER_RENDER,"RSpawn: ","ms",engine.render->getSpawnTime() * 1000.0f); //} // physics profiler counters //if(show_profiler == PROFILER_PHYSICS) { engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PIslands: ","",engine.physics->getNumIslands()); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PBodies: ","",engine.physics->getNumBodies()); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PJoints: ","",engine.physics->getNumJoints()); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PContacts: ","",engine.physics->getNumContacts()); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PBroad: ","ms",engine.physics->getBroadTime() * 1000.0f); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PNarrow: ","ms",engine.physics->getNarrowTime() * 1000.0f); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PUpdate: ","ms",engine.physics->getUpdateTime() * 1000.0f); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PResponse: ","ms",engine.physics->getResponseTime() * 1000.0f); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PIntegrate: ","ms",engine.physics->getIntegrateTime() * 1000.0f); engine.profiler->setValue(show_profiler == PROFILER_PHYSICS,"PSimulation: ","ms",engine.physics->getSimulationTime() * 1000.0f); //} // world profiler counters //if(show_profiler == PROFILER_WORLD) { engine.profiler->setValue(show_profiler == PROFILER_WORLD,"WNodes: ","",Node::getNumNodes()); engine.profiler->setValue(show_profiler == PROFILER_WORLD,"WBodies: ","",Body::getNumBodies()); engine.profiler->setValue(show_profiler == PROFILER_WORLD,"WJoints: ","",Joint::getNumJoints()); engine.profiler->setValue(show_profiler == PROFILER_WORLD,"WSpawn: ","ms",engine.world->getSpawnTime() * 1000.0f); //} // thread profiler counters //if(show_profiler == PROFILER_THREAD) { engine.profiler->setValue(show_profiler == PROFILER_THREAD,"World: ","ms",engine.world->getTotalTime() * 1000.0f,50.0f); engine.profiler->setValue(show_profiler == PROFILER_THREAD,"Sound: ","ms",engine.sound->getTotalTime() * 1000.0f,50.0f); engine.profiler->setValue(show_profiler == PROFILER_THREAD,"PathFind: ","ms",engine.pathfind->getTotalTime() * 1000.0f,50.0f); engine.profiler->setValue(show_profiler == PROFILER_THREAD,"FileSystem: ","ms",engine.filesystem->getTotalTime() * 1000.0f,50.0f); //} //} } After this change the profiler showed (see pic) that it spend most of its time setting values in engine.profiler. Does anyone know why this takes so long? Are there any processes on which engine.profiler must wait? The application uses Unigine 2.3.1. Any help would be greatly appreciated.