eclipse-aspectj / aspectj

Other
290 stars 84 forks source link

LTW verbose to print summary #142

Open abelom opened 2 years ago

abelom commented 2 years ago

We are using LTW on a large codebase and even with verbose output we get about two minutes of silence on start-up between last aspectj info message and start of our user space output

It would be nice for AspectJ agent to print some message with timestamp at the end of LTW. Maybe total number of classes weaved and total time spend?

aclement commented 2 years ago

at the end of LTW

It is hard to know the end of LTW as we don't know when you have finished loading classes.

But there is something you can use that periodically can print matching info: http://andrewclement.blogspot.com/2009/11/aspectj-profiling-pointcut-matching.html

It doesn't quite print number of classes but does present time spent matching point cuts against join points - messages could be extended with types woven in addition to join point match counts.

I haven't used it in a long time but I don't see why it wouldn't still be working.

abelom commented 2 years ago

It is hard to know the end of LTW as we don't know when you have finished loading classes.

Can I access stats from user code? org.aspectj.Stats.getTotalCount() org.aspectj.Stats.getTotalTime() ?

kriegaex commented 2 years ago

I do not know those AJC options or the code dealing with them, but actually the question is interesting enough to look into it. You cannot easily access the stats, because they are stored in the private static inner class org.aspectj.weaver.World.TimeCollector.

Right above that inner class, you see two public methods recording the stats: https://github.com/eclipse/org.aspectj/blob/5abc2f1dce1e97b92acc5562b3c5fa32cf0abb5d/org.aspectj.matcher/src/main/java/org/aspectj/weaver/World.java#L1868-L1881

In method TimeCollector.report(), you can see that the stats are logged into a message handler: https://github.com/eclipse/org.aspectj/blob/5abc2f1dce1e97b92acc5562b3c5fa32cf0abb5d/org.aspectj.matcher/src/main/java/org/aspectj/weaver/World.java#L1904-L1918

For the message handler, there are public getter and setter methods in World: https://github.com/eclipse/org.aspectj/blob/5abc2f1dce1e97b92acc5562b3c5fa32cf0abb5d/org.aspectj.matcher/src/main/java/org/aspectj/weaver/World.java#L714-L724

So, assuming that you can get hold of a World instance, it would in theory be possible to register your own message handler, parse the text messages and create your own stats, doing whatever you please with them and whenever you deem it to be the right time. Like Andy said: Neither the weaver itself nor you can decide for certain when "weaving is done", because there is always the possibility that yet another class or JAR is loaded and woven. So in a LTW scenario, you can only talk about "weaving so far" rather than "weaving done". But if for your purpose you simply say e.g. that when your application reaches a certain point, you want to dump, save, transmit or publish weaving stats, you can in theory do so. I am not sure if you really need that in process or you are better off with simply evaluating log files, parsing the text messages in there and then calculate the stats offline or periodically from a process tailing the log.

If all you wanted is a weaver which is not silent for 2 minutes and see some progress, because that makes you feel better, you can just use the logging option out of the box and maybe lower the logging frequency, if you think the log messages should appear more frequently.

kriegaex commented 2 years ago

@abelom, 4 months have passed. Did you try anything along the ideas I sketched here?