Exponential performance

Sunday 13 November 2005 11:01:12 pm

Steve try to upgrade to 3.6.1, this is easy, just replace all files and run one SQL query then clear all cache.

I remember that I had similar problem to your with 3.6.0 version on Windows platform and I still did not find right answer...However 3.6.1 and higher works with normal speed around 0,12, like in my first post. Upgrading should solve your problem.

Personal website -> http://serwatka.net
Blog (about eZ Publish) -> http://serwatka.net/blog

Monday 14 November 2005 1:18:31 pm

Steve,

First of all, you're on Windows. Windows is a slow OS, especially when disk IO comes into play. You're not going to see major improvements over the 0.4s load times.

The queries on the other hand are caused by index.php. Even though you don't display it, it still performs module actions to build $module_result and it also does user checking/policies.

And last but not least, the total script time reported is far from accurate (at least on Windows). If you add the individual numbers, you'll have less than the total script time. On my PC, the total script time reports 1.0605s, but the actual numbers only add up to 0.7819s.

Hans
http://blog.hansmelis.be

Tuesday 15 November 2005 8:31:18 am

Hi,

What Steve mention is correct.. why do we have 14queries in a template that does nothing??

According to all post on this thread and an answer I received a while back mysql queries would reduce to 2 or 3 if page is cached. So if this is correct why is it that we have a page with no dynamic content nor graphic and being cached and still doing 14queries??

I'm no Exponential nor MySQL expert but is this do to the way ez or MySQL functions on Windows?

Thanks,
Fabricio

http://www.solobromasychistes.com <<Joomla Site :P
http://www.recipesforhealthyfood.com/ <<Drupal Site :P
http://www.ezforge.com/ <<future ezCommunity, Articles, forums and more...

Tuesday 29 November 2005 1:44:45 am

The amount of SQL Queries your page generates is highly dependent on its actual layout, if your site is composed out of many elements you'll always need more queries caching or not...

Visit http://triligon.org

Tuesday 29 November 2005 2:08:39 am

Just to add fuel to the fire...

We've seen the same but don't have a solution to the problem.

Check my post above - we create a pagelayout with zero fetches, all it has is two static node links... there's just nothing there - yet the system executes multiple sql queries and takes ages to load.

There's something not right here... And currently dealing with upset cleints as a result :(( One in particular is confused as another Ez site we built for them is really quick..

Regards, Steve.

http://www.oneworldmarket.co.uk

Tuesday 29 November 2005 2:40:12 am

Hi Steve

Could you send me the SQLs generated on the empty page ( to kk_at_ez.no ) ?

There was introduced a performance bug in Rev. 12807 which is currently beeing fixed. The SQL calls might be caused by this.

Kåre Høvik

Tuesday 29 November 2005 5:09:48 am

Kare,

I have changed the pagelayout to using the page I described above, just two static links, nothing else:

Notice: eZMySQLDB::query(1 rows, 0.605 ms) query number per page:0  	Nov 29 2005 13:07:50

SELECT data, user_id, expiration_time FROM ezsession WHERE session_key='30d41969af7d30e8eed6326231320b8e'

Notice: eZMySQLDB::query(0 rows, 0.585 ms) query number per page:1 	Nov 29 2005 13:07:50

SELECT contentobject_id, login, email, password_hash, password_hash_type
FROM   ezuser
WHERE  contentobject_id='0'

Notice: eZMySQLDB::query(0 rows, 0.578 ms) query number per page:2 	Nov 29 2005 13:07:50

SELECT contentobject_id, login, email, password_hash, password_hash_type
FROM   ezuser
WHERE  contentobject_id='0'

Notice: eZMySQLDB::query(0 rows, 0.700 ms) query number per page:3 	Nov 29 2005 13:07:50

SELECT destination_url, forward_to_id
FROM ezurlalias
WHERE source_md5 = '2b7c4514a564d4f3d439d838bf1f83ff' AND
      is_wildcard = 0
ORDER BY forward_to_id ASC, is_internal ASC
LIMIT 0, 1

Timing: 	Nov 29 2005 13:07:50

Module start 'content'

Notice: eZMySQLDB::query(0 rows, 0.685 ms) query number per page:4 	Nov 29 2005 13:07:50

SELECT id, main, memento_key, main_key, memento_data
FROM   ezoperation_memento
WHERE  memento_key='6ceeb025a17151c678afb101d4310ca6' AND main='1'

Notice: eZMySQLDB::query(0 rows, 0.542 ms) query number per page:5 	Nov 29 2005 13:07:50

SELECT id, main, memento_key, main_key, memento_data
FROM   ezoperation_memento
WHERE  memento_key='6ceeb025a17151c678afb101d4310ca6' AND main='0'

