profiler issue

[esger.abbink_]

As we have some performance issues we want to use (a) profiler to get quantitative data where the bottlenecks are / time is spent. The Unigine (micro) profiler seems like a good tool to use so we have started adding begin/end sections to our code. However, we are getting some unexpected results.

This is a screenshot of preliminary microprofiler output:

Note that item "4Sim: widget" does not encompass "4Sim: render" and stuff below that. As the begin call for '4Sim widget' is done before the one for '4Sim render' we would expect it to. The image is as expected for the other 4Sim subjects, these encompass the expected subjects.  Also, hard to see, but the Unigine 'swap' subject is not contained within the '4Sim swap' subject. Which is again unexpected. Also unclear to me is why the swap is taking so much time, but due to the unexpected nesting I am not even sure the presented time is reliable.

A simplified version of our code looks like this:

void c4SimProgram::main ()
{
	Unigine::Profiler* profiler = Unigine::Profiler::get () ;

	while (!done ())
	{
		profiler->begin ("4Sim: Total", Unigine::Math::vec4 (220 / 255.0, 20 / 255.0, 60 / 255.0, 1)) ;
		
			profiler->begin ("4Sim: Qt", Unigine::Math::vec4 (50 / 255.0, 205 / 255.0, 50 / 255.0, 1)) ;
		
				m_qapplication->processEvents () ;
		
			profiler->end () ;

			profiler->begin ("4Sim: mainSingleStep", Unigine::Math::vec4 (50 / 255.0, 205 / 255.0, 50 / 255.0, 1)) ;
		
				mainSingleStep();
		
			profiler->end () ;
		
		profiler->end () ;
	}
}



void c4SimProgram::mainSingleStep ()
{
	Unigine::Profiler* profiler = Unigine::Profiler::get () ;
	
	profiler->begin ("4Sim: widget", Unigine::Math::vec4 (0, 191 / 255.0, 255 / 255.0, 1)) ;
		
	Unigine::Render::get ()->setFadeColor (m_fade_color) ;

		preFrame () ;

		m_4sim_widget->step () ;

		postFrame () ;

		m_4sim_widget->swap () ;
			
	profiler->end () ;
		
	profiler->begin ("4Sim: simulation", Unigine::Math::vec4 (255 / 255.0, 140 / 255.0, 0, 1)) ;
				
		m_simulation->update () ;
				
	profiler->end () ;
			
	profiler->begin ("4Sim: frame", Unigine::Math::vec4 (135 / 255.0, 206 / 255.0, 250 / 255.0, 1)) ;

		m_simulation->preFrameStep () ;

		m_simulation->frameStep () ;

	profiler->end () ;

	m_frame_idx++ ;
}


void cQ4SimAppWidget::step ()
{
	Unigine::Profiler* profiler = Unigine::Profiler::get () ;
	
	// update engine
	if ( timer_resize == 0) // don't update when resizing
	{
		profiler->begin ("4Sim: update", Unigine::Math::vec4 (0, 191 / 255.0, 255 / 255.0, 1)) ;
		
			App::update () ;
		
		profiler->end () ;

		m_theprogram.preRender () ;

		if (m_projection_app)
		{
			profiler->begin ("4Sim: projection render", Unigine::Math::vec4 (0, 191 / 255.0, 255 / 255.0, 1)) ;
			
				m_projection_app->render_window () ; // calls App::render ()
		}
		else
		{
			profiler->begin ("4Sim: render", Unigine::Math::vec4 (0, 191 / 255.0, 255 / 255.0, 1)) ;
			
				App::render () ;
		}
		
		profiler->end () ;

		m_theprogram.postRender () ;
	}
}



void cQ4SimAppWidget::swap ()
{
	if (timer_resize == 0)
	{
		Unigine::Profiler* profiler = Unigine::Profiler::get () ;
		
		profiler->begin ("4Sim: swap", Unigine::Math::vec4 (0, 191 / 255.0, 255 / 255.0, 1)) ;
		
			App::swap () ;
		
			glXSwapBuffers (QX11Info::display (), m_window) ;
		
		profiler->end () ;
	}
}

cQ4SimAppWidget is derived from Unigine::App (similar to Qt GL sample)

However, even if I remove all begin/end pairs except for one in mainSingleStep, it still does not encompass the unigine subjects:

What are we doing wrong?

Second issue: as we have a setup with multiple application instances on a single multi-headed server (syncing through shared memory) we would like to profile all instances. The documentation seems to imply the standard port (1337) can be altered from the console. But the only console variables for the profiler seem to be font & size. Even a 'grep -R MICROPROFILE_WEBSERVER_PORT' in the entire source only has one result, its definition. How can we change the port used?

Last question: is it possible to save results for offline analysis (keeping the browser tab open only goes so far).

 

Edited September 20, 2017 by esger.abbink

[esger.abbink_]

Found the answers to the last two issues, so for reference: 

more information about microprofiler can be found here: https://github.com/jonasmr/microprofile

if the default port 1337 is not available it will increase until it finds an available port (or give up after 20 tries)

The html file is self-contained and can be saved for later viewing, csv saves are also supported.

 

Regarding the first problem, if I add another subject around '4Sim widget' that one does encompass everything below it as expected..

[esger.abbink_]

Solved the main issue as well. The engine update function calls endPresent () 

static void engine_update_func() { EngineMicroprofile::endPresent(); MICROPROFILE_SCOPE(Update); engine.engine->do_update(); }
static void engine_render_func() { MICROPROFILE_SCOPE(Render); engine.engine->do_render(); }
static void engine_swap_func() {
	{
		MICROPROFILE_SCOPE(Swap);
		engine.engine->do_swap();
	}
	EngineMicroprofile::beginPresent();
}

which contains a MicroProfileFlip(); This starts a new measuring frame and messes things up. Note that the 'Present' time was indeed invalid, it contained all time spent outside Unigine as well as the actual swap/present time.

Moving the timing of present and doing the flip at the end of our main loop gives expected results.

[silent]

Hi Esger,

Just a small addition, we are using microprofile fork from zeux: https://github.com/zeux/microprofile (from commit: 09c5b98cf46a12aff318321716b128988e1e58ff).

I've also wondering - there is nothing to be patched on engine sources to get things work as expected, all the things you modified in your code?

Thanks!

[esger.abbink_]

Hi Silent,

ah, thanks for the info!

at the moment for testing I have patched engine source to not do begin/endPresent or the flip. I will clean it up, but I don't think it will be possible to do without engine modification as the location of the flip needs to change and the 'Present' timing does not reflect the actual present time spent. Perhaps if we reorder our stuff that would be preventable, but I am not sure that is possible or would not impact other areas. On top of that we are moving to a more multithreaded approach and then even reordering does not help anymore.

I will probably end up modifying the source, making it definable to have these functions do nothing in EngineMicroProfile.cpp so it is the only file impacted. We'll also be changing the visibility of microprofile functions as we need those to time our own threads and there are several static/global components in the profiler so having two copies around (one in application binary, one in unigine library wouldn't be good..).

Happy to provide you the modification if interested.

[silent]

Esger,

Will be interesting to look at the modifications, thanks!