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
|
| 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>