[
Date Prev][
Date Next][
Thread Prev][
Thread Next][
Date Index][
Thread Index]
[
List Home]
|
RE: [aspectj-users] logging the context of a timing aspect
|
Thanks to everyone who replied -- very helpful to learn about the enclosing
join point information.
As it turns out, I realized that I was actually interested in invoking
methods on the object-being-timed. So, I ended up creating a marker
interface "Timeable." I introduce that interface onto the classes being
timed ("parent" in my example code). My timing aspect then passes that
object into the timer when it's introducing the timer variable onto the
class. In my logging aspect, I have advice that executes after the timer is
stopped which asks the Timer instance for its reference to the Timeable
object. Since the pointcut of the Timer.stop is precise enough to tell me
what the real type of the Timeable instance is, I can perform a runtime cast
(safely, because the pointcuts are precise enough to ensure that the type is
what I think it is) and invoke the required methods to build a logging
message.
What I like about this approach is that the timing and logging aspects are
handled as separate concerns. Further, the logging aspect is abstract, with
concrete instances given responsibility for determining which invocations of
Timer.stop() are interesting to that logging aspect and (based on that
knowledge) for determing how to construct a meaningful logging message from
the recently stopped Timer's instance of Timeable. The result is that I now
have the ability to reuse the timing/logging aspects independently or
together on different aspects of my code base.
So:
abstract public aspect TimerLog {
// the pointcut used to define interesting Timer.stop() concerns
// for the purposes of logging.
protected abstract pointcut methods();
/**
* Create a message to log using the timer
*
* @param t the timer whose stop method was just invoked.
* @return a message to log.
*/
protected abstract String getLogMessage(Timer t);
protected abstract Log getLogger();
after(Timer t): target(t)
&& call(* Timer.stop())
&& methods() {
getLogger().info(getLogMessage(t));
}
}
-----Original Message-----
From: Wes Isberg [mailto:wes@xxxxxxxxxxxxxx]
Sent: Sunday, June 08, 2003 9:12 AM
To: aspectj-users@xxxxxxxxxxx
Subject: 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/pro
gguide/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
>
_______________________________________________
aspectj-users mailing list
aspectj-users@xxxxxxxxxxx
http://dev.eclipse.org/mailman/listinfo/aspectj-users
