eZ Community » Forums » General » Log number of SQL queries
expandshrink

Log number of SQL queries

Log number of SQL queries

Wednesday 08 April 2015 9:47:42 pm - 5 replies

Hi all,

We host some EZ publish website and I'm very surprised by the number of MySQL that are executed.

For some website almost 800 sql queries are executed (front page!), and even more than 1800 for some other pages (some internal directory).. And each time I access the page, even if I just wait one second between two accesses to the same page.. The pages are slow as you can guess.. Is this usual for EZ Publish ?

So I would like to log  the number of SQL requests executed in apache's access_log..
Then I could do some stats..
I think it should be possible to use the apache_note php function to pass the value from Ez publish to the apache httpd server..

IE:
apache_note('mysql_queries', $some_ezpublish_variable);
Then use some LogFormat with: %{mysql_queries}n

The problem I don't know where to put this PHP code, neither how to obtain the number of queries.
Did anyone succeed in doing that and would like  to share his work ?Any pointers ?

Regards, Luc.
References:
http://php.net/manual/en/function.apache-note.php
http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#formats

Modified on Wednesday 08 April 2015 10:08:36 pm by Luc Dumaine

Thursday 09 April 2015 5:20:48 am

Hello Luc,

Welcome to the eZ Community!

I am sorry your having troubles. I think some learning is in order for you to better understand eZ Publish before jumping into the temporary fixes you describe.

I am very short on time this evening as I am out of the office but was compelled to jump in and respond to your first post.

In short, queries are not the problem here instead your use of caches and other performance improvement tools and features are the answers you really need to leverage.

As a friend of mine (kracker) said to me about your post, "People just won't find a very sympathetic ear to complaints about your custom eZ Publish Web Application's Database access (queries) in this community."

Now while ruff on the edges he means well and what he really means without explaining is that while by default eZ Publish -can- be used by developers poorly which thus can result in high query counts, long running queries, poorly performing page response times, etc ... this is not really an eZ Publish problem as much as it is a problem with developers use of eZ Publish (or lack of it) namely the lack of proper use of a feature which solves many of these concerns the right way: caching.

If you use caching in eZ Publish properly you negate huge amounts of potential or actual performance problems almost right away with a solid return on investment in refactoring your application to leverage cached usage. Now eZ Publish provides a lot of caching features enabled by default while others you must use / implement within the custom parts of your application yourself.

Caching in eZ Publish has a lot of support for many different kinds of caching at several different levels but I will touch upon a few that you will want to leverage. One of the most important is template cache blocks which are tools which exist for the developer to use when writing eZ Publish templates to cache the results of the template's operations and resulting compiled resulting output. I've optimized many sites over the years using cache blocks to greatly improve performance while retaining key dynamic features required by the application.

You would be served well to study eZ Publish Caching and Server Optimization articles on share.ez.no/learn 

There are quite a few so I link to a specific google search which returns many of them at once, you should read and leverage all of them: https://www.google.com/search?q=cache%20site%3Ashare.ez.no%2Flearn

Another point I want to cover carefully is the investment of resources to solve a problem.

In short, what you suggest is a poor choice for an investment. Query counting is quite superficial and pales in comparison to query analysis and application database code review. In the end in eZ if you need the data, you need the data, so you fetch, yes you can do things to move the cost around and save some of the costs but in the end it's a choice between requirements, features and the costs they bring to the table. Some move some functionality to the client side to change the cost and increase server side caching. Others buy bigger servers. Still others refactor their templates to reduce costs and some do all of that and implement proper use of cache blocks and cache block keys.

In the end, you get much more in return in investing in the optimization of the application (use of cache / template caching) than doing almost anything else at all. This includes counting queries or tampering with web server logs to try to track an almost meaningless number which is a poor way of counting the actual costs of rendering a page, several different pages, etc one or manny more times in a row (load testing). What I mean is query counting does not tell you much and certainly does not tell you the cost of those queries. You could have thousands of queries which return could return wicked fast for many other factors or alternately could return very very slowly and counting just does not provide any real useful insight.

