[solved] Engine.profiler is slow to update

[kbrodie]

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.

 

[kbrodie]

Further investigation shows that most the time consumed with updating the statistics (like 99.99%) came from updating the fields "Meshes: ", "Textures: ", "Samples: ".

For now, I've disabled these with an if-statement, so that they only update if the profiler is enabled. We don't do this for all stats (as it was in the past), as we also use them elsewhere in the application.

Now the swap time has been reduced to a meager 0.03ms, the application takes a significant boost in its framerate.

I'd still like to know why those 3 values need so much time, because it means that enabling profiler, will lower the framerate and may show the wrong bottlenecks.

[silent]

2 hours ago, kbrodie said:

because it means that enabling profiler, will lower the framerate and may show the wrong bottlenecks.

Mostly all profilers are not completely free. show_profiler 2 or any other show_profiler_* is not free as well.

These methods probably time consuming due to complex memory usage calculations (you need to check every surface, every texture, every sound and calculate their size each frame). Starting with 2.7 SDK update we are no longer including Microprofile in Release configuratios (since it also consumes some resourced even if web ui is not opened).

Maybe we will also add another counter to see the microprofile update time.

Thanks!

[kbrodie]

That makes sense. And it's good know that Microprofile will be disabled in Release configurations of 2.7 and higher. If and when we decide to upgrade, we can keep it in mind.

Thank you for your information.