Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
[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


Back to the top