I have turned on the org.apache.axis.TIME category in my log4j.properties file to measure the time it takes to run one of my service and I need help to understand/interpret the output sent to the axis.log file. Here is the configuration from my log4j.properties file:
# Set root category priority to INFO and its only appender to CONSOLE. log4j.rootCategory=INFO, CONSOLE log4j.logger.org.apache.axis.TIME=DEBUG, CONSOLE, LOGFILE
# Set the enterprise logger category to FATAL and its only appender to CONSOLE.
log4j.logger.org.apache.axis.enterprise=FATAL, CONSOLE
# CONSOLE is set to be a ConsoleAppender using a PatternLayout. log4j.appender.CONSOLE=org.apache.log4j.ConsoleAppender log4j.appender.CONSOLE.Threshold=INFO log4j.appender.CONSOLE.layout=org.apache.log4j.PatternLayout log4j.appender.CONSOLE.layout.ConversionPattern=- %m%n
# LOGFILE is set to be a File appender using a PatternLayout. log4j.appender.LOGFILE=org.apache.log4j.FileAppender log4j.appender.LOGFILE.File=/usr/local/apache/tomcat/logs/axis.log log4j.appender.LOGFILE.Append=true log4j.appender.LOGFILE.Threshold=DEBUG log4j.appender.LOGFILE.layout=org.apache.log4j.PatternLayout log4j.appender.LOGFILE.layout.ConversionPattern=%-4r [%t] %-5p %c %x - %m%n
And here is the output from the axis.log file:
1371 [Thread-6] DEBUG org.apache.axis.TIME - AxisServer.invoke2 preTr=0 tr=0 preInv
oke=0 invoke=93 postInvoke=0 popdetailservice.getPOPDetails
1375 [Thread-6] DEBUG org.apache.axis.TIME - axisServlet.doPost: "" pre=1 invoke=93
post=3 send=1 popdetailservice.getPOPDetails
963 [main] DEBUG org.apache.axis.TIME - axis.Call.invoke: 206 {popservice}getPOPDet
ails
On the first line, it is showing 93ms, on the seond line, it's 93ms, and on the last line, it's 206ms. What does this mean? Is the total time taken to run my service = 206ms or should I add up the 'invoke time' from the output above: 206+93+93 = 392ms or should I substract 206-93-93 = 20ms?
Could anyone explain this? Thanks a lot for your help.
-David
