Counting method execution time through annotation

In many projects it is required to count the time that a particular method has spent. To do this, you can manually save the value of System.currentTimeMillis () and after the method calculate the elapsed time. When a lot of methods it becomes not very convenient.
So I decided to write a simple annotation that would consider the execution time of the method. Trying to find information on the Internet, I realized that there is very little of it on this topic. We'll have to somehow get out, collecting information bit by bit.

Our annotation will mark the methods for which we want to calculate the execution time in milliseconds or nanoseconds and output the result through System.out.println.

First, create the annotation itself:

package annotations.time;

import java.lang.annotation.ElementType;
import java.lang.annotation.Retention;
import java.lang.annotation.RetentionPolicy;
import java.lang.annotation.Target;

@Target({ElementType.METHOD})
@Retention(RetentionPolicy.SOURCE)
public @ interface Time {
public enum TimeInterval { MILLISECOND, NANOSECOND };
annotations.time.Time.TimeInterval interval() default annotations.time.Time.TimeInterval.MILLISECOND;
String format() default "Elapsed %s" ;
}

* This source code was highlighted with Source Code Highlighter .

The interval field is used to specify the time interval (milliseconds or nanoseconds), the format field specifies the format for outputting the result.
')
Now, in order for this annotation to work as it should, you need to create a handler class that extends AbstractProcessor. In this class, the time saving is added before the method code, the method code itself is copied into the try-finally block, and the time spent by the method is calculated and finally displayed in the console:

package annotations.time;

import com.sun.tools.javac.code.Flags;
import com.sun.tools.javac.code.TypeTags;
import com.sun.tools.javac.model.JavacElements;
import com.sun.tools.javac.processing.JavacProcessingEnvironment;
import com.sun.tools.javac.tree.JCTree;
import com.sun.tools.javac.tree.JCTree.JCBlock;
import com.sun.tools.javac.tree.JCTree.JCCatch;
import com.sun.tools.javac.tree.JCTree.JCExpression;
import com.sun.tools.javac.tree.JCTree.JCExpressionStatement;
import com.sun.tools.javac.tree.JCTree.JCMethodDecl;
import com.sun.tools.javac.tree.JCTree.JCStatement;
import com.sun.tools.javac.tree.JCTree.JCVariableDecl;
import com.sun.tools.javac.tree.TreeMaker;
import com.sun.tools.javac.util. List ;
import java.util.Set;
import javax.annotation.processing.AbstractProcessor;
import javax.annotation.processing.ProcessingEnvironment;
import javax.annotation.processing.RoundEnvironment;
import javax.annotation.processing.SupportedAnnotationTypes;
import javax.annotation.processing.SupportedSourceVersion;
import javax.lang.model.SourceVersion;
import javax.lang.model.element.Element;
import javax.lang.model.element.TypeElement;
import javax.lang.model.util.Elements;

