Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
8 messages Options
Reply | Threaded
Open this post in threaded view
|

Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Sanjeev Gupta
when you go to a product page and hit Previous or Next button, its is taking about 15 - 20 seconds for ofbiz to load the product page.
From the logs it looks like that the data resources and the content associations created for SEO URL's cold be the culprit - the complex SQL queries itself is taking about 360 + 116 milli seconds.

I even increased the memory allocation, but it didn't help  - -Xms1024M -Xmx5120M -XX:MaxPermSize=5120m

Can someone pls take a look at this and advise.

Version  : SVN Trunk
O/S      : Windows
DB       : derby

Logs
2012-04-09 14:10:25,482 (http-bio-0.0.0.0-8080-exec-3) [ControlEventListener.java:65 :INFO ] Creating session: 78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
2012-04-09 14:10:30,989 (http-bio-0.0.0.0-8080-exec-3) [         GenericDAO.java:799:INFO ] Ran query in 310 milli-seconds:  EntityName: ContentAssocDataResourceViewTo Sql: SELECT CA.CONTENT_ID, CA.CONTENT_ID, CA.CONTENT_ID_TO, CA.CONTENT_ASSOC_TYPE_ID, CA.FROM_DATE, CA.THRU_DATE, CA.CONTENT_ASSOC_PREDICATE_ID, CA.DATA_SOURCE_ID, CA.SEQUENCE_NUM, CA.MAP_KEY, CA.UPPER_COORDINATE, CA.LEFT_COORDINATE, CA.CREATED_DATE, CA.CREATED_BY_USER_LOGIN, CA.LAST_MODIFIED_DATE, CA.LAST_MODIFIED_BY_USER_LOGIN, CO.CONTENT_ID, CO.CONTENT_TYPE_ID, CO.OWNER_CONTENT_ID, CO.DECORATOR_CONTENT_ID, CO.INSTANCE_OF_CONTENT_ID, CO.DATA_RESOURCE_ID, CO.TEMPLATE_DATA_RESOURCE_ID, CO.DATA_SOURCE_ID, CO.STATUS_ID, CO.PRIVILEGE_ENUM_ID, CO.SERVICE_NAME, CO.CONTENT_NAME, CO.DESCRIPTION, CO.LOCALE_STRING, CO.MIME_TYPE_ID, CO.CHARACTER_SET_ID, CO.CHILD_LEAF_COUNT, CO.CHILD_BRANCH_COUNT, CO.CREATED_DATE, CO.CREATED_BY_USER_LOGIN, CO.LAST_MODIFIED_DATE, CO.LAST_MODIFIED_BY_USER_LOGIN, DR.DATA_RESOURCE_ID, DR.DATA_RESOURCE_TYPE_ID, DR.DATA_TEMPLATE_TYPE_ID, DR.DATA_CATEGORY_ID, DR.DATA_SOURCE_ID, DR.STATUS_ID, DR.DATA_RESOURCE_NAME, DR.LOCALE_STRING, DR.MIME_TYPE_ID, DR.CHARACTER_SET_ID, DR.OBJECT_INFO, DR.SURVEY_ID, DR.SURVEY_RESPONSE_ID, DR.RELATED_DETAIL_ID, DR.IS_PUBLIC, DR.CREATED_DATE, DR.CREATED_BY_USER_LOGIN, DR.LAST_MODIFIED_DATE, DR.LAST_MODIFIED_BY_USER_LOGIN FROM (OFBIZ.CONTENT_ASSOC CA LEFT OUTER JOIN OFBIZ.CONTENT CO ON CA.CONTENT_ID_TO = CO.CONTENT_ID) LEFT OUTER JOIN OFBIZ.DATA_RESOURCE DR ON CO.DATA_RESOURCE_ID = DR.DATA_RESOURCE_ID WHERE ((CA.CONTENT_ID = ? AND CA.CONTENT_ASSOC_TYPE_ID = ? AND DR.DATA_RESOURCE_TYPE_ID = ?)) where clause:{CA_CONTENT_ID=WK_WL_RE_13_e, CA_CONTENT_ASSOC_TYPE_ID=ALTERNATE_LOCALE, DR_DATA_RESOURCE_TYPE_ID=ELECTRONIC_TEXT}
2012-04-09 14:10:31,162 (http-bio-0.0.0.0-8080-exec-3) [         GenericDAO.java:799:INFO ] Ran query in 166 milli-seconds:  EntityName: ContentAssocDataResourceViewTo Sql: SELECT CA.CONTENT_ID, CA.CONTENT_ID, CA.CONTENT_ID_TO, CA.CONTENT_ASSOC_TYPE_ID, CA.FROM_DATE, CA.THRU_DATE, CA.CONTENT_ASSOC_PREDICATE_ID, CA.DATA_SOURCE_ID, CA.SEQUENCE_NUM, CA.MAP_KEY, CA.UPPER_COORDINATE, CA.LEFT_COORDINATE, CA.CREATED_DATE, CA.CREATED_BY_USER_LOGIN, CA.LAST_MODIFIED_DATE, CA.LAST_MODIFIED_BY_USER_LOGIN, CO.CONTENT_ID, CO.CONTENT_TYPE_ID, CO.OWNER_CONTENT_ID, CO.DECORATOR_CONTENT_ID, CO.INSTANCE_OF_CONTENT_ID, CO.DATA_RESOURCE_ID, CO.TEMPLATE_DATA_RESOURCE_ID, CO.DATA_SOURCE_ID, CO.STATUS_ID, CO.PRIVILEGE_ENUM_ID, CO.SERVICE_NAME, CO.CONTENT_NAME, CO.DESCRIPTION, CO.LOCALE_STRING, CO.MIME_TYPE_ID, CO.CHARACTER_SET_ID, CO.CHILD_LEAF_COUNT, CO.CHILD_BRANCH_COUNT, CO.CREATED_DATE, CO.CREATED_BY_USER_LOGIN, CO.LAST_MODIFIED_DATE, CO.LAST_MODIFIED_BY_USER_LOGIN, DR.DATA_RESOURCE_ID, DR.DATA_RESOURCE_TYPE_ID, DR.DATA_TEMPLATE_TYPE_ID, DR.DATA_CATEGORY_ID, DR.DATA_SOURCE_ID, DR.STATUS_ID, DR.DATA_RESOURCE_NAME, DR.LOCALE_STRING, DR.MIME_TYPE_ID, DR.CHARACTER_SET_ID, DR.OBJECT_INFO, DR.SURVEY_ID, DR.SURVEY_RESPONSE_ID, DR.RELATED_DETAIL_ID, DR.IS_PUBLIC, DR.CREATED_DATE, DR.CREATED_BY_USER_LOGIN, DR.LAST_MODIFIED_DATE, DR.LAST_MODIFIED_BY_USER_LOGIN FROM (OFBIZ.CONTENT_ASSOC CA LEFT OUTER JOIN OFBIZ.CONTENT CO ON CA.CONTENT_ID_TO = CO.CONTENT_ID) LEFT OUTER JOIN OFBIZ.DATA_RESOURCE DR ON CO.DATA_RESOURCE_ID = DR.DATA_RESOURCE_ID WHERE ((CA.CONTENT_ID = ? AND CA.CONTENT_ASSOC_TYPE_ID = ? AND DR.DATA_RESOURCE_TYPE_ID = ?)) where clause:{CA_CONTENT_ID=WK_WL_RE_12_e, CA_CONTENT_ASSOC_TYPE_ID=ALTERNATE_LOCALE, DR_DATA_RESOURCE_TYPE_ID=ELECTRONIC_TEXT}
2012-04-09 14:10:35,802 (http-bio-0.0.0.0-8080-exec-3) [     CategoryWorker.java:82 :INFO ] [CategoryWorker.getCatalogTopCategory] Setting new top category: CATALOG1
2012-04-09 14:10:35,807 (http-bio-0.0.0.0-8080-exec-3) [   CatalogUrlFilter.java:325:INFO ] [Filtered request]: /Addidas-BG-15-WK-Bags-WK_BG_AD_15-p (/control/product)
2012-04-09 14:10:35,807 (http-bio-0.0.0.0-8080-exec-3) [     ControlServlet.java:141:INFO ] [[[product(Domain:http://localhost)] Request Begun, encoding=[UTF-8]- total:0.0,since last(Begin):0.0]]
2012-04-09 14:10:35,808 (http-bio-0.0.0.0-8080-exec-3) [       VisitHandler.java:232:INFO ] Found visitorId [10000] in cookie
2012-04-09 14:10:35,837 (http-bio-0.0.0.0-8080-exec-3) [    ConfigXMLReader.java:120:INFO ] controller loaded: 0.0040s, 300 requests, 99 views in jndi:/0.0.0.0/ecommerce/WEB-INF/controller.xml
2012-04-09 14:10:35,837 (http-bio-0.0.0.0-8080-exec-3) [     RequestHandler.java:295:INFO ] This is the first request in this visit. sessionId=78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
2012-04-09 14:10:35,842 (http-bio-0.0.0.0-8080-exec-3) [     RequestHandler.java:762:INFO ] Rendering View [product], sessionId=78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
2012-04-09 14:10:35,928 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 37 screens in 0.011s from: file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CatalogScreens.xml
2012-04-09 14:10:36,049 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 16 screens in 0.01s from: file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CommonScreens.xml
2012-04-09 14:10:36,175 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 8 screens in 0.01s from: file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CartScreens.xml
2012-04-09 14:10:36,254 (http-bio-0.0.0.0-8080-exec-5) [ControlEventListener.java:65 :INFO ] Creating session: 51466D98AADAB81472F35A64CCAFCF09.jvm1
2012-04-09 14:10:36,422 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 7 screens in 0.01s from: file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/EmailContactListScreens.xml
2012-04-09 14:10:36,476 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 8 screens in 0.0080s from: file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/ContentScreens.xml
2012-04-09 14:10:36,487 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 13 screens in 0.0090s from: file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/ForumScreens.xml
2012-04-09 14:10:36,504 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 15 screens in 0.01s from: file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/blog/BlogScreens.xml
2012-04-09 14:10:36,553 (http-bio-0.0.0.0-8080-exec-3) [      ScreenFactory.java:130:INFO ] Got 19 screens in 0.0070s from: file:/D:/testbed/ofbiz-trunk/applications/order/widget/ordermgr/OrderEntryCatalogScreens.xml
2012-04-09 14:10:37,036 (http-bio-0.0.0.0-8080-exec-3) [ ProductStoreWorker.java:481:INFO ] getSurvey for product WK_BG_AD_15
2012-04-09 14:10:37,093 (http-bio-0.0.0.0-8080-exec-3) [  ServiceDispatcher.java:619:INFO ] [[ASync service started...- total:0.0,since last(Begin):0.0]] - 'ecommerce / countProductView'
2012-04-09 14:10:37,094 (http-bio-0.0.0.0-8080-exec-3) [  ServiceDispatcher.java:716:INFO ] [[ASync service finished...- total:0.0010,since last(ASync service sta...):0.0010]] - 'ecommerce / countProductView'
2012-04-09 14:10:37,141 (default-invoker-Thread-20) [         JobInvoker.java:232:INFO ] Invoker [default-invoker-Thread-20] received job [1333960837094] from poller [org.ofbiz.service.job.JobPoller@5a89484a]
2012-04-09 14:10:37,208 (http-bio-0.0.0.0-8080-exec-3) [   GenericDelegator.java:2246:WARN ] Tried to put a value of the Visit entity in the BY PRIMARY KEY cache but this entity has never-cache set to true, not caching.
2012-04-09 14:10:37,208 (http-bio-0.0.0.0-8080-exec-3) [       ServerHitBin.java:633:INFO ] Visit delegatorName=default, ServerHitBin delegatorName=default
2012-04-09 14:10:37,230 (http-bio-0.0.0.0-8080-exec-3) [     ControlServlet.java:324:INFO ] [[[product(Domain:http://localhost)] Request Done- total:1.423,since last([product(Domain:h...):1.423]]

Rgds
Sanjeev Gupta
www.digitalwebadvisors.com
Reply | Threaded
Open this post in threaded view
|

Re: Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

samhamilton
Did you try turning on caching?

Sam


On 9 Apr 2012, at 17:34, sanjeev wrote:

> when you go to a product page and hit Previous or Next button, its is taking
> about 15 - 20 seconds for ofbiz to load the product page.
> From the logs it looks like that the data resources and the content
> associations created for SEO URL's cold be the culprit - the complex SQL
> queries itself is taking about 360 + 116 milli seconds.
>
> I even increased the memory allocation, but it didn't help  - -Xms1024M
> -Xmx5120M -XX:MaxPermSize=5120m
>
> Can someone pls take a look at this and advise.
>
> *Version*  : SVN Trunk
> *O/S*      : Windows
> *DB*       : derby
>
> *Logs *
> 2012-04-09 14:10:25,482 (http-bio-0.0.0.0-8080-exec-3)
> [ControlEventListener.java:65 :INFO ] Creating session:
> 78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
> 2012-04-09 14:10:30,989 (http-bio-0.0.0.0-8080-exec-3) [        
> GenericDAO.java:799:INFO ] Ran query in 310 milli-seconds:  EntityName:
> ContentAssocDataResourceViewTo Sql: SELECT CA.CONTENT_ID, CA.CONTENT_ID,
> CA.CONTENT_ID_TO, CA.CONTENT_ASSOC_TYPE_ID, CA.FROM_DATE, CA.THRU_DATE,
> CA.CONTENT_ASSOC_PREDICATE_ID, CA.DATA_SOURCE_ID, CA.SEQUENCE_NUM,
> CA.MAP_KEY, CA.UPPER_COORDINATE, CA.LEFT_COORDINATE, CA.CREATED_DATE,
> CA.CREATED_BY_USER_LOGIN, CA.LAST_MODIFIED_DATE,
> CA.LAST_MODIFIED_BY_USER_LOGIN, CO.CONTENT_ID, CO.CONTENT_TYPE_ID,
> CO.OWNER_CONTENT_ID, CO.DECORATOR_CONTENT_ID, CO.INSTANCE_OF_CONTENT_ID,
> CO.DATA_RESOURCE_ID, CO.TEMPLATE_DATA_RESOURCE_ID, CO.DATA_SOURCE_ID,
> CO.STATUS_ID, CO.PRIVILEGE_ENUM_ID, CO.SERVICE_NAME, CO.CONTENT_NAME,
> CO.DESCRIPTION, CO.LOCALE_STRING, CO.MIME_TYPE_ID, CO.CHARACTER_SET_ID,
> CO.CHILD_LEAF_COUNT, CO.CHILD_BRANCH_COUNT, CO.CREATED_DATE,
> CO.CREATED_BY_USER_LOGIN, CO.LAST_MODIFIED_DATE,
> CO.LAST_MODIFIED_BY_USER_LOGIN, DR.DATA_RESOURCE_ID,
> DR.DATA_RESOURCE_TYPE_ID, DR.DATA_TEMPLATE_TYPE_ID, DR.DATA_CATEGORY_ID,
> DR.DATA_SOURCE_ID, DR.STATUS_ID, DR.DATA_RESOURCE_NAME, DR.LOCALE_STRING,
> DR.MIME_TYPE_ID, DR.CHARACTER_SET_ID, DR.OBJECT_INFO, DR.SURVEY_ID,
> DR.SURVEY_RESPONSE_ID, DR.RELATED_DETAIL_ID, DR.IS_PUBLIC, DR.CREATED_DATE,
> DR.CREATED_BY_USER_LOGIN, DR.LAST_MODIFIED_DATE,
> DR.LAST_MODIFIED_BY_USER_LOGIN FROM (OFBIZ.CONTENT_ASSOC CA LEFT OUTER JOIN
> OFBIZ.CONTENT CO ON CA.CONTENT_ID_TO = CO.CONTENT_ID) LEFT OUTER JOIN
> OFBIZ.DATA_RESOURCE DR ON CO.DATA_RESOURCE_ID = DR.DATA_RESOURCE_ID WHERE
> ((CA.CONTENT_ID = ? AND CA.CONTENT_ASSOC_TYPE_ID = ? AND
> DR.DATA_RESOURCE_TYPE_ID = ?)) where clause:{CA_CONTENT_ID=WK_WL_RE_13_e,
> CA_CONTENT_ASSOC_TYPE_ID=ALTERNATE_LOCALE,
> DR_DATA_RESOURCE_TYPE_ID=ELECTRONIC_TEXT}
> 2012-04-09 14:10:31,162 (http-bio-0.0.0.0-8080-exec-3) [        
> GenericDAO.java:799:INFO ] Ran query in 166 milli-seconds:  EntityName:
> ContentAssocDataResourceViewTo Sql: SELECT CA.CONTENT_ID, CA.CONTENT_ID,
> CA.CONTENT_ID_TO, CA.CONTENT_ASSOC_TYPE_ID, CA.FROM_DATE, CA.THRU_DATE,
> CA.CONTENT_ASSOC_PREDICATE_ID, CA.DATA_SOURCE_ID, CA.SEQUENCE_NUM,
> CA.MAP_KEY, CA.UPPER_COORDINATE, CA.LEFT_COORDINATE, CA.CREATED_DATE,
> CA.CREATED_BY_USER_LOGIN, CA.LAST_MODIFIED_DATE,
> CA.LAST_MODIFIED_BY_USER_LOGIN, CO.CONTENT_ID, CO.CONTENT_TYPE_ID,
> CO.OWNER_CONTENT_ID, CO.DECORATOR_CONTENT_ID, CO.INSTANCE_OF_CONTENT_ID,
> CO.DATA_RESOURCE_ID, CO.TEMPLATE_DATA_RESOURCE_ID, CO.DATA_SOURCE_ID,
> CO.STATUS_ID, CO.PRIVILEGE_ENUM_ID, CO.SERVICE_NAME, CO.CONTENT_NAME,
> CO.DESCRIPTION, CO.LOCALE_STRING, CO.MIME_TYPE_ID, CO.CHARACTER_SET_ID,
> CO.CHILD_LEAF_COUNT, CO.CHILD_BRANCH_COUNT, CO.CREATED_DATE,
> CO.CREATED_BY_USER_LOGIN, CO.LAST_MODIFIED_DATE,
> CO.LAST_MODIFIED_BY_USER_LOGIN, DR.DATA_RESOURCE_ID,
> DR.DATA_RESOURCE_TYPE_ID, DR.DATA_TEMPLATE_TYPE_ID, DR.DATA_CATEGORY_ID,
> DR.DATA_SOURCE_ID, DR.STATUS_ID, DR.DATA_RESOURCE_NAME, DR.LOCALE_STRING,
> DR.MIME_TYPE_ID, DR.CHARACTER_SET_ID, DR.OBJECT_INFO, DR.SURVEY_ID,
> DR.SURVEY_RESPONSE_ID, DR.RELATED_DETAIL_ID, DR.IS_PUBLIC, DR.CREATED_DATE,
> DR.CREATED_BY_USER_LOGIN, DR.LAST_MODIFIED_DATE,
> DR.LAST_MODIFIED_BY_USER_LOGIN FROM (OFBIZ.CONTENT_ASSOC CA LEFT OUTER JOIN
> OFBIZ.CONTENT CO ON CA.CONTENT_ID_TO = CO.CONTENT_ID) LEFT OUTER JOIN
> OFBIZ.DATA_RESOURCE DR ON CO.DATA_RESOURCE_ID = DR.DATA_RESOURCE_ID WHERE
> ((CA.CONTENT_ID = ? AND CA.CONTENT_ASSOC_TYPE_ID = ? AND
> DR.DATA_RESOURCE_TYPE_ID = ?)) where clause:{CA_CONTENT_ID=WK_WL_RE_12_e,
> CA_CONTENT_ASSOC_TYPE_ID=ALTERNATE_LOCALE,
> DR_DATA_RESOURCE_TYPE_ID=ELECTRONIC_TEXT}
> 2012-04-09 14:10:35,802 (http-bio-0.0.0.0-8080-exec-3) [    
> CategoryWorker.java:82 :INFO ] [CategoryWorker.getCatalogTopCategory]
> Setting new top category: CATALOG1
> 2012-04-09 14:10:35,807 (http-bio-0.0.0.0-8080-exec-3) [  
> CatalogUrlFilter.java:325:INFO ] [Filtered request]:
> /Addidas-BG-15-WK-Bags-WK_BG_AD_15-p (/control/product)
> 2012-04-09 14:10:35,807 (http-bio-0.0.0.0-8080-exec-3) [    
> ControlServlet.java:141:INFO ] [[[product(Domain:http://localhost)] Request
> Begun, encoding=[UTF-8]- total:0.0,since last(Begin):0.0]]
> 2012-04-09 14:10:35,808 (http-bio-0.0.0.0-8080-exec-3) [      
> VisitHandler.java:232:INFO ] Found visitorId [10000] in cookie
> 2012-04-09 14:10:35,837 (http-bio-0.0.0.0-8080-exec-3) [  
> ConfigXMLReader.java:120:INFO ] controller loaded: 0.0040s, 300 requests, 99
> views in jndi:/0.0.0.0/ecommerce/WEB-INF/controller.xml
> 2012-04-09 14:10:35,837 (http-bio-0.0.0.0-8080-exec-3) [    
> RequestHandler.java:295:INFO ] This is the first request in this visit.
> sessionId=78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
> 2012-04-09 14:10:35,842 (http-bio-0.0.0.0-8080-exec-3) [    
> RequestHandler.java:762:INFO ] Rendering View [product],
> sessionId=78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
> 2012-04-09 14:10:35,928 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 37 screens in 0.011s from:
> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CatalogScreens.xml
> 2012-04-09 14:10:36,049 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 16 screens in 0.01s from:
> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CommonScreens.xml
> 2012-04-09 14:10:36,175 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 8 screens in 0.01s from:
> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CartScreens.xml
> 2012-04-09 14:10:36,254 (http-bio-0.0.0.0-8080-exec-5)
> [ControlEventListener.java:65 :INFO ] Creating session:
> 51466D98AADAB81472F35A64CCAFCF09.jvm1
> 2012-04-09 14:10:36,422 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 7 screens in 0.01s from:
> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/EmailContactListScreens.xml
> 2012-04-09 14:10:36,476 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 8 screens in 0.0080s from:
> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/ContentScreens.xml
> 2012-04-09 14:10:36,487 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 13 screens in 0.0090s from:
> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/ForumScreens.xml
> 2012-04-09 14:10:36,504 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 15 screens in 0.01s from:
> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/blog/BlogScreens.xml
> 2012-04-09 14:10:36,553 (http-bio-0.0.0.0-8080-exec-3) [    
> ScreenFactory.java:130:INFO ] Got 19 screens in 0.0070s from:
> file:/D:/testbed/ofbiz-trunk/applications/order/widget/ordermgr/OrderEntryCatalogScreens.xml
> 2012-04-09 14:10:37,036 (http-bio-0.0.0.0-8080-exec-3) [
> ProductStoreWorker.java:481:INFO ] getSurvey for product WK_BG_AD_15
> 2012-04-09 14:10:37,093 (http-bio-0.0.0.0-8080-exec-3) [
> ServiceDispatcher.java:619:INFO ] [[ASync service started...-
> total:0.0,since last(Begin):0.0]] - 'ecommerce / countProductView'
> 2012-04-09 14:10:37,094 (http-bio-0.0.0.0-8080-exec-3) [
> ServiceDispatcher.java:716:INFO ] [[ASync service finished...-
> total:0.0010,since last(ASync service sta...):0.0010]] - 'ecommerce /
> countProductView'
> 2012-04-09 14:10:37,141 (default-invoker-Thread-20) [        
> JobInvoker.java:232:INFO ] Invoker [default-invoker-Thread-20] received job
> [1333960837094] from poller [org.ofbiz.service.job.JobPoller@5a89484a]
> 2012-04-09 14:10:37,208 (http-bio-0.0.0.0-8080-exec-3) [  
> GenericDelegator.java:2246:WARN ] Tried to put a value of the Visit entity
> in the BY PRIMARY KEY cache but this entity has never-cache set to true, not
> caching.
> 2012-04-09 14:10:37,208 (http-bio-0.0.0.0-8080-exec-3) [      
> ServerHitBin.java:633:INFO ] Visit delegatorName=default, ServerHitBin
> delegatorName=default
> 2012-04-09 14:10:37,230 (http-bio-0.0.0.0-8080-exec-3) [    
> ControlServlet.java:324:INFO ] [[[product(Domain:http://localhost)] Request
> Done- total:1.423,since last([product(Domain:h...):1.423]]
>
>
>
> -----
> Rgds
> Sanjeev
> --
> View this message in context: http://ofbiz.135035.n4.nabble.com/Product-Page-load-taking-15-20-seconds-to-load-SEO-URLs-may-be-the-culprit-tp4542399p4542399.html
> Sent from the OFBiz - User mailing list archive at Nabble.com.


smime.p7s (6K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Jacques Le Roux
Administrator
I don't reproduce on trunk demo

Jacques

Sam Hamilton wrote:

> Did you try turning on caching?
>
> Sam
>
>
> On 9 Apr 2012, at 17:34, sanjeev wrote:
>
>> when you go to a product page and hit Previous or Next button, its is taking
>> about 15 - 20 seconds for ofbiz to load the product page.
>> From the logs it looks like that the data resources and the content
>> associations created for SEO URL's cold be the culprit - the complex SQL
>> queries itself is taking about 360 + 116 milli seconds.
>>
>> I even increased the memory allocation, but it didn't help  - -Xms1024M
>> -Xmx5120M -XX:MaxPermSize=5120m
>>
>> Can someone pls take a look at this and advise.
>>
>> *Version*  : SVN Trunk
>> *O/S*      : Windows
>> *DB*       : derby
>>
>> *Logs *
>> 2012-04-09 14:10:25,482 (http-bio-0.0.0.0-8080-exec-3)
>> [ControlEventListener.java:65 :INFO ] Creating session:
>> 78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
>> 2012-04-09 14:10:30,989 (http-bio-0.0.0.0-8080-exec-3) [
>> GenericDAO.java:799:INFO ] Ran query in 310 milli-seconds:  EntityName:
>> ContentAssocDataResourceViewTo Sql: SELECT CA.CONTENT_ID, CA.CONTENT_ID,
>> CA.CONTENT_ID_TO, CA.CONTENT_ASSOC_TYPE_ID, CA.FROM_DATE, CA.THRU_DATE,
>> CA.CONTENT_ASSOC_PREDICATE_ID, CA.DATA_SOURCE_ID, CA.SEQUENCE_NUM,
>> CA.MAP_KEY, CA.UPPER_COORDINATE, CA.LEFT_COORDINATE, CA.CREATED_DATE,
>> CA.CREATED_BY_USER_LOGIN, CA.LAST_MODIFIED_DATE,
>> CA.LAST_MODIFIED_BY_USER_LOGIN, CO.CONTENT_ID, CO.CONTENT_TYPE_ID,
>> CO.OWNER_CONTENT_ID, CO.DECORATOR_CONTENT_ID, CO.INSTANCE_OF_CONTENT_ID,
>> CO.DATA_RESOURCE_ID, CO.TEMPLATE_DATA_RESOURCE_ID, CO.DATA_SOURCE_ID,
>> CO.STATUS_ID, CO.PRIVILEGE_ENUM_ID, CO.SERVICE_NAME, CO.CONTENT_NAME,
>> CO.DESCRIPTION, CO.LOCALE_STRING, CO.MIME_TYPE_ID, CO.CHARACTER_SET_ID,
>> CO.CHILD_LEAF_COUNT, CO.CHILD_BRANCH_COUNT, CO.CREATED_DATE,
>> CO.CREATED_BY_USER_LOGIN, CO.LAST_MODIFIED_DATE,
>> CO.LAST_MODIFIED_BY_USER_LOGIN, DR.DATA_RESOURCE_ID,
>> DR.DATA_RESOURCE_TYPE_ID, DR.DATA_TEMPLATE_TYPE_ID, DR.DATA_CATEGORY_ID,
>> DR.DATA_SOURCE_ID, DR.STATUS_ID, DR.DATA_RESOURCE_NAME, DR.LOCALE_STRING,
>> DR.MIME_TYPE_ID, DR.CHARACTER_SET_ID, DR.OBJECT_INFO, DR.SURVEY_ID,
>> DR.SURVEY_RESPONSE_ID, DR.RELATED_DETAIL_ID, DR.IS_PUBLIC, DR.CREATED_DATE,
>> DR.CREATED_BY_USER_LOGIN, DR.LAST_MODIFIED_DATE,
>> DR.LAST_MODIFIED_BY_USER_LOGIN FROM (OFBIZ.CONTENT_ASSOC CA LEFT OUTER JOIN
>> OFBIZ.CONTENT CO ON CA.CONTENT_ID_TO = CO.CONTENT_ID) LEFT OUTER JOIN
>> OFBIZ.DATA_RESOURCE DR ON CO.DATA_RESOURCE_ID = DR.DATA_RESOURCE_ID WHERE
>> ((CA.CONTENT_ID = ? AND CA.CONTENT_ASSOC_TYPE_ID = ? AND
>> DR.DATA_RESOURCE_TYPE_ID = ?)) where clause:{CA_CONTENT_ID=WK_WL_RE_13_e,
>> CA_CONTENT_ASSOC_TYPE_ID=ALTERNATE_LOCALE,
>> DR_DATA_RESOURCE_TYPE_ID=ELECTRONIC_TEXT}
>> 2012-04-09 14:10:31,162 (http-bio-0.0.0.0-8080-exec-3) [
>> GenericDAO.java:799:INFO ] Ran query in 166 milli-seconds:  EntityName:
>> ContentAssocDataResourceViewTo Sql: SELECT CA.CONTENT_ID, CA.CONTENT_ID,
>> CA.CONTENT_ID_TO, CA.CONTENT_ASSOC_TYPE_ID, CA.FROM_DATE, CA.THRU_DATE,
>> CA.CONTENT_ASSOC_PREDICATE_ID, CA.DATA_SOURCE_ID, CA.SEQUENCE_NUM,
>> CA.MAP_KEY, CA.UPPER_COORDINATE, CA.LEFT_COORDINATE, CA.CREATED_DATE,
>> CA.CREATED_BY_USER_LOGIN, CA.LAST_MODIFIED_DATE,
>> CA.LAST_MODIFIED_BY_USER_LOGIN, CO.CONTENT_ID, CO.CONTENT_TYPE_ID,
>> CO.OWNER_CONTENT_ID, CO.DECORATOR_CONTENT_ID, CO.INSTANCE_OF_CONTENT_ID,
>> CO.DATA_RESOURCE_ID, CO.TEMPLATE_DATA_RESOURCE_ID, CO.DATA_SOURCE_ID,
>> CO.STATUS_ID, CO.PRIVILEGE_ENUM_ID, CO.SERVICE_NAME, CO.CONTENT_NAME,
>> CO.DESCRIPTION, CO.LOCALE_STRING, CO.MIME_TYPE_ID, CO.CHARACTER_SET_ID,
>> CO.CHILD_LEAF_COUNT, CO.CHILD_BRANCH_COUNT, CO.CREATED_DATE,
>> CO.CREATED_BY_USER_LOGIN, CO.LAST_MODIFIED_DATE,
>> CO.LAST_MODIFIED_BY_USER_LOGIN, DR.DATA_RESOURCE_ID,
>> DR.DATA_RESOURCE_TYPE_ID, DR.DATA_TEMPLATE_TYPE_ID, DR.DATA_CATEGORY_ID,
>> DR.DATA_SOURCE_ID, DR.STATUS_ID, DR.DATA_RESOURCE_NAME, DR.LOCALE_STRING,
>> DR.MIME_TYPE_ID, DR.CHARACTER_SET_ID, DR.OBJECT_INFO, DR.SURVEY_ID,
>> DR.SURVEY_RESPONSE_ID, DR.RELATED_DETAIL_ID, DR.IS_PUBLIC, DR.CREATED_DATE,
>> DR.CREATED_BY_USER_LOGIN, DR.LAST_MODIFIED_DATE,
>> DR.LAST_MODIFIED_BY_USER_LOGIN FROM (OFBIZ.CONTENT_ASSOC CA LEFT OUTER JOIN
>> OFBIZ.CONTENT CO ON CA.CONTENT_ID_TO = CO.CONTENT_ID) LEFT OUTER JOIN
>> OFBIZ.DATA_RESOURCE DR ON CO.DATA_RESOURCE_ID = DR.DATA_RESOURCE_ID WHERE
>> ((CA.CONTENT_ID = ? AND CA.CONTENT_ASSOC_TYPE_ID = ? AND
>> DR.DATA_RESOURCE_TYPE_ID = ?)) where clause:{CA_CONTENT_ID=WK_WL_RE_12_e,
>> CA_CONTENT_ASSOC_TYPE_ID=ALTERNATE_LOCALE,
>> DR_DATA_RESOURCE_TYPE_ID=ELECTRONIC_TEXT}
>> 2012-04-09 14:10:35,802 (http-bio-0.0.0.0-8080-exec-3) [
>> CategoryWorker.java:82 :INFO ] [CategoryWorker.getCatalogTopCategory]
>> Setting new top category: CATALOG1
>> 2012-04-09 14:10:35,807 (http-bio-0.0.0.0-8080-exec-3) [
>> CatalogUrlFilter.java:325:INFO ] [Filtered request]:
>> /Addidas-BG-15-WK-Bags-WK_BG_AD_15-p (/control/product)
>> 2012-04-09 14:10:35,807 (http-bio-0.0.0.0-8080-exec-3) [
>> ControlServlet.java:141:INFO ] [[[product(Domain:http://localhost)] Request
>> Begun, encoding=[UTF-8]- total:0.0,since last(Begin):0.0]]
>> 2012-04-09 14:10:35,808 (http-bio-0.0.0.0-8080-exec-3) [
>> VisitHandler.java:232:INFO ] Found visitorId [10000] in cookie
>> 2012-04-09 14:10:35,837 (http-bio-0.0.0.0-8080-exec-3) [
>> ConfigXMLReader.java:120:INFO ] controller loaded: 0.0040s, 300 requests, 99
>> views in jndi:/0.0.0.0/ecommerce/WEB-INF/controller.xml
>> 2012-04-09 14:10:35,837 (http-bio-0.0.0.0-8080-exec-3) [
>> RequestHandler.java:295:INFO ] This is the first request in this visit.
>> sessionId=78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
>> 2012-04-09 14:10:35,842 (http-bio-0.0.0.0-8080-exec-3) [
>> RequestHandler.java:762:INFO ] Rendering View [product],
>> sessionId=78D8FE9C7C3C8F916DAEE4E5242ECD24.jvm1
>> 2012-04-09 14:10:35,928 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 37 screens in 0.011s from:
>> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CatalogScreens.xml
>> 2012-04-09 14:10:36,049 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 16 screens in 0.01s from:
>> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CommonScreens.xml
>> 2012-04-09 14:10:36,175 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 8 screens in 0.01s from:
>> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/CartScreens.xml
>> 2012-04-09 14:10:36,254 (http-bio-0.0.0.0-8080-exec-5)
>> [ControlEventListener.java:65 :INFO ] Creating session:
>> 51466D98AADAB81472F35A64CCAFCF09.jvm1
>> 2012-04-09 14:10:36,422 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 7 screens in 0.01s from:
>> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/EmailContactListScreens.xml
>> 2012-04-09 14:10:36,476 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 8 screens in 0.0080s from:
>> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/ContentScreens.xml
>> 2012-04-09 14:10:36,487 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 13 screens in 0.0090s from:
>> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/ForumScreens.xml
>> 2012-04-09 14:10:36,504 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 15 screens in 0.01s from:
>> file:/D:/testbed/ofbiz-trunk/specialpurpose/ecommerce/widget/blog/BlogScreens.xml
>> 2012-04-09 14:10:36,553 (http-bio-0.0.0.0-8080-exec-3) [
>> ScreenFactory.java:130:INFO ] Got 19 screens in 0.0070s from:
>> file:/D:/testbed/ofbiz-trunk/applications/order/widget/ordermgr/OrderEntryCatalogScreens.xml
>> 2012-04-09 14:10:37,036 (http-bio-0.0.0.0-8080-exec-3) [
>> ProductStoreWorker.java:481:INFO ] getSurvey for product WK_BG_AD_15
>> 2012-04-09 14:10:37,093 (http-bio-0.0.0.0-8080-exec-3) [
>> ServiceDispatcher.java:619:INFO ] [[ASync service started...-
>> total:0.0,since last(Begin):0.0]] - 'ecommerce / countProductView'
>> 2012-04-09 14:10:37,094 (http-bio-0.0.0.0-8080-exec-3) [
>> ServiceDispatcher.java:716:INFO ] [[ASync service finished...-
>> total:0.0010,since last(ASync service sta...):0.0010]] - 'ecommerce /
>> countProductView'
>> 2012-04-09 14:10:37,141 (default-invoker-Thread-20) [
>> JobInvoker.java:232:INFO ] Invoker [default-invoker-Thread-20] received job
>> [1333960837094] from poller [org.ofbiz.service.job.JobPoller@5a89484a]
>> 2012-04-09 14:10:37,208 (http-bio-0.0.0.0-8080-exec-3) [
>> GenericDelegator.java:2246:WARN ] Tried to put a value of the Visit entity
>> in the BY PRIMARY KEY cache but this entity has never-cache set to true, not
>> caching.
>> 2012-04-09 14:10:37,208 (http-bio-0.0.0.0-8080-exec-3) [
>> ServerHitBin.java:633:INFO ] Visit delegatorName=default, ServerHitBin
>> delegatorName=default
>> 2012-04-09 14:10:37,230 (http-bio-0.0.0.0-8080-exec-3) [
>> ControlServlet.java:324:INFO ] [[[product(Domain:http://localhost)] Request
>> Done- total:1.423,since last([product(Domain:h...):1.423]]
>>
>>
>>
>> -----
>> Rgds
>> Sanjeev
>> --
>> View this message in context:
>> http://ofbiz.135035.n4.nabble.com/Product-Page-load-taking-15-20-seconds-to-load-SEO-URLs-may-be-the-culprit-tp4542399p4542399.html
>> Sent from the OFBiz - User mailing list archive at Nabble.com.

smime.p7s (8K) Download Attachment
Reply | Threaded
Open this post in threaded view
|

Re: Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Sanjeev Gupta
Hi Sam
I'm using the default cache settings that available out of box - haven't implemented anything additional. Please do let me know you have any suggestions or can point me to them.

Hi Jacques,
I have about 350 products loaded in my instance - could that be making the difference
Rgds
Sanjeev Gupta
www.digitalwebadvisors.com
Reply | Threaded
Open this post in threaded view
|

Re: Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Sanjeev Gupta
In a different instance of ofbiz, I loaded the same 350 products but without the SEO URLs. The response is just a few seconds which is in line with other page requests.

Rgds
Sanjeev Gupta
www.digitalwebadvisors.com
Reply | Threaded
Open this post in threaded view
|

Re: Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Jacques Le Roux
Administrator
In reply to this post by Sanjeev Gupta
Did you follow
https://cwiki.apache.org/confluence/display/OFBTECH/Apache+OFBiz+Technical+Production+Setup+Guide#ApacheOFBizTechnicalProductionSetupGuide-CacheSettings ?

Jacques

From: "sanjeev" <[hidden email]>

> Hi Sam
> I'm using the default cache settings that available out of box - haven't
> implemented anything additional. Please do let me know you have any
> suggestions or can point me to them.
>
> Hi Jacques,
> I have about 350 products loaded in my instance - could that be making the
> difference
>
> -----
> Rgds
> Sanjeev
> --
> View this message in context:
> http://ofbiz.135035.n4.nabble.com/Product-Page-load-taking-15-20-seconds-to-load-SEO-URLs-may-be-the-culprit-tp4542399p4542519.html
> Sent from the OFBiz - User mailing list archive at Nabble.com.
Reply | Threaded
Open this post in threaded view
|

Re: Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Sanjeev Gupta
Yes, I did try the cache settings too but didn't help.

I have a strongly feel that it's something to do with the way Alternate URL's have been implemented. Every time i his the browser for the Next or the Previous product:
1) It take a good few seconds for the server to respond and display something on the server console.
2) Ever hit calls GenericDAO.java:799 twice, each call taking its sweet time : first call is typically 200+ ms and the second is 100+ ms.
And by the time the next product shows up on the browser (only local machine itself), it is about 15 - 20 seconds.
Rgds
Sanjeev Gupta
www.digitalwebadvisors.com
Reply | Threaded
Open this post in threaded view
|

Re: Product Page load taking 15 - 20 seconds to load : SEO URLs may be the culprit

Jacques Le Roux
Administrator
And you did not change anything regarding this aspect?
Did you change other things?
Did you try with less products since?

Jacques

From: "sanjeev" <[hidden email]>

> Yes, I did try the cache settings too but didn't help.
>
> I have a strongly feel that it's something to do with the way Alternate
> URL's have been implemented. Every time i his the browser for the *Next *or
> the *Previous* product:
> 1) It take a good few seconds for the server to respond and display
> something on the server console.
> 2) Ever hit calls GenericDAO.java:799 twice, each call taking its sweet time
> : first call is typically 200+ ms and the second is 100+ ms.
> And by the time the next product shows up on the browser (only local machine
> itself), it is about 15 - 20 seconds.
>
>
> -----
> Rgds
> Sanjeev
> www.sanjeevg.com
> @sanjeevgcom
> --
> View this message in context:
> http://ofbiz.135035.n4.nabble.com/Product-Page-load-taking-15-20-seconds-to-load-SEO-URLs-may-be-the-culprit-tp4542399p4568321.html
> Sent from the OFBiz - User mailing list archive at Nabble.com.