[TYPO3-dev] Slow BE-Performance in 4.5 - doubled system calls?

[Roland Hager]

Hi Kay,

>  reduced both loading times.
>
> I just sumup the basic steps ;)
>


Thanks for your list. Sadly most of the points where already checked or 
not relevant for us. So I kept seeking deeper ...

First I logged all DB queries using slow query log and a long_query_time 
of 0. Analyzing them with pt-query-digest[1] results in a total 
execution time of 45ms for all 553 queries. So that should not be the 
problem. Round trip time between webserver and db-server is around 
0.389ms and the throughput around 550MB/s

But where's the bottleneck ???

Back to the webserver. I again straced the action "List view of a page" 
as follows:

$ strace -p PIDs -o strace.log -tt -r

That results in a pretty overview of all syscalls and the relative 
execution time. I then summed up some syscalls to see how much they take 
into account.

$ grep poll strace.log | awk '{sum+=$2} END {print sum}'
1.61099

$ grep "stat(" strace.log | awk '{sum+=$2} END {print sum}'
0.46976


So 1.6 seconds are used for polls and nearly 0.5s for stats!

OK we are using a network filesystem for both the core and the 
"fileadmin stuff" so we are used to not have the best performance here. 
But beside the increase of DB queries also the number of stats seems to 
increase more and more with each TYPO3 version. Thus increasing the 
impact for us more and more.

stats using TYPO3 4.4: 758
stats using TYPO3 4.5: 3099


So now what about those poll syscalls? Well it seems that before every 
mysql_query() internally the mysql connection is polled for 
POLLIN|POLLPRI events. I'm not sure why but maybe it's just some kind of 
check to see if the server send some abortion signals. I have 553 poll 
calls which backs nearly the number of queries. 450 of them needed less 
than 1ms but 24 took more than 10ms. Those 24 poll calls alone took 
about 1s. Using TYPO3 4.4 I just have 1 poll call that took longer than 
10ms.
Actually I do not have a proper explanation for that. I already thought 
there might be a scheduling problem on our virtual servers.



Well that's all I got so far. If anybody has further suggestions please 
tell me.

Roland


P.S. All numbers where measured as described in the first post. Same 
server, same Database content, clicking the same page in List view.


[1] http://www.percona.com/doc/percona-toolkit/2.1/