Notice: eZMySQLDB::query(0 rows, 0.565 ms) query number per page:6 	Nov 29 2005 13:07:50

SELECT id, module_name, function_name, connect_type, workflow_id, name
FROM   eztrigger
WHERE  name='pre_read' AND module_name='content' AND function_name='read'

Notice: eZMySQLDB::query(1 rows, 0.948 ms) query number per page:7 	Nov 29 2005 13:07:50

SELECT ezcontentobject.*,
                       ezcontentobject_tree.*,
                       ezcontentclass.name as class_name,
                       ezcontentclass.identifier as class_identifier
                       , ezcontentobject_name.name as name,  ezcontentobject_name.real_translation 
                FROM ezcontentobject_tree,
                     ezcontentobject,
                     ezcontentclass
                     , ezcontentobject_name 
                WHERE node_id IN ( 2 ) AND
                      ezcontentobject_tree.contentobject_id=ezcontentobject.id AND
                      ezcontentclass.version=0  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.content_translation = 'eng-GB'

Notice: eZMySQLDB::query(0 rows, 0.520 ms) query number per page:7 	Nov 29 2005 13:07:50

SELECT limit_value
                                          FROM ezuser_role
                                          WHERE contentobject_id = 617

Timing: 	Nov 29 2005 13:07:50

Module end 'content'

Timing: 	Nov 29 2005 13:07:50

End

Timing points:
Checkpoint	Elapsed	Rel. Elapsed	Memory	Rel. Memory
Module start 'content'	0.0000 sec	0.0707 sec	0.0000KB	0.0000KB
Module end 'content'	0.0707 sec	0.0501 sec	0.0000KB	0.0000KB
End	0.1208 sec	 	0.0000KB	0.0000KB
Total runtime:	512.1863 sec	
Time accumulators:
 Accumulator	 Elapsed	 Percent	 Count	 Average
ini_load				
Load cache	512.0726 sec	156,962.3528%	10	51.2073 sec
Mysql Total				
Mysql_queries	1,536.0209 sec	470,826.7106%	9	170.6690 sec
Looping result	512.0002 sec	156,940.1573%	2	256.0001 sec
Template Total	0.1015 sec	31.1%	2	0.0508 sec
Template load	0.0421 sec	12.8949%	2	0.0210 sec
Template processing	512.0588 sec	156,958.1194%	2	256.0294 sec
override				
Cache load	0.0304 sec	9.3104%	2	0.0152 sec
Total script time:	0.3262 sec	

This is after the page had been cached. 9 sql queries in total.

Regards, Steve

http://www.oneworldmarket.co.uk

Wednesday 07 December 2005 7:21:09 am

Hey Kare, you still out there??

We really need to fix this, would appreciate some help.

Thanks, Steve

http://www.oneworldmarket.co.uk

Friday 09 December 2005 8:33:48 am

Hi Kare,

We disabled all the extensions - but we're still seeing loads of mysql queries.

Thanks, Steve

http://www.oneworldmarket.co.uk

Friday 09 December 2005 10:36:09 am

Hi Paul,

Thanks for your reply - AFAWK, all triggers are disabled. Using our stripped down pagelayout as above we see:

Notice: eZMySQLDB::query(1 rows, 0.846 ms) query number per page:0  	Dec 09 2005 18:23:50

SELECT data, user_id, expiration_time FROM ezsession WHERE session_key='36380249a14e449383788a71c93da738'

Notice: eZMySQLDB::query(0 rows, 0.643 ms) query number per page:1 	Dec 09 2005 18:23:50

SELECT contentobject_id, login, email, password_hash, password_hash_type
FROM   ezuser
WHERE  contentobject_id='0'

Notice: eZMySQLDB::query(0 rows, 0.587 ms) query number per page:2 	Dec 09 2005 18:23:50

SELECT contentobject_id, login, email, password_hash, password_hash_type
FROM   ezuser
WHERE  contentobject_id='0'

Notice: eZMySQLDB::query(0 rows, 0.743 ms) query number per page:3 	Dec 09 2005 18:23:50

SELECT destination_url, forward_to_id
FROM ezurlalias
WHERE source_md5 = '2b7c4514a564d4f3d439d838bf1f83ff' AND
      is_wildcard = 0
ORDER BY forward_to_id ASC, is_internal ASC
LIMIT 0, 1

Timing: 	Dec 09 2005 18:23:50

Module start 'content'

Notice: eZMySQLDB::query(0 rows, 0.769 ms) query number per page:4 	Dec 09 2005 18:23:50

