lilith Wiki
Brought to you by:
huxhorn
Menu
▾
▴
TracingAspect
Tracing and Profiling using SLF4J and aspects
Starting with 0.9.39, Lilith contains a module that supports tracing and profiling of applications using Spring AOP.
You can take a look at the implementation in case you are wondering or simply jump ahead to the example output.
Wrapping all implementations of an interface
An example applicationContext.xml looks like this:
<?xml version="1.0" encoding="UTF-8"?>
<beans xmlns="http://www.springframework.org/schema/beans"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xmlns:aop="http://www.springframework.org/schema/aop"
xsi:schemaLocation="
http://www.springframework.org/schema/beans http://www.springframework.org/schema/beans/spring-beans-3.0.xsd
http://www.springframework.org/schema/aop http://www.springframework.org/schema/aop/spring-aop-3.0.xsd">
<bean id="tracingAspect" class="de.huxhorn.lilith.tracing.TracingAspect">
<!--
The SLF4J-Logger used to log the tracing/profiling messages.
"de.huxhorn.lilith.tracing.TracingAspect" is used if unspecified.
-->
<property name="loggerName" value="DefaultTracing"/>
</bean>
<!-- ExampleService is an actual implementation of the ExampleServiceIfc interface -->
<bean id="exampleService" class="de.huxhorn.lilith.tracing.ExampleService">
<property name="other">
<bean class="de.huxhorn.lilith.tracing.Other"/>
</property>
</bean>
<aop:config>
<aop:aspect ref="tracingAspect">
<!--
Wrap all method-calls of all ExampleServiceIfc implementations with the
trace-aspect, i.e. enable tracing.
-->
<aop:pointcut id="testServicePointcut"
expression="execution(* de.huxhorn.lilith.tracing.ExampleServiceIfc.*(..))"/>
<aop:around pointcut-ref="testServicePointcut" method="trace"/>
<!--
Wrap all method-calls of all OtherIfc implementations with the
trace-aspect, i.e. enable tracing.
-->
<aop:pointcut id="testOtherPointcut"
expression="execution(* de.huxhorn.lilith.tracing.OtherIfc.*(..))"/>
<aop:around pointcut-ref="testOtherPointcut" method="trace"/>
</aop:aspect>
</aop:config>
</beans>
Required dependencies
<dependencies>
<dependency>
<groupId>de.huxhorn.lilith</groupId>
<artifactId>de.huxhorn.lilith.tracing</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-context</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-aop</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.aspectj</groupId>
<artifactId>aspectjweaver</artifactId>
<scope>runtime</scope>
</dependency>
</dependencies>
Wrapping a specific class instead of an interface
It's also possible to specify a class instead of an interface in the above <aop:pointcut> expression. This, however, requires the optional CGLIB dependency in the classpath.
Required dependencies
<dependencies>
<dependency>
<groupId>de.huxhorn.lilith</groupId>
<artifactId>de.huxhorn.lilith.tracing</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-context</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.springframework</groupId>
<artifactId>spring-aop</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>org.aspectj</groupId>
<artifactId>aspectjweaver</artifactId>
<scope>runtime</scope>
</dependency>
<dependency>
<groupId>cglib</groupId>
<artifactId>cglib-nodep</artifactId>
<scope>runtime</scope>
</dependency>
</dependencies>
Example-Output
An example using the following appender definition
<appender name="CONSOLE" class="ch.qos.logback.core.ConsoleAppender">
<encoder>
<pattern>%-8marker - %d{HH:mm:ss.SSS} [%thread] - %logger - %msg%n%ex{short}</pattern>
</encoder>
</appender>
looks like this:
ENTRY - 12:41:21.232 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgs() entered.
- 12:41:21.232 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing noArgs
PROFILE - 12:41:21.232 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgs() took 163000ns.
EXIT - 12:41:21.232 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgs() returned.
ENTRY - 12:41:21.233 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsResult() entered.
- 12:41:21.233 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing noArgsResult
PROFILE - 12:41:21.233 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsResult() took 109000ns.
EXIT - 12:41:21.233 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsResult() returned noArgsResult.
ENTRY - 12:41:21.235 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArg(single) entered.
- 12:41:21.235 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing singleArg with single
PROFILE - 12:41:21.235 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArg(single) took 124000ns.
EXIT - 12:41:21.235 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArg(single) returned.
ENTRY - 12:41:21.236 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResult(single) entered.
- 12:41:21.236 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing singleArgResult with single
PROFILE - 12:41:21.236 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResult(single) took 107000ns.
EXIT - 12:41:21.236 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResult(single) returned singleArgResult single.
ENTRY - 12:41:21.236 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResultTakingTime(single) entered.
- 12:41:21.236 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing singleArgResultTakingTime with single
PROFILE - 12:41:23.236 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResultTakingTime(single) took 2000130000ns.
EXIT - 12:41:23.237 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResultTakingTime(single) returned singleArgResultTakingTime single.
ENTRY - 12:41:23.237 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.args(first, second) entered.
- 12:41:23.238 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing args with first and second
PROFILE - 12:41:23.238 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.args(first, second) took 132000ns.
EXIT - 12:41:23.238 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.args(first, second) returned.
ENTRY - 12:41:23.238 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsWithVarargs(first, second, [third, fourth]) entered.
- 12:41:23.238 [main] - de.huxhorn.lilith.tracing.ExampleService - Foo third
- 12:41:23.239 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing argsWithVarargs with first, second & [third, fourth]
PROFILE - 12:41:23.239 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsWithVarargs(first, second, [third, fourth]) took 268000ns.
EXIT - 12:41:23.239 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsWithVarargs(first, second, [third, fourth]) returned.
ENTRY - 12:41:23.239 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsResult(first, second) entered.
- 12:41:23.239 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing argsResult with first and second
PROFILE - 12:41:23.239 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsResult(first, second) took 107000ns.
EXIT - 12:41:23.239 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsResult(first, second) returned argsResult[arg1=first, arg2=second].
ENTRY - 12:41:23.240 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.methodCallingPrivateMethod() entered.
- 12:41:23.240 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing methodCallingPrivateMethod
- 12:41:23.240 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing privateMethod
PROFILE - 12:41:23.240 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.methodCallingPrivateMethod() took 185000ns.
EXIT - 12:41:23.240 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.methodCallingPrivateMethod() returned privateMethod.
ENTRY - 12:41:23.241 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.callingOther() entered.
- 12:41:23.241 [main] - de.huxhorn.lilith.tracing.ExampleService - Executing callingOther
ENTRY - 12:41:23.241 [main] - DefaultTracing - de.huxhorn.lilith.tracing.OtherIfc.someMethod() entered.
- 12:41:23.241 [main] - de.huxhorn.lilith.tracing.Other - Executing someMethod
PROFILE - 12:41:23.241 [main] - DefaultTracing - de.huxhorn.lilith.tracing.OtherIfc.someMethod() took 95000ns.
EXIT - 12:41:23.241 [main] - DefaultTracing - de.huxhorn.lilith.tracing.OtherIfc.someMethod() returned someMethod.
PROFILE - 12:41:23.241 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.callingOther() took 536000ns.
EXIT - 12:41:23.242 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.callingOther() returned someMethod.
ENTRY - 12:41:23.242 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsThrows() entered.
PROFILE - 12:41:23.242 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsThrows() took 70000ns.
THROWING - 12:41:23.248 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsThrows() failed.
java.lang.RuntimeException: Executing noArgsThrows
at de.huxhorn.lilith.tracing.ExampleService.noArgsThrows(ExampleService.java:123)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
ENTRY - 12:41:23.249 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsResultThrows() entered.
PROFILE - 12:41:23.249 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsResultThrows() took 29000ns.
THROWING - 12:41:23.250 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.noArgsResultThrows() failed.
java.lang.RuntimeException: Executing noArgsThrows
at de.huxhorn.lilith.tracing.ExampleService.noArgsResultThrows(ExampleService.java:128)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
ENTRY - 12:41:23.251 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgThrows(single) entered.
PROFILE - 12:41:23.251 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgThrows(single) took 30000ns.
THROWING - 12:41:23.252 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgThrows(single) failed.
java.lang.RuntimeException: Executing singleArgThrows with single
at de.huxhorn.lilith.tracing.ExampleService.singleArgThrows(ExampleService.java:133)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
ENTRY - 12:41:23.252 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResultThrows(single) entered.
PROFILE - 12:41:23.253 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResultThrows(single) took 29000ns.
THROWING - 12:41:23.254 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.singleArgResultThrows(single) failed.
java.lang.RuntimeException: Executing singleArgResultThrows with single
at de.huxhorn.lilith.tracing.ExampleService.singleArgResultThrows(ExampleService.java:138)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
ENTRY - 12:41:23.255 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsThrows(first, second) entered.
PROFILE - 12:41:23.255 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsThrows(first, second) took 33000ns.
THROWING - 12:41:23.256 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsThrows(first, second) failed.
java.lang.RuntimeException: Executing argsThrows with first and second
at de.huxhorn.lilith.tracing.ExampleService.argsThrows(ExampleService.java:143)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
ENTRY - 12:41:23.257 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsResultThrows(first, second) entered.
PROFILE - 12:41:23.257 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsResultThrows(first, second) took 30000ns.
THROWING - 12:41:23.258 [main] - DefaultTracing - de.huxhorn.lilith.tracing.ExampleServiceIfc.argsResultThrows(first, second) failed.
java.lang.RuntimeException: Executing argsResultThrows with first and second
at de.huxhorn.lilith.tracing.ExampleService.argsResultThrows(ExampleService.java:148)
at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
