From 996ff0ac76084e9cae4155ce1dea63ed4f14774a Mon Sep 17 00:00:00 2001 From: beckerdo Date: Thu, 16 Oct 2008 21:34:06 +0000 Subject: TUSCANY-2641 Enhancements to Tuscany Logging and tracing git-svn-id: http://svn.us.apache.org/repos/asf/tuscany@705368 13f79535-47bb-0310-9956-ffa450edef68 --- .../apache/tuscany/sca/aspectj/LoggingAspect.java | 64 +++++++++++++--------- .../tuscany/sca/aspectj/SimpleTracingAspect.java | 55 ++++++++++--------- .../apache/tuscany/sca/aspectj/TimingAspect.java | 60 ++++++++++++++++++++ .../apache/tuscany/sca/aspectj/TracingAspect.java | 21 ++----- .../src/main/resources/META-INF/aop.xml | 24 +++++--- 5 files changed, 150 insertions(+), 74 deletions(-) create mode 100644 java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TimingAspect.java (limited to 'java/sca/modules') diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java index 8ad64d498b..630bcb285b 100644 --- a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java +++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/LoggingAspect.java @@ -32,6 +32,8 @@ import org.aspectj.lang.annotation.Before; import org.aspectj.lang.annotation.Pointcut; /** + * LoggingAspect performs standard logging of method signatures, arguments, and + * return values. All Tuscany methods, constructors, and statics are logged. * @version $Rev$ $Date$ */ @Aspect @@ -50,44 +52,54 @@ public class LoggingAspect { @Pointcut("cflow(anyMethodExecution()) && anyLogCall()") public void anyLog() { - } - - // @Around("anyMethodCall() || anyLog()") - @Around("anyLog()") - public Object around(ProceedingJoinPoint jp) throws Throwable { - System.out.println("Around: " + jp); - long start = System.currentTimeMillis(); - try { - return jp.proceed(); - } finally { - long end = System.currentTimeMillis(); - System.out.println("Roundtrip is " + (end - start) + "ms for " + jp.getSignature()); - } + @Pointcut("call(org.apache.tuscany.sca..*.new(..))") + public void anyConstructor() { } - @Before("anyMethodCall()") - public void before(JoinPoint jp) { - System.out.println("Before: " + jp); - System.out.println("Location: " + jp.getSourceLocation()); - System.out.println("This: " + jp.getThis()); - System.out.println("Target: " + jp.getTarget()); - System.out.println("Input: " + Arrays.asList(jp.getArgs())); + // e.g. org.apache.tuscany.sca.implementation.java.introspect.impl.JavaIntrospectionHelper + @Pointcut("staticinitialization(org.apache.tuscany.sca.implementation..*)") + public void anyStatic() { } - @After("anyMethodCall()") - public void after(JoinPoint jp) { - System.out.println("After: " + jp); + @Before("anyMethodCall()") + public void before(JoinPoint jp) { + // System.out.println("Logging anyMethodCall before jp=" + jp); + // System.out.println("Logging anyMethodCall before jp.getSourceLocation=" + jp.getSourceLocation()); + // System.out.println("Logging anyMethodCall before jp.getThis=" + jp.getThis()); + // System.out.println("Logging anyMethodCall before jp.getTarget=" + jp.getTarget()); + System.out.println("Logging Before anyMethodCall jp.getSignature=" + jp.getSignature()); + java.lang.Object[] args = jp.getArgs(); + if (( args != null ) && ( args.length > 0 )) { + System.out.println("Logging Before anyMethodCall jp.getArgs=" + Arrays.asList(args)); + } } @AfterReturning(pointcut = "anyMethodCall()", returning = "result") public void afterReturning(JoinPoint jp, Object result) { - System.out.println("After returning: " + jp + " " + result); + // Note that result is null for methods with void return. + System.out.println("Logging AfterReturning anyMethodCall jp=" + jp + ", result=" + result); + } + + @AfterThrowing(pointcut = "anyMethodCall()", throwing = "t") + public void afterThrowing(JoinPoint jp, Throwable t) { + System.out.println("Logging AfterThrowing anyMethodCall jp=" + jp + ", t=" + t); + } + + @Before("anyConstructor()") + public void beforeConstructor(JoinPoint jp) { + System.out.println("Logging Before anyConstructor jp.getSignature=" + jp.getSignature()); + java.lang.Object[] args = jp.getArgs(); + if (( args != null ) && ( args.length > 0 )) { + System.out.println("Logging Before anyConstructor jp.getArgs=" + Arrays.asList(args)); + } } - @AfterThrowing(pointcut = "anyMethodCall()", throwing = "e") - public void afterThrowing(Exception e) { + @Before("anyStatic()") + public void beforeStatic(JoinPoint jp) { + System.out.println("Logging Before anyStatic before jp=" + jp); + System.out.println("Logging anyMethodCall before jp.getSourceLocation=" + jp.getSourceLocation()); } } diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java index d8feefe079..965cfa5b5d 100644 --- a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java +++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/SimpleTracingAspect.java @@ -26,57 +26,62 @@ import org.aspectj.lang.annotation.Aspect; import org.aspectj.lang.annotation.Pointcut; /** + * SimpleTraceAspect performs tracing of method signatures, arguments, and + * return values. All Tuscany methods, constructors, and statics are traced. + * * @version $Rev$ $Date$ */ @Aspect public class SimpleTracingAspect extends TracingAspect { - public SimpleTracingAspect() { - super(); - } - - @Override - protected void completeLog() { - System.out.println("<<< ----------------------------------------------------"); - } - @Pointcut("execution(public * org.apache.tuscany.sca..*.*(..))") + // @Pointcut("call(* org.apache.tuscany.sca..*(..))") protected void entry() { } - @Pointcut("within(org.apache.tuscany.sca..*) && !within(org.apache.tuscany.sca.aspectj.*Aspect)") + @Pointcut("within(org.apache.tuscany.sca..*) && !within(org.apache.tuscany.sca.aspectj..*Aspect)") protected void withinScope() { } @Override - protected void logEnter(JoinPoint jp) { - System.out.println("> " + jp.getSignature()); - if (jp.getArgs().length != 0) { - System.out.println("Input: " + Arrays.asList(jp.getArgs())); - } + protected void startLog() { + System.out.println(">>> ----------------------------------------------------"); } @Override - protected void logExit(JoinPoint jp) { - // System.out.println("> " + jp.getSignature()); + protected void completeLog() { + System.out.println("<<< ----------------------------------------------------"); } @Override - protected void logException(JoinPoint jp, Throwable throwable) { - System.out.println("! " + jp.getSignature() + " " + throwable.getMessage()); + protected void logEnter(JoinPoint jp) { + System.out.println("> logEnter jp.getSignature=" + jp.getSignature()); + java.lang.Object[] args = jp.getArgs(); + if (( args != null ) && ( args.length > 0 )) { + // See http://www.eclipse.org/aspectj/doc/released/progguide/pitfalls-infiniteLoops.html + // System.out.println("Logging anyMethodCall before jp.getArgs=" + Arrays.asList(args)); + System.out.print(" logEnter jp.getArgs(" + args.length + ")=[" ); + for ( int i = 0; i < args.length; i++ ){ + if ( i > 0 ) System.out.print( ","); + System.out.print( args[ i ]); + } + System.out.println("]" ); + } } @Override protected void logExit(JoinPoint jp, Object result) { - System.out.println("< " + jp.getSignature()); - if (!jp.getSignature().toString().startsWith("void ")) { - System.out.println("Output: " + result); - } + // Note that result is null for methods with void return. + System.out.println("< logExit jp.getSignature=" + jp.getSignature() +", result=" + result ); } @Override - protected void startLog() { - System.out.println(">>> ----------------------------------------------------"); + protected void logThrowable(JoinPoint jp, Throwable throwable) { + while ( throwable.getCause() != null ) + throwable = throwable.getCause(); + System.out.println("! logThrowable jp.getSignature=" + jp.getSignature() + ", throwable=" + throwable); + // System.out.println("! logThowable stackTrace=" ); + // throwable.printStackTrace( System.out ); } } diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TimingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TimingAspect.java new file mode 100644 index 0000000000..262742e867 --- /dev/null +++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TimingAspect.java @@ -0,0 +1,60 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, + * software distributed under the License is distributed on an + * "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY + * KIND, either express or implied. See the License for the + * specific language governing permissions and limitations + * under the License. + */ + +package org.apache.tuscany.sca.aspectj; + +import java.util.Arrays; + +import org.aspectj.lang.JoinPoint; +import org.aspectj.lang.ProceedingJoinPoint; +import org.aspectj.lang.annotation.After; +import org.aspectj.lang.annotation.AfterReturning; +import org.aspectj.lang.annotation.AfterThrowing; +import org.aspectj.lang.annotation.Around; +import org.aspectj.lang.annotation.Aspect; +import org.aspectj.lang.annotation.Before; +import org.aspectj.lang.annotation.Pointcut; + +/** + * The TimingAspect is used to perform timing metrics on various calls. + * The Pointcut "timedCall" is not defined here, but rather in the aop.xml + * configuration file. You may provide a point cut to state which type + * of call you would like timed and reported in the output files. + * + * @version $Rev$ $Date$ + */ +@Aspect +public abstract class TimingAspect { + // Abstract pointcut. Pointcut is defined in aop.xml file. + @Pointcut + public void timedCall() { + } + + @Around("timedCall()") + public Object timedSection(ProceedingJoinPoint jp) throws Throwable { + System.out.println("Timing Around timedSection jp=" + jp); + long start = System.currentTimeMillis(); + try { + return jp.proceed(); + } finally { + long end = System.currentTimeMillis(); + System.out.println("Timing Around timedSection Roundtrip is " + (end - start) + "ms for jp.getSignature=" + jp.getSignature()); + } + } +} diff --git a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java index ae3f8f93d5..0178ebdb6e 100644 --- a/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java +++ b/java/sca/modules/tracing-aspectj/src/main/java/org/apache/tuscany/sca/aspectj/TracingAspect.java @@ -37,7 +37,6 @@ public abstract class TracingAspect { @Pointcut("") protected abstract void entry(); - /** ignore join points outside this scope - use within(..) */ @Pointcut("") protected abstract void withinScope(); @@ -49,8 +48,9 @@ public abstract class TracingAspect { void start() { } - // @Pointcut("withinScope() && cflow(entry()) && !cflow(exit()) && !within(org.apache.tuscany.sca.aspectj.*Aspect)") - @Pointcut("withinScope() && entry() && !within(org.apache.tuscany.sca.aspectj.*Aspect)") + // @Pointcut("withinScope() && cflow(entry()) && !cflow(exit()) && !within(org.apache.tuscany.sca.aspectj.*Aspect) && !within(*.toString)") + @Pointcut("withinScope() && entry()") + // @Pointcut("withinScope() && entry()&& !cflow(execution(String toString())") void trace() { } @@ -67,12 +67,7 @@ public abstract class TracingAspect { public void beforeTrace(JoinPoint jp) { logEnter(jp); } - - @After("trace() && supportsAfterAdvice()") - public void afterTrace(JoinPoint jp) { - logExit(jp); - } - + @AfterReturning(pointcut = "trace() && supportsAfterAdvice()", returning = "result") public void afterReturning(JoinPoint jp, Object result) { logExit(jp, result); @@ -80,7 +75,7 @@ public abstract class TracingAspect { @AfterThrowing(pointcut = "trace() && supportsAfterAdvice()", throwing = "e") public void afterThrowing(JoinPoint jp, Throwable e) { - logException(jp, e); + logThrowable(jp, e); } @After("start()") @@ -89,13 +84,9 @@ public abstract class TracingAspect { } protected abstract void logEnter(JoinPoint jp); - - protected abstract void logExit(JoinPoint jp); protected abstract void logExit(JoinPoint jp, Object result); - protected abstract void logException(JoinPoint jp, Throwable throwable); + protected abstract void logThrowable(JoinPoint jp, Throwable throwable); protected abstract void startLog(); - protected abstract void completeLog(); - } diff --git a/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml b/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml index 60c0132e9a..f699a140e3 100644 --- a/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml +++ b/java/sca/modules/tracing-aspectj/src/main/resources/META-INF/aop.xml @@ -1,16 +1,24 @@ - - - - + + + + + + + + + + + - + - + -- cgit v1.2.3