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 |
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 |
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 |
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 |
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 |
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. |
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 |
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. |
Free forum by Nabble | Edit this page |