@SupportedAnnotationTypes( value = {TimeAnnotationProcessor.ANNOTATION_TYPE})
@SupportedSourceVersion(SourceVersion.RELEASE_6)
public class TimeAnnotationProcessor extends AbstractProcessor {

public static final String ANNOTATION_TYPE = "annotations.time.Time" ;
private JavacProcessingEnvironment javacProcessingEnv;
private TreeMaker maker;

@Override
public void init(ProcessingEnvironment procEnv) {
super.init(procEnv);
this .javacProcessingEnv = (JavacProcessingEnvironment) procEnv;
this .maker = TreeMaker.instance(javacProcessingEnv.getContext());
}

@Override
public boolean process(Set<? extends TypeElement> annotations, RoundEnvironment roundEnv) {
if (annotations == null || annotations.isEmpty()) {
return false ;
}

final Elements elements = javacProcessingEnv.getElementUtils();

final TypeElement annotation = elements.getTypeElement(ANNOTATION_TYPE);

if (annotation != null ) {
// ,
final Set<? extends Element> methods = roundEnv.getElementsAnnotatedWith(annotation);

JavacElements utils = javacProcessingEnv.getElementUtils();
for (final Element m : methods) {
Time time = m.getAnnotation(Time. class );
if (time != null ) {
JCTree blockNode = utils.getTree(m);
//
if (blockNode instanceof JCMethodDecl) {
//
final List <JCStatement> statements = ((JCMethodDecl) blockNode).body.stats;

//
List <JCStatement> newStatements = List .nil();
//
JCVariableDecl var = makeTimeStartVar(maker, utils, time);
newStatements = newStatements.append( var );

// try,
List <JCStatement> tryBlock = List .nil();
for (JCStatement statement : statements) {
tryBlock = tryBlock.append(statement);
}

// finally,
JCBlock finalizer = makePrintBlock(maker, utils, time, var );
JCStatement stat = maker.Try(maker.Block(0, tryBlock), List .<JCCatch>nil(), finalizer);
newStatements = newStatements.append(stat);

//
((JCMethodDecl) blockNode).body.stats = newStatements;
}
}
}

return true ;
}

return false ;
}

private JCExpression makeCurrentTime(TreeMaker maker, JavacElements utils, Time time) {
// System.nanoTime System.currentTimeMillis
JCExpression exp = maker.Ident(utils.getName( "System" ));
String methodName;
switch (time.interval()) {
case NANOSECOND:
methodName = "nanoTime" ;
break ;
default :
methodName = "currentTimeMillis" ;
break ;
}
exp = maker.Select(exp, utils.getName(methodName));
return maker.Apply( List .<JCExpression>nil(), exp, List .<JCExpression>nil());
}

protected JCVariableDecl makeTimeStartVar(TreeMaker maker, JavacElements utils, Time time) {
// . time_start_{random}
JCExpression currentTime = makeCurrentTime(maker, utils, time);
String fieldName = fieldName = "time_start_" + ( int ) ( Math .random() * 10000);
return maker.VarDef(maker.Modifiers(Flags.FINAL), utils.getName(fieldName), maker.TypeIdent(TypeTags.LONG), currentTime);
}

protected JCBlock makePrintBlock(TreeMaker maker, JavacElements utils, Time time, JCVariableDecl var ) {
// System.out.println
JCExpression printlnExpression = maker.Ident(utils.getName( "System" ));
printlnExpression = maker.Select(printlnExpression, utils.getName( "out" ));
printlnExpression = maker.Select(printlnExpression, utils.getName( "println" ));

// (currentTime - startTime)
JCExpression currentTime = makeCurrentTime(maker, utils, time);
JCExpression elapsedTime = maker.Binary(JCTree.MINUS, currentTime, maker.Ident( var .name));

//
JCExpression formatExpression = maker.Ident(utils.getName( "String" ));
formatExpression = maker.Select(formatExpression, utils.getName( "format" ));

//
List <JCExpression> formatArgs = List .nil();
formatArgs.append(maker.Literal(time.format()));
formatArgs.append(elapsedTime);

JCExpression format = maker.Apply( List .<JCExpression>nil(), formatExpression, formatArgs);

List <JCExpression> printlnArgs = List .nil();
printlnArgs.append(format);

JCExpression print = maker.Apply( List .<JCExpression>nil(), printlnExpression, printlnArgs);
JCExpressionStatement stmt = maker.Exec(print);

List <JCStatement> stmts = List .nil();
stmts.append(stmt);

return maker.Block(0, stmts);
}
}

* This source code was highlighted with Source Code Highlighter .

In order for the java compiler to use our control class, you need to create the file META-INF / javax.annotation.processing.Processor, which should contain the following line:
annotations.time.TimeAnnotationProcessor

After that, we collect all our files in annotations.jar and add it to the classpath to any project.

Now, to calculate the execution time of the method, it is enough to add the Time annotation to this method and after its execution, the time spent by the method will be displayed in the console:

@Time(format= "method time: %s ms" )
public void start() {
Thread.sleep(1000);
}

* This source code was highlighted with Source Code Highlighter .

As a result, we will see in the console:
method time: 1000 ms

UPD: added some comments to the code
UPD2: You can also rework the example so that it displays the time spent by the method in System.err only if it is more than the value specified in the annotation parameters. This could be useful for production servers, where using the profiler is not always convenient.