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.
