Hi Team,
I work on Liferay 6.1 and last week when we added an Index-Hook (JournalArticle) to our present system, we ran into this problem.
Before showing my logs ,would like to explain the present system in detail.
ISSUE: After loading few pages ,I see these errors on my log file i.e connection pool error
log file below
Note: After checking this logs ,We update no of "activeconnection=100" & "maxpoolsize=100" in our data source definition
But Again we ran into this issue ,but this time with 2-3min delay after server is loaded.And I started getting mails from my DB team
"High CPU Load sessions from XXXXX Schema" -asking me to explain why so many connection?.
Here is the Logs I received from DB team .
Please Note this query below
Not sure what this query about ? and surely its not coming from my application . As I tested my production server by removing all the portlets,hooks and theme.
Still saw this issue.
Any help is appreciated .
I had to roll back my changes on PROD server
.
Thanks
Shoda Srikanth
I work on Liferay 6.1 and last week when we added an Index-Hook (JournalArticle) to our present system, we ran into this problem.
Before showing my logs ,would like to explain the present system in detail.
- We have been using liferay since 5.X ,we migrated it to successive Liferay releases and now we have our Prod on Liferay 6.1
- Point to note is ,we had some external JAR (spring Interceptors ) for using Custom Indexing ,which we moved till 6.1 last year and everything worked smoothly.
- Recently we decided to move out of this patch files and use Liferay Index-Hook and where able to implement and test everything on stage successfully.
- But when we moved the Index Hook and removed the old Patch files(external-jars) from our system.
- When we start the server everything works smoothly and new Indexing is being used/called when we add an article(Journal) by Liferay. So far so good .
ISSUE: After loading few pages ,I see these errors on my log file i.e connection pool error
DBCExceptionReporter:82] Cannot get a connection, pool error Timeout waiting for idle objectlog file below
17:56:09,160 ERROR [ajp-bio-4558-exec-174][JDBCExceptionReporter:82] Cannot get a connection, pool error Timeout waiting for idle object
17:56:09,166 ERROR [ajp-bio-4558-exec-174][IncludeTag:167] Current URL /press-release-content?type=webcontent&articleId=1786758 generates exception: com.liferay.portal.kernel.exception.SystemException: com.liferay.portal.kernel.dao.orm.ORMException: org.hibernate.exception.GenericJDBCException: could not execute query
java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1171)
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
at com.liferay.portal.dao.jdbc.util.DataSourceWrapper.getConnection(DataSourceWrapper.java:39)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:534)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:452)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1700)
at org.hibernate.loader.Loader.doQuery(Loader.java:801)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
at org.hibernate.loader.Loader.doList(Loader.java:2542)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
at org.hibernate.loader.Loader.list(Loader.java:2271)
at org.hibernate.hql.classic.QueryTranslatorImpl.list(QueryTranslatorImpl.java:940)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:101)
at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:86)
at com.liferay.portlet.asset.service.persistence.AssetEntryPersistenceImpl.fetchByC_C(AssetEntryPersistenceImpl.java:3005)
17:56:09,209 ERROR [ajp-bio-4558-exec-7][JDBCExceptionReporter:82] Cannot get a connection, pool error Timeout waiting for idle object
17:56:09,210 ERROR [ajp-bio-4558-exec-7][IncludeTag:167] Current URL /feature-content?type=webcontent&articleId=1786641&Country_Site=GL&POSITION=Social+Media&REFERRING_SITE=Twitter&CREATIVE=Corporate%20Communications+Cisco++Article+Graphic generates exception: com.liferay.portal.kernel.exception.SystemException: com.liferay.portal.kernel.dao.orm.ORMException: org.hibernate.exception.GenericJDBCException: could not execute query
java.util.NoSuchElementException: Timeout waiting for idle object
at org.apache.tomcat.dbcp.pool.impl.GenericObjectPool.borrowObject(GenericObjectPool.java:1171)
at org.apache.tomcat.dbcp.dbcp.PoolingDataSource.getConnection(PoolingDataSource.java:106)
at org.apache.tomcat.dbcp.dbcp.BasicDataSource.getConnection(BasicDataSource.java:1044)
at com.liferay.portal.dao.jdbc.util.DataSourceWrapper.getConnection(DataSourceWrapper.java:39)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:534)
at org.hibernate.jdbc.AbstractBatcher.getPreparedStatement(AbstractBatcher.java:452)
at org.hibernate.jdbc.AbstractBatcher.prepareQueryStatement(AbstractBatcher.java:161)
at org.hibernate.loader.Loader.prepareQueryStatement(Loader.java:1700)
at org.hibernate.loader.Loader.doQuery(Loader.java:801)
at org.hibernate.loader.Loader.doQueryAndInitializeNonLazyCollections(Loader.java:274)
at org.hibernate.loader.Loader.doList(Loader.java:2542)
at org.hibernate.loader.Loader.listIgnoreQueryCache(Loader.java:2276)
at org.hibernate.loader.Loader.list(Loader.java:2271)
at org.hibernate.hql.classic.QueryTranslatorImpl.list(QueryTranslatorImpl.java:940)
at org.hibernate.engine.query.HQLQueryPlan.performList(HQLQueryPlan.java:196)
at org.hibernate.impl.SessionImpl.list(SessionImpl.java:1268)
at org.hibernate.impl.QueryImpl.list(QueryImpl.java:102)
at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:101)
at com.liferay.portal.dao.orm.hibernate.QueryImpl.list(QueryImpl.java:86)
at com.liferay.portlet.asset.service.persistence.AssetEntryPersistenceImpl.fetchByC_C(AssetEntryPersistenceImpl.java:3005)Note: After checking this logs ,We update no of "activeconnection=100" & "maxpoolsize=100" in our data source definition
But Again we ran into this issue ,but this time with 2-3min delay after server is loaded.And I started getting mails from my DB team
"High CPU Load sessions from XXXXX Schema" -asking me to explain why so many connection?.
Here is the Logs I received from DB team .
SPID SID SERIAL# USERNAME MACHINE SQL_ID SQL_HASH_VALUE MODULE STATUS EVENT
-------- ------ ------- --------------- ------------------------ ------------- -------------- -------------------------------------------------- -------- ------------------------------
INACTIVE SQL*Net message from client
22743 221 27180 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
26428 1168 44203 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
21348 411 2139 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
22437 1355 53914 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
20643 29 506 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
14132 1367 10338 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
20645 34 21034 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
14943 216 11341 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
20647 409 5129 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
22739 794 26418 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
26430 219 11615 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
22748 977 38323 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
24091 1166 49229 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
26131 22 10196 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
25043 220 10635 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
25179 410 61808 XXXXXX prod-server 3rca9sp05ps60 1079697600 JDBC Thin Client ACTIVE SQL*Net message from client
Please Note this query below
Following are the sql_text(2000 chars) for the above sql_id's
--------------------------------------------------------------
SQL_ID SQL_TEXT
------------------ --------------------------------------------------------------------------------
3rca9sp05ps60 select * from ( SELECT JournalArticle.* FROM ( SELECT groupId AS
tempGroupId, articleId AS tempArticleId, MAX(version) AS tempVe
rsion FROM JournalArticle INNER JOIN ( SELECT scope, primKey,
roleId, ownerId FROM ResourcePermission WHERE (ResourcePermissio
n.companyId = 10132) AND (ResourcePermission.name = 'com.liferay
.portlet.journal.model.JournalArticle') AND (ResourcePermission.
scope = 4) AND (MOD(ResourcePermission.actionIds, 2) = 1) AND (R
esourcePermission.roleId IN (10139)) ) InlineSQLResourcePermissi
on ON (((InlineSQLResourcePermission.primKey = CAST(JournalArtic
le.resourcePrimKey AS VARCHAR(4000))) AND (((JournalArticle.grou
pId = 10157))))) WHERE (JournalArticle.companyId = :1 ) AND (g
roupId = :2 ) AND (classNameId = :3 ) AND ( (articleId LIKE :4
OR :5 IS NULL) AND (lower(title) LIKE :6 OR :7 IS NULL) AND
(description LIKE :8 OR :9 IS NULL) AND (content LIKE :10 OR
:11 IS NULL) AND (displayDate >= :12 OR :13 IS NULL) AND (dis
playDate <= :14 OR :15 IS NULL) AND ( (status = :16 ) AND (rev
iewDate <= :17 OR :18 IS NULL) ) ) GROUP BY groupId, articleId
) TEMP_TABLE INNER JOIN JournalArticle ON (TEMP_TABLE.tempGroup
Id = JournalArticle.groupId) AND (TEMP_TABLE.tempArticleId = Jou
rnalArticle.articleId) AND (TEMP_TABLE.tempVersion = JournalArti
cle.version) WHERE (type_ = :19 OR :20 IS NULL) AND (Journal
Article.companyId = :21 ) ORDER BY JournalArticle.modifiedDate D
ESC ) where rownum <= :22
c93hph0596h1n select * from ( SELECT JournalArticle.* FROM ( SELECT groupId AS
tempGroupId, articleId AS tempArticleId, MAX(version) AS tempVe
rsion FROM JournalArticle INNER JOIN ( SELECT scope, primKey,
roleId, ownerId FROM ResourcePermission WHERE (ResourcePermissio
n.companyId = 10132) AND (ResourcePermission.name = 'com.liferay
.portlet.journal.model.JournalArticle') AND (ResourcePermission.
scope = 4) AND (MOD(ResourcePermission.actionIds, 2) = 1) AND (R
esourcePermission.roleId IN (10139)) ) InlineSQLResourcePermissi
on ON (((InlineSQLResourcePermission.primKey = CAST(JournalArtic
le.resourcePrimKey AS VARCHAR(4000))) AND (((JournalArticle.grou
pId = 10157))))) WHERE (JournalArticle.companyId = :1 ) AND (g
roupId = :2 ) AND (classNameId = :3 ) AND ( (articleId LIKE :4
OR :5 IS NULL) AND (lower(title) LIKE :6 OR :7 IS NULL) AND
(description LIKE :8 OR :9 IS NULL) AND (content LIKE :10 OR
:11 IS NULL) AND (displayDate >= :12 OR :13 IS NULL) AND (dis
playDate <= :14 OR :15 IS NULL) AND ( (status = :16 ) AND (rev
iewDate <= :17 OR :18 IS NULL) ) ) GROUP BY groupId, articleId
) TEMP_TABLE INNER JOIN JournalArticle ON (TEMP_TABLE.tempGroup
Id = JournalArticle.groupId) AND (TEMP_TABLE.tempArticleId = Jou
rnalArticle.articleId) AND (TEMP_TABLE.tempVersion = JournalArti
cle.version) WHERE (JournalArticle.companyId = :19 ) ORDER BY
JournalArticle.modifiedDate DESC ) where rownum <= :20
Not sure what this query about ? and surely its not coming from my application . As I tested my production server by removing all the portlets,hooks and theme.
Still saw this issue.
Any help is appreciated .
I had to roll back my changes on PROD server
.Thanks
Shoda Srikanth
Srikanth Reddy:
Note : Why this connection pool issue,when nothing is changed ,except removing external Jars . It works fine when I rollback these external jars i.e remove my Index hook ....
I looked into some of the source and noticed that these queries are fro JournalArticlePersistenceImpl class which in turn is calling custom SQL defined in journal.xml file.
<sql id="com.liferay.portlet.journal.service.persistence.JournalArticleFinder.findByC_G_C_A_V_T_D_C_T_S_T_D_S_R">
SELECT
JournalArticle.*
FROM
(
SELECT
groupId AS tempGroupId, articleId AS tempArticleId, MAX(version) AS tempVersion
FROM
JournalArticle
WHERE
(companyId = ?) AND
(groupId = ?) AND
(classNameId = ?) AND
(
(articleId LIKE ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(version = ?) [$AND_OR_CONNECTOR$]
(lower(title) LIKE ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(description LIKE ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(content LIKE ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(displayDate >= ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(displayDate <= ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(
(status = ?) AND
(reviewDate <= ? [$AND_OR_NULL_CHECK$])
)
)
GROUP BY
groupId, articleId
) TEMP_TABLE
INNER JOIN
JournalArticle ON
(TEMP_TABLE.tempGroupId = JournalArticle.groupId) AND
(TEMP_TABLE.tempArticleId = JournalArticle.articleId) AND
(TEMP_TABLE.tempVersion = JournalArticle.version)
WHERE
(type_ = ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(structureId LIKE ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(templateId LIKE ? [$AND_OR_NULL_CHECK$]) [$AND_OR_CONNECTOR$]
(companyId = ?)
ORDER BY
id_ ASC
</sql>
Now looks like I need to check production jars ,not sure if any of the spring-jars have be causing it ?.
Will test with weekend ,as I wont be able to bring down production on week days or night
Any suggestions what else I can look for ?..
Thanks
Shoda Srikanth
Hi,
As I tried to work on this issue past weekend ,but no luck yet.
But at least I narrowed it down ! Debugging is a challenge .
Case 1:
Even all this I get the same error when I start my server. Not sure what is causing this .Its a plain server with nothing in it expect the DB and some other properties set.
NOTE: ISSUE may be from below list of points.
My DB size (i.e. number of records in my DB is 60K for journal article and so on...),Its a huge.
And My configuration of Data Source (i.e. DB configuration in server.xml) is below .
Something is wrong with my configuration ,which is causing this database connection pool issue ,as shown on the top of this forum.
Can someone good at DB let me know how to debug this issue and find the root cause for it.
What are the things I need to look for ,while address such issue.
Any suggestion or help is appreciated .
Thanks
Srikanth
As I tried to work on this issue past weekend ,but no luck yet
.But at least I narrowed it down ! Debugging is a challenge .
Case 1:
- 1. Removed all the User defined portlets ,hooks,layouts from webapps (removed all components from server).
- 2. Removed all the jars from tomcat/webapps/Web-Inf/lib and replaced them with news jars extracted from new Tomcat bundle 6.1.2 EE .
- 3. Finally also replaced jars from tomcat /lib directory with new set of jars.
Even all this I get the same error when I start my server. Not sure what is causing this .Its a plain server with nothing in it expect the DB and some other properties set.
NOTE: ISSUE may be from below list of points.
My DB size (i.e. number of records in my DB is 60K for journal article and so on...),Its a huge.
And My configuration of Data Source (i.e. DB configuration in server.xml) is below .
Something is wrong with my configuration ,which is causing this database connection pool issue ,as shown on the top of this forum.
But what is surprising is that when I roll back my patch files and all my components it works perfect . With no issues.
<resource name="jdbc/newsdb" auth="Container" type="javax.sql.DataSource" driverClassName="oracle.jdbc.driver.OracleDriver" url="jdbc:oracle:thin:@(DESCRIPTION= (ADDRESS=(PROTOCOL=TCP)(HOST=xxxxxxxxxxxxxxx.com)(PORT=1524)) (CONNECT_DATA=(SERVICE_NAME=xyz)))" validationQuery="SELECT 1 FROM DUAL" connectionProperties="SetBigStringTryClob=true" username="xyz" password="****************" maxActive="20" maxIdle="10" maxWait="5000" maxPoolSize="50" minPoolSize="10" acquireIncrement="5" />
Can someone good at DB let me know how to debug this issue and find the root cause for it.
What are the things I need to look for ,while address such issue.
Any suggestion or help is appreciated .
Thanks
Srikanth
Hi Olaf Kock,
My bad , its tomcat/webapps/ROOT/WEB-INF/lib & 6.1.3 EE to be exact
The reason for all this to occur is
1) This portal was build 5-6 years back when I was not around.
2) There where too many patch files written by previous developer ( 10-15 jars) under tomcat/lib/ext & tomcat/webapps/ROOT/WEB-INF/lib.
These were used for custom Indexing.bookmarks,Imagegallery,Remote publishing etc.... Not sure why so many patch files ,clearly a Bad choice.
3) So when we started working on this Portal ,we build it with 6.0 .X and had to move those patch files along with us as we wanted site to be up and major components were depended on these patch files .We started improving the performance and some more patches were added ,making things more complex and tightly coupled. Once the site was stable ,we wanted to clean up the server and remove these file one by one ,without effecting the server going offline.
4) One & half years back we decided to move to 6.1.x and remove these patch files as much as possible. Migration gave us Hard time ,but we were able to migrate it with minimal patch files ( only 2 ) .We removed most of the patch file and moved to 6.1.X Liferay . Things were very good . The only patch file which were on Server was for Index & Cache. Site work absolutely fine now . But I wanted to get rid of these and start building new things .
And also wanted to move to Liferay 6.2.X or Liferay 7 without any of the patch files & a Clean Liferay bundle .-
Finally we build everything using Hooks and removed the final patch files from our DEV-STAGE servers.Everything was tested on Dev & Stage .
Site worked smoothly without these patch files and gave us good response .We even started our plan for migration .
But when we push these changes to prod ,I came across this issue.
I know the inputs shared here is not be sufficient for anyone to commit or address the issue. The only way one can understand the issue is by understanding our past and present environment .Cant help it
But what I am looking is for any suggestion to debug it and find the root cause . I know once I find the root cause ,I can fix it .
Will be working on it and will be trying different options ..
Thanks
Shoda
My bad , its tomcat/webapps/ROOT/WEB-INF/lib & 6.1.3 EE to be exact
The reason for all this to occur is
1) This portal was build 5-6 years back when I was not around.
2) There where too many patch files written by previous developer ( 10-15 jars) under tomcat/lib/ext & tomcat/webapps/ROOT/WEB-INF/lib.
These were used for custom Indexing.bookmarks,Imagegallery,Remote publishing etc.... Not sure why so many patch files ,clearly a Bad choice.
3) So when we started working on this Portal ,we build it with 6.0 .X and had to move those patch files along with us as we wanted site to be up and major components were depended on these patch files .We started improving the performance and some more patches were added ,making things more complex and tightly coupled. Once the site was stable ,we wanted to clean up the server and remove these file one by one ,without effecting the server going offline.
4) One & half years back we decided to move to 6.1.x and remove these patch files as much as possible. Migration gave us Hard time ,but we were able to migrate it with minimal patch files ( only 2 ) .We removed most of the patch file and moved to 6.1.X Liferay . Things were very good . The only patch file which were on Server was for Index & Cache. Site work absolutely fine now . But I wanted to get rid of these and start building new things .
And also wanted to move to Liferay 6.2.X or Liferay 7 without any of the patch files & a Clean Liferay bundle .-
Finally we build everything using Hooks and removed the final patch files from our DEV-STAGE servers.Everything was tested on Dev & Stage .
Site worked smoothly without these patch files and gave us good response .We even started our plan for migration .
But when we push these changes to prod ,I came across this issue.
I know the inputs shared here is not be sufficient for anyone to commit or address the issue. The only way one can understand the issue is by understanding our past and present environment .Cant help it
But what I am looking is for any suggestion to debug it and find the root cause . I know once I find the root cause ,I can fix it .
Will be working on it and will be trying different options ..
Thanks
Shoda
Olaf Kock:
When you say "patch jars" this sounds like somebody changed Liferay's sourcecode and recompiled?
Yes ! these are patch jars written on top of Liferay's sourcecode and recompiled to work on Liferay.
Olaf Kock:
Unfortunately this is true. And I don't even understand what exactly happens with which custom code, and what you changed - so I don't have an idea where to look at. Remove all custom code, inspect it before adding it back. Test each individual step
Yes ! I am trying to clean the bundle and then add my plugin components one by one. But the movement I remove everything and restart server ,things look fine for some time 3-5 min ,than I get this connection pool issue , without loading any component
Need to understand what is causing this issue. As I removed all the patch files and My custom plugins from the server .All I have is Datasource config in server.xml and portal -ext properties.
Also trying to reach DB team to find the MaxPoolsize & Maxactive values for my DB .
Olaf Kock:
Nope, still not quite exact. If it's 6.1.3, then it's CE.
Its an 6.1 EE ,not sure which minor version .
Thanks
Shoda