Question about server profiling

[selsner]

I am interested in the total time for one server "loop" from profiling. For us it is something like 700ms maximum with ~300 "clients". Is this too much? I am trying to find if our server is too slow or the network might be bad on our side....

[timurhai]

It looks like too big, i think, even for 300 clients.
There are 3 measures: Prep, Proc and Post where are most of yours 700ms?
Prep - reading message.
Proc - process message.
Post - writing an answer message.

[selsner]

Ok, this is a copy paste of a current output of the server.

Code: Select all

Served connections per second: 90
Mon 27 Mar 15:33.14: Server load profiling:
Clients per second: 87.10, Now: 1 
Prep: 0.05, Proc: 318.50, Post: 0.00, Tolal: 318.54 ms

So it takes a long time to process messages. Is there a way to fiurther profile the proc step?

[timurhai]

Wow, i thought that "Prep" (network reading should take the most time).
For now there is no simple way to profile Proc step.
How much CPU load? How much running / total jobs on afserver?

[selsner]

load average is 0.56, the host (8 core 16Gb) is pretty bored. There are 600 jobs in the queue, 17 rendering, 20 ready.

[timurhai]

Strange.
I think that your afserver load should not be so much.
Try to measure after some major changes, for example, most jobs deleted, no jobs running and much more queued/running.

[selsner]

Could it be there is a bug in the profiler? From the code profiler.cpp Line 108:

Code: Select all

	double prep = 0.0;
	double proc = 0.0;
	double post = 0.0;
	for( int i = 0; i < ms_profiles.size(); i++)
	{
		prep += toFloat( ms_profiles[i]->m_tstart   ) - toFloat( ms_profiles[i]->m_tinit   );
		proc += toFloat( ms_profiles[i]->m_tfinish  ) - toFloat( ms_profiles[i]->m_tstart  );
		proc += toFloat( ms_profiles[i]->m_tcollect ) - toFloat( ms_profiles[i]->m_tfinish );
	}
	prep /= double( ms_stat_period ) / 1000.0;
	proc /= double( ms_stat_period ) / 1000.0;
	post /= double( ms_stat_period ) / 1000.0;

In the for loop, should the last line be:

Code: Select all

		post += toFloat( ms_profiles[i]->m_tcollect ) - toFloat( ms_profiles[i]->m_tfinish );

instead of

Code: Select all

		proc += toFloat( ms_profiles[i]->m_tcollect ) - toFloat( ms_profiles[i]->m_tfinish );

post instead of proc ??

[selsner]

I changed it and get about 10ms for proc now (which was constantly 0 before). I also noticed that there were 2 other afserver instances running (for whatever reason) maybe they are making the high times....

[timurhai]

Hi.
Yes, it is a bug in the code!
Can you commit it, please?

[seven11]

While you are fixing the bug, Can you fix the spelling mistake?
Prep: 0.15, Proc: 0.01, Post: 8.50, Tolal: 8.67 ms.

Tolal > Total


Thx
Scott