Skip to main content
[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [aspectj-users] logging the context of a timing aspect 
To unpack and add to Ron's answer a bit, Eric asked:

>> // would like a way to log information about the method
>>    in the Parent class hierarchy that precipitated
>> // execution of this advice

The advice runs at join points picked out by

>>    pointcut sendMessage(Parent p) :
>>        target(p) && call (* send(..));

Ron said

> You can use thisEnclosingJoinPoint - to do what you want.

The "enclosing" join point of a call join point is,
e.g., the method body containing the call.  e.g., for

   public class Kid extends Parent {
     protected void doWork() { // defined & called by Parent?
       send("Hello, World!");
     }
     private Object[] send(String s) { ... }
   }

in the body of the advice, thisJoinPointStaticPart
would identify the name of the method called:

     private Object[] send(String s)

while thisEnclosingJoinPoint in this case identifies
the method containing the call:

     protected void doWork()

Eric could have been asking about either, but I'd
guess with Ron that he was asking about doWork().

btw, you can time in one around advice:

   Object around() : somePointcut() {
      long start = System.currentTimeMillis();
      try {
        return proceed();
      } finally {
        long end = System.currentTimeMillis();
        logTime(thisJoinPointStaticPart, start, end);
      }
   }

Declaring a timer on Parent assumes the flow of control is
only within/below only one join point at the same time for
a particular instance.

By contast, putting the timer on the stack (in around advice)
makes it thread-safe and permits the same instance to be
targeted for timing by multiple pointcuts.*

Wes

* - So to uniquely identify a call for logging also requires
the thread (ok, and the jvm, the machine...):

 void logTime(JoinPoint.StaticPart jp, long start, long end) {
    Thread thread = Thread.currentThread();
    String m = thread + " - " + jp
               + "[" + start + ", " + end + "]";
    System.out.println(m);
 }

Ron Bodkin wrote:


Eric,
You can use thisEnclosingJoinPoint - to do what you want. E.g., System.err.println("Called by " + thisEnclosingJoinPoint.getSignature()); 

See http://dev.eclipse.org/viewcvs/indextech.cgi/~checkout~/aspectj-home/doc/progguide/apbs03.html  for more information...



------------Original Message-------------
From: Eric.D.Friedman@xxxxxxxxxxxxxx
To: aspectj-users@xxxxxxxxxxx
Date: Thu, Jun-5-2003 10:55 AM
Subject: [aspectj-users] logging the context of a timing aspect

I'm attempting to use a variation on one of the sample aspects and am
unclear as to how to capture some additional information in a logging
operation.  I'd be grateful for any insights you can offer.

I have a family of classes, all of which extend the same base class.  To
keep it simple, let's call the base class "Parent" and the subclasses
"Child" and "Kid."

My goal is to introduce an aspect onto this family that will start/stop a
timer when a certain method is invoked.  That method is not defined on
Parent, but it's defined on Child/Kid -- the return type and arguments are
different in each case, though the name is the same.  So:

class Parent {}
class Child extends Parent {
 private ChildResponse send(ChildRequest req) { .. }
}
class Kid extends Parent {
 private KidResponse send(KidRequest req) { .. }
}

I have a Timer class, borrowed from the examples:
class Timer {
 private long start, stop;
 public void start() { start = System.currentTimeMillis(); }
 public void stop() { stop = System.currentTimeMillis(); }
 public long getTime() { return stop - start; }
}


I have an aspect which introduces a Timer instance onto Parent and which
uses before/after advice to start/stop the timer when * send(..) is invoked:

public aspect Timing {
   pointcut sendMessage(Parent p) :
       target(p) && call (* send(..));

   private Timer Parent.timer = new Timer();
   public Timer getTimer(Parent p) { return p.timer; }

   before(Parent p): sendMessage(p) {
     getTimer(p).start();
   }

   after(Parent p): sendMessage(p) {
     getTimer(p).stop();
   }
}

I have a second aspect which implements support for the logging concern:

public aspect TimerLog {
after(Timer t): target(t) && call(* Timer.stop()) && cflow(call(* Parent+.*(..))) { 
     System.err.println("Elapsed time: " + t.getTime() + " ms");
     System.err.println("In " + thisJoinPoint.toLongString());
     // would like a way to log information about the method in the Parent
class hierarchy that precipitated
     // execution of this advice
   }
}

This all works very well.  However, there doesn't appear to be a way for the
TimerLog aspect to report *what* the timer was logging.  The after advice of
the TimerLog has visibility on the Timer object, but not on the context in
which the matching cut occurred.  The cflow() pointcut helps to ensure that
I only log "interesting" Timing events, but it does not (AFAICT) expose the
method in the cflow stack in which the TimerLog advice is being executed.

Obviously I could add state to the Timer object and make the Timing aspect
responsible for setting that, though it seems I would be blurring the
boundary between the timing concern and the logging concern in the process.

Does anyone have any insight into how "best" to accomplish what I'm after?

Thanks,
Eric Friedman
_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
http://dev.eclipse.org/mailman/listinfo/aspectj-users



_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
http://dev.eclipse.org/mailman/listinfo/aspectj-users

Back to the top