SELECT limit_value
                                          FROM ezuser_role
                                          WHERE contentobject_id = 617

Timing: 	Dec 09 2005 18:23:50

Module end 'content'

Timing: 	Dec 09 2005 18:23:50

End

Timing points:
Checkpoint	Elapsed	Rel. Elapsed	Memory	Rel. Memory
Module start 'content'	0.0000 sec	0.0464 sec	0.0000KB	0.0000KB
Module end 'content'	0.0464 sec	0.0524 sec	0.0000KB	0.0000KB
End	0.0989 sec	 	0.0000KB	0.0000KB
Total runtime:	0.1626 sec	
Time accumulators:
 Accumulator	 Elapsed	 Percent	 Count	 Average
ini_load				
Load cache	-511.9264 sec	-168,989.9800%	10	-51.1926 sec
Mysql Total				
Mysql_queries	-511.9872 sec	-169,010.0497%	5	-102.3974 sec
Looping result	0.0001 sec	0.0245%	1	0.0001 sec
Template Total	0.1017 sec	33.6%	2	0.0509 sec
Template load	0.0442 sec	14.5977%	2	0.0221 sec
Template processing	0.0569 sec	18.7682%	2	0.0284 sec
override				
Cache load	-511.9678 sec	-169,003.6559%	2	-255.9839 sec
Total script time:	0.3029 sec	

Queries are down to 4 now which is better, and we can see that some queries need to be there as they are authenticating the user, though you can see that the same query is listed twice?

The sql query time is really low here - but you can see that the template load time is still 0.1 sec which seems a lot still...

If we now change pagelayout back to our normal one for this intranet website we see:

- first time page loads after cache clear, 206 queries

On reloading a cached page we see:

Notice: eZMySQLDB::query(1 rows, 0.655 ms) query number per page:0  	Dec 09 2005 18:34:06

SELECT data, user_id, expiration_time FROM ezsession WHERE session_key='36380249a14e449383788a71c93da738'

Notice: eZMySQLDB::query(0 rows, 0.659 ms) query number per page:1 	Dec 09 2005 18:34:06

SELECT contentobject_id, login, email, password_hash, password_hash_type
FROM   ezuser
WHERE  contentobject_id='0'

Notice: eZMySQLDB::query(0 rows, 0.600 ms) query number per page:2 	Dec 09 2005 18:34:08

SELECT contentobject_id, login, email, password_hash, password_hash_type
FROM   ezuser
WHERE  contentobject_id='0'

Notice: eZMySQLDB::query(0 rows, 0.743 ms) query number per page:3 	Dec 09 2005 18:34:08

SELECT destination_url, forward_to_id
FROM ezurlalias
WHERE source_md5 = '2b7c4514a564d4f3d439d838bf1f83ff' AND
      is_wildcard = 0
ORDER BY forward_to_id ASC, is_internal ASC
LIMIT 0, 1

Timing: 	Dec 09 2005 18:34:08

Module start 'content'

Notice: eZMySQLDB::query(0 rows, 0.687 ms) query number per page:4 	Dec 09 2005 18:34:08

SELECT limit_value
                                          FROM ezuser_role
                                          WHERE contentobject_id = 617

Timing: 	Dec 09 2005 18:34:08

Module end 'content'

Notice: eZMySQLDB::query(1 rows, 0.767 ms) query number per page:5 	Dec 09 2005 18:34:08

SELECT id, user_id, node_id, name
FROM   ezcontentbrowsebookmark
WHERE  user_id='617'
ORDER BY id DESC

Notice: eZMySQLDB::query(1 rows, 1.029 ms) query number per page:6 	Dec 09 2005 18:34:08

SELECT ezcontentobject.*,
                       ezcontentobject_tree.*,
                       ezcontentclass.name as class_name,
                       ezcontentclass.identifier as class_identifier
                       , ezcontentobject_name.name as name,  ezcontentobject_name.real_translation 
                FROM ezcontentobject_tree,
                     ezcontentobject,
                     ezcontentclass
                     , ezcontentobject_name 
                WHERE node_id IN ( 116 ) AND
                      ezcontentobject_tree.contentobject_id=ezcontentobject.id AND
                      ezcontentclass.version=0  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.content_translation = 'eng-GB'

Notice: eZMySQLDB::query(1 rows, 1.008 ms) query number per page:6 	Dec 09 2005 18:34:08

