Unbelievably slow query !

Author Message

Brno Bery

Thursday 01 May 2008 1:51:59 am

Hi there,

I have a blog containing almost 2500 posts.
When I update or create a new post, the page takes more than 2 mn to refresh because of a very very slow query (see below)
It happens every time on one of the server (linux VPS with no dedicated memory garantee)
It is very rare but still exists on another linux VPS with 384 Mo garantee.

Do you have heard about this issue and how can I fix that (Ez Publish 3.10) ?
The website is totally unusable now !

Any help welcome !!

Brno Bery

---------------------------------------------------------

129 ms
EDIT : actually it is <b>129 seconds</b> (129320 ms exactly !)

SELECT
count( DISTINCT ezcontentobject_tree.node_id ) as count
FROM
ezcontentobject_tree,
ezcontentobject,
ezcontentclass
, ezcontentobject_name
WHERE
ezcontentobject_tree.path_string like '/1/2/1081/%' and ezcontentobject_tree.depth <= 3 and
ezcontentclass.version=0 AND
ezcontentobject_tree.node_id != 1081 AND
ezcontentobject_tree.contentobject_id = ezcontentobject.id AND
ezcontentclass.id = ezcontentobject.contentclass_id AND
ezcontentobject_tree.contentobject_id = ezcontentobject_name.contentobject_id and
ezcontentobject_tree.contentobject_version = ezcontentobject_name.content_version and
( ezcontentobject_name.language_id & ezcontentobject.language_mask > 0 AND
( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 4 ) >> 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 2 ) << 1 )
<
( ezcontentobject_name.language_id & 1 )
+ ( ( ezcontentobject_name.language_id & 4 ) >> 1 )
+ ( ( ezcontentobject_name.language_id & 2 ) << 1 )
)
AND ezcontentobject_tree.is_invisible = 0
AND ezcontentobject.language_mask & 7 > 0

------------------------------------------------------------

5 secondes !!!

SELECT DISTINCT
ezcontentobject.*,
ezcontentobject_tree.*,
ezcontentclass.serialized_name_list as class_serialized_name_list,
ezcontentclass.identifier as class_identifier,
ezcontentclass.is_container as is_container
, ezcontentobject_name.name as name, ezcontentobject_name.real_translation
FROM
ezcontentobject_tree,
ezcontentobject,ezcontentclass
, ezcontentobject_name
, ezcontentobject_attribute a0
WHERE
ezcontentobject_tree.path_string like '/1/2/1081/%' and ezcontentobject_tree.depth <= 3 and
a0.contentobject_id = ezcontentobject.id AND
a0.contentclassattribute_id = 343 AND
a0.version = ezcontentobject_name.content_version AND
( a0.language_id & ezcontentobject.language_mask > 0 AND
( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & a0.language_id ) ) & 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & a0.language_id ) ) & 4 ) >> 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & a0.language_id ) ) & 2 ) << 1 )
<
( a0.language_id & 1 )
+ ( ( a0.language_id & 4 ) >> 1 )
+ ( ( a0.language_id & 2 ) << 1 )
)
AND
ezcontentclass.version=0 AND
ezcontentobject_tree.node_id != 1081 AND
ezcontentobject_tree.contentobject_id = ezcontentobject.id AND
ezcontentclass.id = ezcontentobject.contentclass_id AND
ezcontentobject_tree.contentobject_id = ezcontentobject_name.contentobject_id and
ezcontentobject_tree.contentobject_version = ezcontentobject_name.content_version and
( ezcontentobject_name.language_id & ezcontentobject.language_mask > 0 AND
( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 4 ) >> 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 2 ) << 1 )
<
( ezcontentobject_name.language_id & 1 )
+ ( ( ezcontentobject_name.language_id & 4 ) >> 1 )
+ ( ( ezcontentobject_name.language_id & 2 ) << 1 )
)
AND ezcontentobject_tree.is_invisible = 0
AND ezcontentobject.language_mask & 7 > 0
ORDER BY a0.sort_key_int DESC
LIMIT 2484, 6

-------------------------------------------------------------------------

