| Summary: | SOA Platform, standalone server, default configuration - log4j configuration = 300,000 log messages/hour on idle server | ||
|---|---|---|---|
| Product: | [JBoss] JBoss Enterprise SOA Platform 4 | Reporter: | Julian Coleman <jcoleman> |
| Component: | Configuration, Standalone Server | Assignee: | Julian Coleman <jcoleman> |
| Status: | CLOSED NEXTRELEASE | QA Contact: | |
| Severity: | high | Docs Contact: | |
| Priority: | high | ||
| Version: | 4.2 CP01 | ||
| Target Milestone: | --- | ||
| Target Release: | 4.2 CP03 | ||
| Hardware: | Unspecified | ||
| OS: | Unspecified | ||
| URL: | http://jira.jboss.org/jira/browse/SOA-1073 | ||
| Whiteboard: | |||
| Fixed In Version: | Doc Type: | Bug Fix | |
| Doc Text: | Story Points: | --- | |
| Clone Of: | Environment: | ||
| Last Closed: | 2009-01-08 16:09:39 UTC | Type: | Bug |
| Regression: | --- | Mount Type: | --- |
| Documentation: | --- | CRM: | |
| Verified Versions: | Category: | --- | |
| oVirt Team: | --- | RHEL 7.3 requirements from Atomic Host: | |
| Cloudforms Team: | --- | Target Upstream Version: | |
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>
|
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