Now I will say if you digg into becoming an advanced eZ Publish legacy developer you will learn to leverage the features of 'DebugOutput' to understand the costs involved in and between a cached and uncached page view across your entire site. DebugOutput can be displayed selectively via many ini settings features. DebugOutput actually displays a query count (tho I only just recently was reminded of this upon checking while composing this post). DebugOutput also educates you on the time to render the page which you can leverage to tracing down your actual real performance bottle necks (problems) and solve them by making improvements. Another feature I've used in the past tho not as frequently since it's just not always needed is the QueryAnalysisOutput feature which will display the queries used to render a page (all or just slow queries by variable ms query time).

In summary in a well written application the performance is greatly increased when say after the cache is primed (after first page load cache is stored), subsequent follow up page views are all served from cache and require little to no processing to serve the resulting page to the user (quickly). Developers all over the world take these ideas even further with solutions to increase performance like static html caching of page content, reverse proxy caching (at a server / memory level), varnish, specialized cdn and cloud hosting services, and much much more.

With eZ Performance is less about the database access and more about what your doing beyond to deliver the very best performance to users.

I just know that you can improve the performance of your website but it will take learning more about all of these aspects in stages and using those lessons to implement the improvements which will help you most of all. I recommend starting using DebugOutput, code review (php and template (but mostly template) to learn which templates need improvements and or caching first. Then you can decided if you want to or need to go further with improving your website's performance.  

Ok. That said I could show you how to count queries and do what you suggest, I'm sure, but I still know in my heart that there is a better path for you to choose to embrace today to ensure the performance of your website tomorrow. 

I hope this helps!

Cheers,
Heath

Thursday 09 April 2015 6:19:42 am

Heath, thank you for your very elaborate reply.

I'm a sysadmin, and I'm not in charge of the websites development, so I'm not really asking for EZ publish development advice
I want to increase the visibility on our EZ publish sites activity, and doing this at the apache's access_log level is the best way for me to do this

I think I could force integration of some technical code in EZ publish sites...

Because I'm not satisfied by the performance of some of the EZ publish sites we host, I studied about EZ publish performance, and know about the crucial importance of caching.

To tell you the truth, I suspect these performance problems result from developer malpractices..

For instance in some cases ViewCaching is disabled..

Unfortunately the developper's manager is sensible to functional and design aspects, much less to performance ones.

Thursday 09 April 2015 6:30:31 am

Well ... that's all well and good Heath but I think you missed the point.

He just hosts the sites which are killing his server performance and hurting his business and prolly negatively affecting other customers websites on the same shared server. He can't do anything to fix the problem the right way, that's all the customers responsibility.  

Which I why I almost always insist on dedicated (real metal) server hosting for an eZ Publish customer (isolation).

The point I'm making is he prolly doesn't care to learn or invest in anything eZ. He's trying to figure out how to prove the customer site is a serious problem and needs to be delt with ... what do the Jedi call that? oh yeah ... aggressive negotiations.

In short you prolly want to fire the customer asap and be done with it. The customer prolly can't afford dedicated hardware hosting required and also will refuse to pay for further development improvements to the website custom code to increase performance.

What Heath didn't say that I also tell people flat out: You can not change the queries eZ produces or uses almost at all with one exception, you can optimize the query internals by customizing your fetch function usage (less params is faster and some params / usages cost much more than others) slow query analysis shows this.

I used it mid-last year to solve a home page with some seriously slow queries killing the server's performance completely until we found solutions by rewriting our fetch usage as a way to optimize query execution until the site was again faster than we needed and we no longer have any performance problems at all in any way (without any other changes or server changes). My changes to a long time to trace, debug, troubleshoot and optimize till the problem was solved and also required re-thinking how we provided for several key content fetch features to ensure our queries avoided complications which destroyed performance (default fetch features are not always the best solution when it comes to performance)

Most customers just don't care enough to address performance optimization of a badly created eZ Publish Website Templates etc.

Still Heath is right, query counting is a worthless metric and certainly not worth the kernel hacking and class overrides required to implement the weird solution you suggest.

But again, it comes down to cost. If the customer is costing you more than you can bare, fire them and move on. I've so rarely seen a customer take hosting provider threats to fire if they didn't rewrite seriously if at all.

Sounds harsh but then I've seen it all before and it's cyclical so I'm cynical big-smile.gif Emoticon

Listen to the theme and cry yourself to sleep. I'm going to right now :\

//kracker

THEME: Kflay - Turn it Around! https://soundcloud.com/kflay/turn-it-around-3?in=kflay/sets/life-as-a-dog

Monday 20 April 2015 1:14:44 pm

Hello Luc,

I'm not sure how to jump in such a large conversation, but I'll still try. Your conclusion is perfect:

Quote from Luc Dumaine :

To tell you the truth, I suspect these performance problems result from developer malpractices..

For instance in some cases ViewCaching is disabled..

Unfortunately the developper's manager is sensible to functional and design aspects, much less to performance ones.

It is quite common, and developers indeed can't entirely be blamed for that. ViewCaching is indeed mandatory, and there are very, very little cases where it is actually required to disable it. But it is usually done because of complex cache expiry scenarii, and it ends up being easier to just disable it.

You might be interested in http://projects.ez.no/ezperformancelogger.

We have much more flexible logging (Monolog) in eZ Publish Platform / 5, but unfortunately, I believe you're stuck in 2012.something, aren't you ? happy.gif Emoticon

Wednesday 22 April 2015 10:56:48 am

Hello Luc,

I wanted to follow up on this topic just a little further.

I initially pushed back on helping provide a solution for query counting because I truly think it's not worth the time and effort, also because I suspected it would require kernel changes. That said it seems like you still think you do need it so I took the time to do the research and find out exactly (at the lowest levels) what it would take.

As I mentioned previously query counting is built into eZ Publish by default, but it is rather specifically hard coded to the eZDebug class. After some research and testing I found that the eZDebug class does not provide direct access to the query count the systems collects within it.

As I have said, to do what you wish will require kernel hacking on -each- site you wish to collect this information within.

The file you need to modify (at least) is, 'lib/ezutils/classes/ezdebug.php'.

You should add this code to the class (I suggest as the last method in the class).

    public static function TimeAccumulatorList()
    {
        $debug = eZDebug::instance();
        return $debug->TimeAccumulatorList;
    }

This change will allow you to statically call the eZDebug class method to get the information you need. Remember to call this method only at the end of the normal kernel php code execution chain (or just be for the end) to ensure you get an accurate account of the queries executed.

I recommend you make kernel hacks if your using eZ Publish 3.x -> 4.0 (version control if possible these changes). If you happen to be using eZ Publish stable-4.1 I would recommend you enable kernel overrides and make a kernel override of the eZDebug class (within an extension, which is painless to do, but very ezp version specific). This addresses the first kernel hack required.

Here is a simple snippet of code which uses the above additional class method:

// Fetch accumulators (which contain the query count)
$list = eZDebug::TimeAccumulatorList();
 
// Default handler is mysqli. Only attempt to access the accumulator for the database handler your using
if( isset( $list['mysqli_query'] ) )
{
    $mysqli_query_count = $list['mysqli_query']['count'];
    print_r( $mysqli_query_count );
}
 
// Deprecated handler is mysql. Only attempt to access the accumulator for the database handler your using
if( isset( $list['mysql_query'] ) )
{
    $mysql_query_count = $list['mysql_query']['count'];
    print_r( $mysql_query_count );
}

Remember that the query count is stored in the accumulator list by database handler. The current default is mysqli but in older installations of eZ Publish you will find the db handler is still mysql. If you use a different database your handler name will be different and you will have to adjust the above usage examples to use the right database handler prefix / name in order to access the query count.

Here is a simple snippet of code which using the examples you shared should provide you with the apache level data you desire. Please note this example requires apache mod_log_config module :

function ezpLogQueryCount()
{
 
// Fetch accumulators (which contain the query count)
$list = eZDebug::TimeAccumulatorList();
 
// Default handler is mysqli. Only attempt to access the accumulator for the database handler your using
if( isset( $list['mysqli_query'] ) )
{
    $ezpublish_request_mysqli_query_count = $list['mysqli_query']['count'];
    apache_note( 'ezpRequestQueryCount', $ezpublish_request_mysqli_query_count );
}
 
// Deprecated handler is mysql. Only attempt to access the accumulator for the database handler your using
if( isset( $list['mysql_query'] ) )
{
    $ezpublish_request_mysql_query_count = $list['mysqli_query']['count'];
    apache_note( 'ezpRequestQueryCount', $ezpublish_request_mysql_query_count );
}
 
}

I would recommend you add the above code into the kernel directly. Where specifically to place this code is a little more tricky since the answer 'where' would be extremely version specific. In general the best target for placement would be within the index.php (yes, another kernel hack).

I will first use the index.php from the stable-4.4 branch as an example.

You will want to add the above code (to fetch the query count and pass the count to apache) right after the line, "eZDebug::addTimingPoint( "End" );". Which I highlight directly in the following link:

https://github.com/ezsystems/ezpublish-legacy/blob/stable-4.4/index.php#L1109

This in general will guide you on where to place your code hack into any eZ Publish 4.x index.php and should ensure it is never cached (though realize some queries are cached when cache is used properly).

If however you are using an eZ Publish version greater than 5.x the placement of your hack is even more tricky since the bulk of the index.php contents have been migrated into the 'ezpKernelWeb' class. Still I think you can place your hack into the index.php file right after the line, "$kernel = new ezpKernel( new ezpKernelWeb() );". The other tricky part is execution vs output. by default the execution is triggered on the same line as output, which is why I suggest you change the line, "echo $kernel->run()->getContent();" to "$output = $kernel->run()->getContent(); ezpLogQueryCount(); echo $output;". Which I highlight directly in the following link:

https://github.com/ezsystems/ezpublish-legacy/blob/master/index.php#L23

The placement suggested above for ezp5 may or may not work and I've not tested it. If it does not work (ie: query count variable is not set / is null / or zero) which might happen because the placement in an index.php in a 5.x kernel might be too late in the chain of execution to access the query count ie: after kernel execution shutdown / deconstruction. If that is the case (sorry, this is a long post and I think after writting so much it is infact the case). Alternatively consider placing the code into the 'ezpKernelWeb' class at the following position:

https://github.com/ezsystems/ezpublish-legacy/blob/master/kernel/private/classes/ezpkernelweb.php#L577

Which is basically the same placement 'logistically' as described in the above 4.x index.php kernel. 

This addresses the second kernel hack required.

Then remember that for each apache virtual host you will need to make the following configuration changes to store the provided apache_note variable from the apache php module.

Then add the following above each of your current apache Log directives (like CustomLog and ErrorLog).

LogFormat "%h %l %u %t \"%r\" %>s %b %{ezpRequestQueryCount}n" common-ezp-query-count

The LogFormat configuration directive is documented here: http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#logformat

The above LogFormat parameters and there meanings are documented here: http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#formats

Then replace each of your current CustomLog directives with the following:

CustomLog "/private/var/log/apache2/ezp5dev-access_log" common-ezp-query-count

The CustomLog configuration directive is documented here: http://httpd.apache.org/docs/2.2/mod/mod_log_config.html#customlog

After making all of these changes (not so much work per-say once you understand what you are doing) ... this should provide for the solution you desire. While I have not tested the apache config changes I suggest, I did test the basic eZDebug kernel class hack and usage which worked, meaning the rest should be very simple and should just ... work, right out of the box. happy.gif Emoticon  

References

I found this stackoverflow thread which is related and more specific in terms of the apache side setup required. http://stackoverflow.com/questions/4470716/writing-to-apache-access-log-file-with-php

Closing

Please let me know if this works for you and if you are able to use the examples I've shared.

Again I am sorry I did not give you the exact answers you wanted right away. I had my reasons, but in general I was short time to write this code example post and what I did first instead was part of 'process' and faster in the heat of the moment.

I hope this helps!

Cheers,
Heath 

expandshrink

You must be logged in to post messages in this topic!

36 542 Users on board!

Forums menu

Proudly Developed with from