Checkpoint Elapsed Rel. Elapsed Memory Rel. Memory
Module start 'content' 0.0000 sec 145.8821 sec 813.0391KB 4,206.0703KB
Module end 'content' 145.8821 sec 1.0536 sec 5,019.1094KB 720.5703KB
End 146.9356 sec 5,739.6797KB 0.7037KB
Total runtime: 147.4662 sec

Time accumulators:
Accumulator Elapsed Percent Count Average
ini_load
Load cache 0.0268 sec 0.0179% 14 0.0019 sec
FindInputFiles 0.0212 sec 0.0142% 14 0.0015 sec
Mysql Total
Mysql_queries 144.1667 sec 96.3994% 138 1.0447 sec
Looping result 0.0105 sec 0.0070% 136 0.0001 sec
TS translator
TS init 0.0049 sec 0.0033% 3 0.0016 sec
TS cache load 0.0031 sec 0.0020% 3 0.0010 sec
TS context load 0.0021 sec 0.0014% 3 0.0007 sec
Template Total 146.9087 sec 98.2% 3 48.9696 sec
Template load 0.0123 sec 0.0082% 3 0.0041 sec
Template processing 146.8952 sec 98.2239% 3 48.9651 sec
Template load and register function 0.0003 sec 0.0002% 1 0.0003 sec
override
Cache load 0.0220 sec 0.0147% 20 0.0011 sec
Sytem overhead
Fetch class attribute can translate value 0.0285 sec 0.0191% 98 0.0003 sec
Fetch class attribute name 0.0033 sec 0.0022% 7 0.0005 sec
XML
Image XML parsing 0.1941 sec 0.1298% 98 0.0020 sec
class_abstraction
Instantiating content class attribute 0.0003 sec 0.0002% 7 0.0000 sec
General
String conversion 0.0003 sec 0.0002% 8 0.0000 sec
dbfile 0.1285 sec 0.0859% 256 0.0005 sec
Total script time: 149.5514 sec

-----------------------------------------------------------

MYSQL Runtime information
mysql restarted since 2 days

Handler_read_rnd 1.293 K
Handler_read_rnd 7.086 K
Select_full_join 725

Maxime Thomas

Thursday 01 May 2008 8:35:30 am

Are your db indexes set ? It's very strange...

By the way, I see that you hve 138 queries on one page !?!
- Have you enabled the cache on the identified server ?
- If yes, is the Smart cache policies well defined ?
- Do you use cache blocks ?

Hope it will help you.

Maxime Thomas
[email protected] | www.wascou.org | http://twitter.com/wascou

Company Blog : http://www.wascou.org/eng/Company/Blog
Technical Blog : http://share.ez.no/blogs/maxime-thomas

Brno Bery

Thursday 01 May 2008 9:49:22 am

Yes, indexes are set.

These long queries occure from the standard admin siteaccess.
No cache block and just a smart cache asking for cleaning the homepage cache when publishing blog post.

I get 138 queries when listing 10 subitems and more than 450 queries when listing 50 subitems.
But the numerous queries do not seem to be the problem since 99% of the processing time comes from the 2 or 3 slow queries listed above.

makes me crazy...

By the way, the first query with the 'count' column takes <b>129 seconds</b> and not 129 ms as I wrote

André R.

Thursday 01 May 2008 3:22:25 pm

Do you have all the 2500 blog posts in 1 node?
node id: 1081?

eZ Online Editor 5: http://projects.ez.no/ezoe || eZJSCore (Ajax): http://projects.ez.no/ezjscore || eZ Publish EE http://ez.no/eZPublish/eZ-Publish-Enterprise-Subscription
@: http://twitter.com/andrerom

Brno Bery

Friday 02 May 2008 12:02:05 am

Right !

Stéphane Couzinier

Friday 02 May 2008 1:46:17 am

Hi

take the last version of ezcontentobjecttree.php .
With the old version , mysql query generate by Fetch list and fetch list count didn't use index.
The new version will replace path_string like '/1/2/1081/%' by parent_node_id =1081.

It should be faster.

http://www.kouz-cooking.fr

Brno Bery

Friday 02 May 2008 5:01:25 am

Thanks Stephane.

