Overview

The service solves a simple problem - how to monitor the execution time of service invocations in a production environment. It allows to monitor a a user-defined list of services and tresholds which affects the trace level of the logger being used to write the performance data.

Captured Information

During the execution the service captures the following information for producing a meaning log

Item Description
Transaction ID (TID) the number of times the invocationDepth was zero
Invocation ID (IID) the current number of inovking a service method
InvocationDepth (ID) the service invocation depth, e.g a value of "1" that the currently invoked service method was invoked by another service. A value of "0" indicates that the service method was directly invoked from the caller therefore starting a new transaction
Mode (M) the invocation mode of the interceptor
  • 0 ==> entering the service method
  • 1 ==> leaving the the service method
  • 2 ==> an exception occured
ServiceName the shorthand of the service being invoked
ServiceMethod the name of the service method being invoked
Millis the execution time in milliseconds
Method Signature the name of the executing thread

Example Logfile

Looking at the following example you see that
  • that this was the 18th transaction during the lifetime of the container
  • the transaction spanned eight Avalon service invocations
  • SignatureService.sign is the top-level service invocation taking 140 ms
  • PdfSignatureService.isSupported is invoked by SignatureService.sign hence the invocation depth of "1"
  • PdfSignatureService.sign is also invoked by SignatureService.sign and took 140 ms
  • PdfSignatureService.sign invokes five other Avalon service methods to do its work
        
TID IID ID M ServiceName             ServiceMethod        Millis
18  28  0  1 SignatureService        sign                 140
18  29  1  1 PdfSignatureService     isSupported          0
18  30  1  1 PdfSignatureService     sign                 140
18  31  2  1 CommandDispatcher       exists               0
18  32  2  1 ResourceManagerService  exists               0
18  33  2  1 ResourceManagerService  exists               0
18  34  2  1 ResourceManagerService  read                 0
18  35  2  1 PKCS12KeyStore          getCertificateEntry  0

Configuration

Component Configuration

Item Datatype Cardinality Description
isEnabled Boolean [0|1] Turn the interceptor. If no value is supplied then "false" is used thereby disabling all interceptor invocations.
tresholds Tree [0|1] Contains a list of mappings from execution time to tracelevel
tresholds/debug Integer [0|1] The minimum exeuction time for debug output
tresholds/info Integer [0|1] The minimum exeuction time for info output
tresholds/warn Integer [0|1] The minimum exeuction time for warn output
tresholds/error Integer [0|1] The minimum exeuction time for error output
tresholds/fatal Integer [0|1] The minimum exeuction time for fatal output
services Tree [0|1] Contains a list of services to be monitored.
services/service@name String [1..n] The name of an individual service to be monitored.

Role Configuration

<role
  name="org.apache.fulcrum.yaafi.interceptor.performance.PerformanceInterceptorService"
  shorthand="PerformanceInterceptorService"
  default-class="org.apache.fulcrum.yaafi.interceptor.performance.PerformanceInterceptorServiceImpl"
  logger="performance"
/>

Log4J Configuration

The following Log4J configuration defines a custom appender for the PerformanceInterceptorService. For the layout we just add a timestamp since we produce a CSV file to be analyzed with EXCEL or your tool of choice 
#
# Custom logfiles
#

log4j.category.yaafi.performance = DEBUG, performance
log4j.additivity.yaafi.performance = false

#
# Performance Appender
#

log4j.appender.performance = org.apache.log4j.FileAppender
log4j.appender.performance.file = ./temp/performance.csv
log4j.appender.performance.layout = org.apache.log4j.PatternLayout
log4j.appender.performance.layout.conversionPattern = %d;%m%n
log4j.appender.performance.append = true

Usage

Monitor all exection times 
        
<PerformanceInterceptorService>
  <isEnabled>true</isEnabled>
  <tresholds>
    <debug millis="0"/>
    <info  millis="100"/>
    <warn  millis="500"/>
    <error millis="1000"/>
    <fatal millis="5000"/>
  </tresholds>
  <services>
    <service name="*"/>
  </services>
</PerformanceInterceptorService>