Trace and Timer Logging in Log4J
Currently two subsystems have trace and timer logging available to inspect the system performance:
com.trax.system.rules.RuleLibrary
com.trax.ogf.session.CRUDSessionBean
There are two types of logging available:
Trace logging (trace.*)
This log message (%m) will print "BEGIN" at the start of the execution and "END" when processing is complete.
Timer logging (timer.*)
This log message (%m) will print messages in the following structure "A;B;C", where:
A: Type of logged item: RuleSequence, Rule or CRUD
B: Name of logged item
C: duration in milliseconds
The following variables can be used for the log message:
| %x | Nested Diagnostic Context, function call stack with RuleSequence, Rule & CRUD |
|---|---|
| %X{SessionID} | Session ID aka SecurityToken, containing the user & session start or internal for internal processes |
| %X{RuleSequence} | Currently executing RuleSequence (if any) |
| %X{Rule} | Currently executing Rule (if any) |
Table 151 Log Variables
The Template application contains the following setup which should be adjusted or disabled before putting in production as necessary.
<appender name="trace" class="org.apache.log4j.DailyRollingFileAppender">
<errorHandler class="org.apache.log4j.helpers.OnlyOnceErrorHandler"/>
<param name="File" value="trace.log"/>
<param name="Append" value="true"/>
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ISO8601};%t;%x;%m%n"/>
</layout>
</appender>
<logger name="trace.com.trax.system.rules.RuleLibrary" additivity="false"><level value="debug"/>
<logger name="trace.com.trax.ogf.session.CRUDSessionBean" additivity="false"><level value="debug"/><ap-
pender-ref ref="trace"/></logger>
File 151 Trace Log Config
2010-02-16 13:04:05,072;main;(RSeq Server startup);BEGIN
2010-02-16 13:04:07,066;main;(RSeq Server startup) (CRUD FindByUniqueIdentifier);BEGIN
2010-02-16 13:04:07,202;main;(RSeq Server startup) (CRUD FindByUniqueIdentifier);END
2010-02-16 13:04:07,204;main;(RSeq Server startup) (CRUD FindByHQL);BEGIN
2010-02-16 13:04:07,318;main;(RSeq Server startup) (CRUD FindByHQL);END
2010-02-16 13:04:07,320;main;(RSeq Server startup) (CRUD FindByHQL);BEGIN
2010-02-16 13:04:07,485;main;(RSeq Server startup) (CRUD FindByHQL);END
2010-02-16 13:04:07,486;main;(RSeq Server startup) (CRUD FindByUniqueIdentifier);BEGIN
2010-02-16 13:04:07,487;main;(RSeq Server startup) (CRUD FindByUniqueIdentifier);END
2010-02-16 13:04:07,488;main;(RSeq Server startup) (CRUD FindByUniqueIdentifier);BEGIN
2010-02-16 13:04:07,488;main;(RSeq Server startup) (CRUD FindByUniqueIdentifier);END
2010-02-16 13:04:07,489;main;(RSeq Server startup) (Rule PurgeValueObjectsRule);BEGIN
2010-02-16 13:04:08,862;main;(RSeq Server startup) (Rule PurgeValueObjectsRule) (CRUD UpdateHQL);BEGIN
2010-02-16 13:04:09,502;main;(RSeq Server startup) (Rule PurgeValueObjectsRule) (CRUD UpdateHQL);END
2010-02-16 13:04:09,502;main;(RSeq Server startup) (Rule PurgeValueObjectsRule) (CRUD UpdateHQL);BEGIN
2010-02-16 13:04:09,844;main;(RSeq Server startup) (Rule PurgeValueObjectsRule) (CRUD UpdateHQL);END
File 152 Trace Log File
<appender name="timer" class="org.apache.log4j.DailyRollingFileAppender">
<errorHandler class="org.apache.log4j.helpers.OnlyOnceErrorHandler"/>
<param name="File" value="timer.log"/>
<param name="Append" value="true"/>
<param name="DatePattern" value="'.'yyyy-MM-dd"/>
<layout class="org.apache.log4j.PatternLayout">
<param name="ConversionPattern" value="%d{ISO8601};%t;%X{SessionID};%X{RuleSe- quence};%X{Rule};%m%n"/>
</layout>
</appender>
File 153 Timer Log Config
2010-02-16 13:04:10,769;main;internal-2010-02-16T13:04:00;SYS-RecoverCommunications;SetCommunication- StateRule;Rule;SetCommunicationStateRule;120
2010-02-16 13:04:10,771;main;internal-2010-02-16T13:04:00;SYS-RecoverCommunications;;CRUD;FindByU- niqueIdentifier;1
2010-02-16 13:04:10,792;main;internal-2010-02-16T13:04:00;SYS-RecoverCommunications;;CRUD;FindByHQL;20
2010-02-16 13:04:10,811;main;internal-2010-02-16T13:04:00;SYS-RecoverCommunications;;CRUD;FindByHQL;18
2010-02-16 13:04:10,996;main;internal-2010-02-16T13:04:00;SYS-RecoverCommunications;persist;Rule;per- sist;184
2010-02-16 13:04:10,996;main;internal-2010-02-16T13:04:00;SYS-RecoverCommunications;;RuleSequence;SYS- RecoverCommunications;934
2010-02-16 13:04:10,996;main;internal-2010-02-16T13:04:00;Server startup;;Rule;ApplyRuleSequenceRule;1102
2010-02-16 13:04:10,996;main;internal-2010-02-16T13:04:00;Server startup;;RuleSequence;Server startup;5924
File 154 Timer Log File