I've updated the ezcontentobjecttreenode.php. It now uses parent_node_id instead of path_string for the query.

But the query is still very slow. I even got my best score : 298 secondes !

------------------------------------------------------

137 seconds !!!

SELECT
count( DISTINCT ezcontentobject_tree.node_id ) as count
FROM
ezcontentobject_tree,
ezcontentobject,
ezcontentclass
, ezcontentobject_name
WHERE
ezcontentobject_tree.parent_node_id = 1081 and
ezcontentclass.version=0 AND
ezcontentobject_tree.contentobject_id = ezcontentobject.id AND
ezcontentclass.id = ezcontentobject.contentclass_id AND
ezcontentobject_tree.contentobject_id = ezcontentobject_name.contentobject_id and
ezcontentobject_tree.contentobject_version = ezcontentobject_name.content_version and
( ezcontentobject_name.language_id & ezcontentobject.language_mask > 0 AND
( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 8 ) >> 2 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 4 ) )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 2 ) << 2 )
<
( ezcontentobject_name.language_id & 1 )
+ ( ( ezcontentobject_name.language_id & 8 ) >> 2 )
+ ( ( ezcontentobject_name.language_id & 4 ) )
+ ( ( ezcontentobject_name.language_id & 2 ) << 2 )
)
AND ezcontentobject.language_mask & 15 > 0

---------------------------------------------------------------------------------------

113 secondes
SELECT
count( DISTINCT ezcontentobject_tree.node_id ) as count
FROM
ezcontentobject_tree,
ezcontentobject,
ezcontentclass
, ezcontentobject_name
WHERE
ezcontentobject_tree.parent_node_id = 1081 and
ezcontentclass.version=0 AND
ezcontentobject_tree.contentobject_id = ezcontentobject.id AND
ezcontentclass.id = ezcontentobject.contentclass_id AND
ezcontentobject_tree.contentobject_id = ezcontentobject_name.contentobject_id and
ezcontentobject_tree.contentobject_version = ezcontentobject_name.content_version and
( ezcontentobject_name.language_id & ezcontentobject.language_mask > 0 AND
( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 1 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 8 ) >> 2 )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 4 ) )
+ ( ( ( ezcontentobject.language_mask - ( ezcontentobject.language_mask & ezcontentobject_name.language_id ) ) & 2 ) << 2 )
<
( ezcontentobject_name.language_id & 1 )
+ ( ( ezcontentobject_name.language_id & 8 ) >> 2 )
+ ( ( ezcontentobject_name.language_id & 4 ) )
+ ( ( ezcontentobject_name.language_id & 2 ) << 2 )
)
AND ezcontentobject.language_mask & 15 > 0

Brno Bery

Friday 02 May 2008 6:51:35 am

Apparently, the problem disappeared after a mysql repair table action.
It's strange because the check table action didn't report any trouble.

André R.

Friday 02 May 2008 9:25:49 am

Good, if it returns:
It's not recommended to have several thousands nodes in a single folder (node container), since it can affect mysql order by performance. So you should try to look into organizing your blog posts in sub folders or something (year/ category / you pick).

eZ Online Editor 5: http://projects.ez.no/ezoe || eZJSCore (Ajax): http://projects.ez.no/ezjscore || eZ Publish EE http://ez.no/eZPublish/eZ-Publish-Enterprise-Subscription
@: http://twitter.com/andrerom

Francisca Hernández

Friday 02 May 2008 1:47:29 pm

hi brno,

I have slow querys when i'm reading from some nodes that contains thousands nodes.
when you say that "Apparently, the problem disappeared after a mysql repair table action.
It's strange because the check table action didn't report any trouble."
do you use myisam or innodb?

thanks,
fran

Iguana IT, SL - http://www.iguanait.com

Piotrek Karaś

Saturday 03 May 2008 1:34:29 am

André,

<i>It's not recommended to have several thousands nodes in a single folder (node container), since it can affect mysql order by performance. So you should try to look into organizing your blog posts in sub folders or something (year/ category / you pick).</i>