SELECT ezcontentobject.*,
                       ezcontentobject_tree.*,
                       ezcontentclass.name as class_name,
                       ezcontentclass.identifier as class_identifier
                       , ezcontentobject_name.name as name,  ezcontentobject_name.real_translation 
                FROM ezcontentobject_tree,
                     ezcontentobject,
                     ezcontentclass
                     , ezcontentobject_name 
                WHERE node_id IN ( 116 ) AND
                      ezcontentobject_tree.contentobject_id=ezcontentobject.id AND
                      ezcontentclass.version=0  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.content_translation = 'eng-GB'

Notice: eZMySQLDB::query(1 rows, 0.763 ms) query number per page:6 	Dec 09 2005 18:34:08

SELECT id, version, name, identifier, contentobject_name, creator_id, modifier_id,
       created, remote_id, modified, is_container
FROM   ezcontentclass
WHERE  id='1' AND version='0'
ORDER BY version ASC
LIMIT 0, 2

Notice: eZMySQLDB::query(1 rows, 0.994 ms) query number per page:7 	Dec 09 2005 18:34:08

SELECT ezcontentobject.*,
                       ezcontentobject_tree.*,
                       ezcontentclass.name as class_name,
                       ezcontentclass.identifier as class_identifier
                       , ezcontentobject_name.name as name,  ezcontentobject_name.real_translation 
                FROM ezcontentobject_tree,
                     ezcontentobject,
                     ezcontentclass
                     , ezcontentobject_name 
                WHERE node_id IN ( 116 ) AND
                      ezcontentobject_tree.contentobject_id=ezcontentobject.id AND
                      ezcontentclass.version=0  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.content_translation = 'eng-GB'

Notice: eZMySQLDB::query(1 rows, 0.671 ms) query number per page:7 	Dec 09 2005 18:34:08

SELECT id, version, name, identifier, contentobject_name, creator_id, modifier_id,
       created, remote_id, modified, is_container
FROM   ezcontentclass
WHERE  id='1' AND version='0'
ORDER BY version ASC
LIMIT 0, 2

Notice: eZMySQLDB::query(1 rows, 1.040 ms) query number per page:8 	Dec 09 2005 18:34:08

SELECT ezcontentobject.*,
                       ezcontentobject_tree.*,
                       ezcontentclass.name as class_name,
                       ezcontentclass.identifier as class_identifier
                       , ezcontentobject_name.name as name,  ezcontentobject_name.real_translation 
                FROM ezcontentobject_tree,
                     ezcontentobject,
                     ezcontentclass
                     , ezcontentobject_name 
                WHERE node_id IN ( 116 ) AND
                      ezcontentobject_tree.contentobject_id=ezcontentobject.id AND
                      ezcontentclass.version=0  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.content_translation = 'eng-GB'

Notice: eZMySQLDB::query(1 rows, 0.989 ms) query number per page:8 	Dec 09 2005 18:34:08

SELECT ezcontentobject.*,
                       ezcontentobject_tree.*,
                       ezcontentclass.name as class_name,
                       ezcontentclass.identifier as class_identifier
                       , ezcontentobject_name.name as name,  ezcontentobject_name.real_translation 
                FROM ezcontentobject_tree,
                     ezcontentobject,
                     ezcontentclass
                     , ezcontentobject_name 
                WHERE node_id IN ( 116 ) AND
                      ezcontentobject_tree.contentobject_id=ezcontentobject.id AND
                      ezcontentclass.version=0  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.content_translation = 'eng-GB'

Timing: 	Dec 09 2005 18:34:08

End

Timing points:
Checkpoint	Elapsed	Rel. Elapsed	Memory	Rel. Memory
Module start 'content'	0.0000 sec	0.0452 sec	0.0000KB	0.0000KB
Module end 'content'	0.0452 sec	512.1575 sec	0.0000KB	0.0000KB
End	512.2027 sec	 	0.0000KB	0.0000KB
Total runtime:	0.2666 sec	
Time accumulators:
 Accumulator	 Elapsed	 Percent	 Count	 Average
ini_load				
Load cache	-511.9139 sec	-20,023.1195%	12	-42.6595 sec
Mysql Total				
Mysql_queries	0.0336 sec	1.3138%	13	0.0026 sec
Looping result	1,024.0007 sec	40,053.0030%	9	113.7779 sec
Template Total	0.2066 sec	8.1%	2	0.1033 sec
Template load	-511.9563 sec	-20,024.7784%	2	-255.9782 sec
Template processing	0.1623 sec	6.3467%	2	0.0811 sec
override				
Cache load	0.0317 sec	1.2414%	2	0.0159 sec
Total script time:	2.5566 sec	

13 Queries here - we can see the bookmarks in there (which is fine as we cant cache that)...

... but again, huge time dedicated to template processing (0.2 sec) - aaargh!

Any thoughts?

Steve.

http://www.oneworldmarket.co.uk