Hide Forgot
Date of First Response: 2009-01-08 11:09:39 project_key: SOA The OOTB log4j configuration of the standalone server/default profile results in > 300K messages per hour on an idle server. The majority of these (DEBUG level) messages - see sample below - are generated by hibernate + jBPM. The large number of these messages can make it difficult to find specific log messages. Also - on an idle server - the log grows by ~15 MB per hour. The logging categories listed below might be a better default for this server. CP01 - standalone server - after one hour Total # of lines in server.log: 300919 (15MB) # of lines from hibernate.org: 234846 # of lines from jbpm.org: 36930 After adding this to server/default/conf/jboss-log4j.xml <category name="org.hibernate"> <priority value="INFO"/> </category> <category name="org.jbpm"> <priority value="INFO"/> </category> After one hour: Total # of lines in server.log: 22315 (3MB file) ====================== This pattern is repeated every 5 seconds: 2008-04-29 21:45:03,533 DEBUG [org.jbpm.job.executor.JobExecutorThread] acquiring jobs for execution... 2008-04-29 21:45:03,533 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2008-04-29 21:45:03,533 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@152a84b 2008-04-29 21:45:03,534 DEBUG [org.jbpm.JbpmContext] start user JTA transaction 2008-04-29 21:45:03,545 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization 2008-04-29 21:45:03,545 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4954193524920320 2008-04-29 21:45:03,545 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2008-04-29 21:45:03,545 DEBUG [org.jbpm.job.executor.JobExecutorThread] querying for acquirable job... 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2008-04-29 21:45:03,546 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_22_, job0_.VERSION_ as VERSION3_22_, job0_.DUEDATE_ as DUEDATE4_22_, job0_.PROCESSINSTANCE_ as PROCESSI5_22_, job0_.TOKEN_ as TOKEN6_22_, job0_.TASKINSTANCE_ as TASKINST7_22_, job0_.ISSUSPENDED_ as ISSUSPEN8_22_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_22_, job0_.LOCKOWNER_ as LOCKOWNER10_22_, job0_.LOCKTIME_ as LOCKTIME11_22_, job0_.EXCEPTION_ as EXCEPTION12_22_, job0_.RETRIES_ as RETRIES13_22_, job0_.NAME_ as NAME14_22_, job0_.REPEAT_ as REPEAT15_22_, job0_.TRANSITIONNAME_ as TRANSIT16_22_, job0_.ACTION_ as ACTION17_22_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_22_, job0_.GRAPHELEMENT_ as GRAPHEL19_22_, job0_.NODE_ as NODE20_22_, job0_.CLASS_ as CLASS2_22_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.DUEDATE_<=? and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2008-04-29 21:45:03,546 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2008-04-29 21:45:03,546 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-04-29 21:45:03,546 DEBUG [org.jbpm.job.executor.JobExecutorThread] no acquirable jobs in job table 2008-04-29 21:45:03,546 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@152a84b 2008-04-29 21:45:03,546 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@122b302 2008-04-29 21:45:03,546 DEBUG [org.jbpm.JbpmContext] end user JTA transaction 2008-04-29 21:45:03,559 DEBUG [org.jbpm.JbpmContext] end jta transation with COMMIT 2008-04-29 21:45:03,559 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@815832 2008-04-29 21:45:03,559 DEBUG [org.jbpm.job.executor.JobExecutorThread] obtained locks on following jobs: [] 2008-04-29 21:45:03,559 DEBUG [org.jbpm.configuration.JbpmContextInfo] creating jbpm context with service factories '[tx, message, scheduler, logging, persistence, authentication]' 2008-04-29 21:45:03,559 DEBUG [org.jbpm.JbpmContext] creating org.jbpm.JbpmContext@1c5472f 2008-04-29 21:45:03,559 DEBUG [org.jbpm.JbpmContext] start user JTA transaction 2008-04-29 21:45:03,576 DEBUG [org.hibernate.jdbc.JDBCContext] successfully registered Synchronization 2008-04-29 21:45:03,576 DEBUG [org.hibernate.impl.SessionImpl] opened session at timestamp: 4954193525047296 2008-04-29 21:45:03,576 DEBUG [org.jbpm.persistence.db.DbPersistenceService] using current hibernate session SessionImpl(PersistenceContext[entityKeys=[],collectionKeys=[]];ActionQueue[insertions=[] updates=[] deletions=[] collectionCreations=[] collectionRemovals=[] collectionUpdates=[]]) 2008-04-29 21:45:03,576 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open PreparedStatement (open PreparedStatements: 0, globally: 0) 2008-04-29 21:45:03,576 DEBUG [org.hibernate.jdbc.ConnectionManager] opening JDBC connection 2008-04-29 21:45:03,577 DEBUG [org.hibernate.SQL] select top ? job0_.ID_ as ID1_22_, job0_.VERSION_ as VERSION3_22_, job0_.DUEDATE_ as DUEDATE4_22_, job0_.PROCESSINSTANCE_ as PROCESSI5_22_, job0_.TOKEN_ as TOKEN6_22_, job0_.TASKINSTANCE_ as TASKINST7_22_, job0_.ISSUSPENDED_ as ISSUSPEN8_22_, job0_.ISEXCLUSIVE_ as ISEXCLUS9_22_, job0_.LOCKOWNER_ as LOCKOWNER10_22_, job0_.LOCKTIME_ as LOCKTIME11_22_, job0_.EXCEPTION_ as EXCEPTION12_22_, job0_.RETRIES_ as RETRIES13_22_, job0_.NAME_ as NAME14_22_, job0_.REPEAT_ as REPEAT15_22_, job0_.TRANSITIONNAME_ as TRANSIT16_22_, job0_.ACTION_ as ACTION17_22_, job0_.GRAPHELEMENTTYPE_ as GRAPHEL18_22_, job0_.GRAPHELEMENT_ as GRAPHEL19_22_, job0_.NODE_ as NODE20_22_, job0_.CLASS_ as CLASS2_22_ from JBPM_JOB job0_ where (job0_.LOCKOWNER_ is null or job0_.LOCKOWNER_=?) and job0_.RETRIES_>0 and job0_.ISSUSPENDED_<>1 order by job0_.DUEDATE_ asc 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to open ResultSet (open ResultSets: 0, globally: 0) 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close ResultSet (open ResultSets: 1, globally: 1) 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.AbstractBatcher] about to close PreparedStatement (open PreparedStatements: 1, globally: 1) 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.ConnectionManager] aggressively releasing JDBC connection 2008-04-29 21:45:03,577 DEBUG [org.hibernate.jdbc.ConnectionManager] releasing JDBC connection [ (open PreparedStatements: 0, globally: 0) (open ResultSets: 0, globally: 0)] 2008-04-29 21:45:03,577 DEBUG [org.hibernate.engine.StatefulPersistenceContext] initializing non-lazy collections 2008-04-29 21:45:03,577 DEBUG [org.jbpm.JbpmContext] closing jbpmContext org.jbpm.JbpmContext@1c5472f 2008-04-29 21:45:03,577 DEBUG [org.jbpm.svc.Services] closing service 'persistence': org.jbpm.persistence.jta.JtaDbPersistenceService@1cc042f 2008-04-29 21:45:03,577 DEBUG [org.jbpm.JbpmContext] end user JTA transaction 2008-04-29 21:45:03,579 DEBUG [org.jbpm.JbpmContext] end jta transation with COMMIT 2008-04-29 21:45:03,579 DEBUG [org.jbpm.svc.Services] closing service 'tx': org.jbpm.tx.TxService@dbe4e5
Link: Added: This issue is related to SOA-222
Need to apply similar changes to revision 1458 of: build-tools/resource/conf-skeleton/ build-tools/builders/eap/build.xml build-tools/builders/esb/build.xml for the EAP CP03 log4j configuration.
Changes also added to 4.2.0 branch in revision 2464 of: builders/eap/build.xml builders/esb/build.xml resource/conf-skeleton/jboss-log4j.xml (deleted) resource/conf-skeleton/jboss-log4j-default.xml (added) resource/conf-skeleton/jboss-log4j-production.xml (added) (this will be in the next CR build of 4.2.0 CP03).
Fix verified in SOA-P 4.2 CP03 CR7: server/default/conf/jboss-log4j.xml now contains: <!-- Limit hibernate Logging --> <category name="org.hibernate"> <priority value="INFO" /> </category> <!-- Limit jBPM Logging --> <category name="org.jbpm"> <priority value="INFO"/> </category>