This isn't exactly the recommendation I would expect. Naturally, if the content structure and management logic fits subdivisions, then that's a way. However, how to organize the content should not be a question of system's efficiency - it's the matter of client's requirements. Or at least not at the level of few thousand...

This is a bad news. I can imagine a number of implementation scenarios where storing under one node is expected. And what about sites with large numbers of registered users and community features such as profile browsing?

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

Brno Bery

Saturday 03 May 2008 11:20:49 am

<i>do you use myisam or innodb?</i>
I use myisam.
I would not affirm that the repair table action resolved the slow query.
I'm not a mysql expert but I can easly guess that the count query took more memory than my server has. If I'm right, it means that the same problem can occure soon when adding new nodes.
This is a bad surprise as I could not imagine that counting 2500 objects can take so much performance.

Francesca, do you have the same slow query ?

André : In the case of my blog, it's true that I can easly re-organize the posts. But as Piotrek said, subdivision is not logic in any case. Is there any study about how performance falls with nodes quantity ? It would help to organize a new project according to the server performance and prevent this kind of problem.

Maxime Thomas

Sunday 04 May 2008 9:43:32 am

I was thinking a lot on that functionnality : how to archive my old content without losing the structure and content layout.

Maybe it's in the roadmap ? Will it come with version 4.5 and new content status ?

Maxime Thomas
[email protected] | www.wascou.org | http://twitter.com/wascou

Company Blog : http://www.wascou.org/eng/Company/Blog
Technical Blog : http://share.ez.no/blogs/maxime-thomas

André R.

Sunday 04 May 2008 11:31:30 pm

> Maybe it's in the roadmap? Will it come with version 4.5 and new content status?

Content object status has to do with workflows, not content.

> Is there any study about how performance falls with nodes quantity?

I'll ask.

EDIT: There isn't a written study on this, basically you might start to see issues when you reach 20 000 nodes or more in one single folder. But it depends on mysql setup (server and config) and what sorting you use on that node. I would guess that sorting on content attributes have a higher overhead then sorting on stuff that is on the content object or content node tables (section,published, modified, modified_subnode, path, path_string, priority, class_identifier and name).

So this issue is something else, or a very badly configured mysql server.

eZ Online Editor 5: http://projects.ez.no/ezoe || eZJSCore (Ajax): http://projects.ez.no/ezjscore || eZ Publish EE http://ez.no/eZPublish/eZ-Publish-Enterprise-Subscription
@: http://twitter.com/andrerom

Piotrek Karaś

Thursday 03 July 2008 1:08:28 pm

I knew it would happen sooner or later ;) I have a similar situation, but I expect my site to have almost all of its content (definitely 10000(0)+ objects) under one parent node. However, no blog-like browsing and google-like navigation - only full view access. Would you expect problems with this?

Details here:
http://ez.no/developer/forum/developer/number_of_nodes_per_parent_node_vs_performance#msg169405

Thanks,
Piotrek

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

Hans Melis

Thursday 03 July 2008 2:00:05 pm

From my own experience, 10000 objects under 1 node does not introduce any performance problems. What's done with those objects? Listing active objects (=attribute filter), custom filtering for some people (= more attribute filtering), google navigator. Some more stuff happens in a programmatic way, like re-publishing, but isn't slowed down either. We do hide "old" content under that node, but the admin interface isn't slowed down either.

The real bottleneck on the page providing the listing is (even after all those years) the template system. Over the years, I've been able to optimize that page using new features which brought processing time from 7-8 seconds to 1.5 seconds. More than a second of that time goes to the template system, which is for a big part caused by the complex fetch condition building.

So if you're not even going to do some tempalting on top of the node, it'll take even longer before you hit performance degradation.

Hans
http://blog.hansmelis.be

Piotrek Karaś

Thursday 03 July 2008 9:17:05 pm

Hi Hans,

Thanks for sharing your experience.

Just to broaden the perspective a bit:
It will be a community-driven site where users can publish objects of 2, maybe 3 classes. All the data classification/structuring of those will be done with a complex custom category datatype, and I am left with no good use for tree structure. Users will never be able to use google-like navigation, but I just realized that I will not be able to avoid it in the administration interface from time to time (I may override admin interface templates, so that child elements of the containers will not be fetched - I will only use search or some other extended functionalities that will take me directly to object's full view). Also, to correct my earlier thoughts, I will have to fetch from that object collection by owner or by some attribute.

I will as well generate some fictional data to test that before actual deployment.

If you have any further thoughts - please share.
Thanks,
Piotrek

--
Company: mediaSELF Sp. z o.o., http://www.mediaself.pl
eZ references: http://ez.no/partners/worldwide_partners/mediaself
eZ certified developer: http://ez.no/certification/verify/272585
eZ blog: http://ez.ryba.eu

Mariusz Scisel

Thursday 07 August 2008 7:59:48 am

Hi
Actually I have similar problem. I have a kind of RSS Reader which generate about 10 000 Posts monthly on my eZ Publish site under about ten parent nodes. It is based on a Blog and it uses tags keywordlist, tagcloud , ezarchive and callendar like a Blog.

After few thousands of posts the tagcloud tamplate generates very long time SQL query and website is unusable and hangs MySQL server!

Below there is query from container node which contains only 4 tags in RSS Post. I moved them for tests, rest of them are in second rss container ( about 10 000 nodes with tags)

query from eztagcloud.php

Notice: eZMySQLDB::query(4 rows, 275,056.335 ms) query number per page:58

SELECT DISTINCT ezkeyword.keyword
                                            FROM ezkeyword,
                                                ezkeyword_attribute_link,
                                                ezcontentobject,
                                                ezcontentobject_attribute,
                                                ezcontentobject_tree,
                                                ezcontentclass
                                            WHERE ezkeyword.id = ezkeyword_attribute_link.keyword_id
                                                AND ezkeyword_attribute_link.objectattribute_id = ezcontentobject_attribute.id
                                                AND ezcontentobject_attribute.contentobject_id = ezcontentobject_tree.contentobject_id
                                                AND ezkeyword.class_id = ezcontentclass.id
                                                AND ezcontentclass.id = ezcontentobject.contentclass_id
                                                AND ezcontentclass.version = '0'
                                                AND ezcontentobject.status = '1'
                                                AND ezcontentobject_attribute.version = ezcontentobject.current_version
                                                AND ezcontentobject_tree.main_node_id = ezcontentobject_tree.node_id
                                                AND ezcontentobject_tree.path_string like '/1/2/12245/%'
                                                AND ezcontentobject_tree.node_id != 12245
                                                AND ezcontentclass.identifier = 'rss_post'
                                                AND 
 ezcontentobject.language_mask & 3 > 0 

                                            ORDER BY ezkeyword.keyword ASC

This is strange because the same query running in PhpMyAdmin takes about 87.5 ms !

after I disabled this line in extra_info.tpl all works fine...

{eztagcloud( hash( 'class_identifier', 'blog_post',
                                               'parent_node_id', $used_node.node_id ) )}

url /content/view/tagcloud/2 works very well

I see that this part of MySQL query slows and hangs my site

AND ezcontentobject_tree.path_string like '/1/2/12245/%'


Can anyone help here to fix this problem?
I think this is non optimised query problem or something with database tables
Mariusz.

Stéphane Couzinier

Thursday 07 August 2008 9:30:35 am

You can try to add this in the where clause
AND ezcontentobject.id=ezcontentobject_attribute.contentobject_id

http://www.kouz-cooking.fr

André R.

Thursday 07 August 2008 11:33:10 am

Hans:
> More than a second of that time goes to the template system, which is for a big part caused by the complex fetch condition building.

If you can't efficiently cache the result of this code you should rewrite the code to a template operator, in php you can take advantage of the php api of eZ Publish to get a lot more efficient code.(list/tree fetch: eZContentObjectTreeNode::subTree)

eZ Online Editor 5: http://projects.ez.no/ezoe || eZJSCore (Ajax): http://projects.ez.no/ezjscore || eZ Publish EE http://ez.no/eZPublish/eZ-Publish-Enterprise-Subscription
@: http://twitter.com/andrerom

Powered by eZ Publish™ CMS Open Source Web Content Management. Copyright © 1999-2014 eZ Systems AS (except where otherwise noted). All rights reserved.