Подсчёт времени выполнения метода через аннотацию

    Во многих проектах требуется посчитать время, которое затратил тот или иной метод. Для этого можно вручную сохранять значение System.currentTimeMillis() и после метода вычислять затраченное время. Когда методов много это становится не очень удобным.
    Поэтому я решил написать простенькую аннотацию, которая бы считала время выполнения метода. Попытавшись найти информацию в интернете, понял, что её по данной теме очень мало. Придётся как-то выкручиваться, собирая информацию по крупицам.

    Наша аннотация будет помечать методы, для которых мы хотим посчитать время выполнения в миллисекундах или наносекундах и выводить результат через System.out.println.

    Для начала создадим саму аннотацию:
    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.


    Поле interval служит для указания интервала времени (миллисекунды или наносекунды), поле format задаёт формат вывода результата.

    Теперь, чтобы данная аннотация сработала как надо, нужно создать класс-обработчик расширяющий AbstractProcessor. В данном классе добавляется сохранение времени перед кодом метода, сам код метода копируется в блок try-finally, а блоке finally вычисляется затраченное методом время и выводится в консоль:
    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.


    Для того чтобы компилятор java использовал наш управляющий класс, нужно создать файл META-INF/javax.annotation.processing.Processor, в котором должна быть прописана следующая строка:
    annotations.time.TimeAnnotationProcessor

    После этого собираем все наши файлы в annotations.jar и добавляем его в classpath к любому проекту.

    Теперь, чтобы посчитать время выполнения метода, достаточно добавить к этому методу аннотацию Time и после его выполнения в консоль будет выведено затраченное методом время:
    @Time(format="method time: %s ms")
    public void start() {
      Thread.sleep(1000);
    }

    * This source code was highlighted with Source Code Highlighter.


    В результате в консоли увидим:
    method time: 1000 ms

    UPD: добавил немного комментариев в код
    UPD2: Так же можно переработать пример, чтобы он выводил время затраченное методом в System.err только если оно больше заданного в параметрах аннотации. Это могло бы быть полезно для production серверов, где пользоваться профайлером не всегда удобно.
    Ads
    AdBlock has stolen the banner, but banners are not teeth — they will be back

    More

    Comments 30

      –9
      Вот что значит отсутствие анонимных функций и ФВП.

      С ними это решается так (с точностью до синтаксиса конкретного языка):
      time fmt act = do
          t <- getCurrentTime
          finally act $ do
              t2 <- getCurrentTime
              printf fmt $ show $ fromEnum $ (utctDayTime t2 - utctDayTime t) / 1e9

      start = time "method time: %s ms" $ do
          threadDelay 1000000
        +10
        Автор написал, как поменять N объявлений методов, чтобы, добавив или убрав десяток символов к ключам компилятора, получить данные профайлинга.
        Вы (если я правильно понимаю этот псевдокод) написали, как поменять M*N точек вызова методов, загадив код сообщениями профайлинга.

        По-моему, Вы решили какую-то другую задачу. Нет?
          0
          Нет, автор предлагает к определению методу дописать
          @Time(format="method time: %s ms")
          А я предлагаю дописать туда же (не к вызову, хотя и это возможно, т.е. ещё один вариант использования, при этом выглядящий так же):
          time "method time: %s ms" $
          По-моему, я решил ту же задачу 5-ю строками.

          Судя по плюсам вам и минусам мне, остальные даже в моём коде не разобрались, но выразили «мнение». Хоть вам спасибо, что словесно.
            +1
            Наверное мало кто понял как это относится к java и java annotations
        +3
        Хорошая идея.
        Кстати есть open-source реализация подобной идеи: Perf4J, там аннотация получила имя @Profiled, а поддерживается через AOP
          0
          Ну, действительно интересная идея. Если нужно померить время выполнения метода, то проще чем аннотация, наверное и не придумать. А Perf4J позволяет «мерить» и нужные кусочки кода внутри методов.
          Ну кстати, это еще и пример того, как создать свою аннотацию. Молодец, автор!
            0
            Небольшой недостаток AOP в том, что необходимо подключать дополнительные библиотеки. А aspectj.jar весит примерно 12 мегабайт.
              +1
              aspectjrt.jar + aspectjweaver.jar = 2Mb
                0
                Хм. Это я на сайте aspecj посмотрел. Там предлагают скачать aspectj-1.6.8.jar (~12M). Видимо можно взять какой-то гораздо меньший кусочек =)
                  0
                  в aspectj-1.6.8.jar на сайте есть либы, доки, примеры. Они просто назвали файл не .zip, а .jar, что сбивает с толку
              0
              Насколько я понимаю, в java нельзя сделать аннотацию на блок кода внутри метода.
              А так можно было бы сделать что-то вроде @Time { longOperation(); } или @Time for(;;) {}
            +1
            Да, спасибо за пример. Для себя нашёл полезное!
            Пишите ещё!
              +1
              Интересная реализация, возьму на заметку с Вашего разрешения :)
              Но комментарии в коде не помешали бы, а? ;)
                +1
                Попробую дописать ;)
                0
                Полезная вещь, если нет возможности пользоваться профайлером
                  +1
                  А можно сделать так, что бы когда в рантайм-класспассе есть annotations.jar — то профилирование включено, а когда её нет — то оно отключено(и без всяких classnotfoundexception)?

                  (Там возможно понадобится порезать annotations.jar на 2 либы annotations-api.jar и annotations-logger.jar)

                    0
                    В runtime библиотека не нужна. При компиляции в код программы вставляются нужные куски и всё.
                    +3
                    Правильно ли я понял что код работает на 1.6+?
                      0
                      Да, похоже это всё появилось только в 1.6.
                      В 1.5 моя аннотация игнорируется.
                        0
                        Да, эта реализация использует «Pluggable Annotation Processing API» появившийся в 1.6. =( *CRY*
                        Тем не менее автору уважение, я проникся.
                          0
                          Если кто-нибудь знает где это всё подробно описано — напишите в комментариях, пожалуйста.
                          Мне пришлось изучать код библиотеки lombok (http://projectlombok.org/, интересная библиотека кстати) для того, чтобы разобраться.
                      +2
                      Интерес представляет compile-time weaving, дающий возможность профайлить private методы. Обычным проксированием такого не добьешься. По поводу аннотаций: лично я бы использовал их лишь как маркер, т.е. без параметров (есть аннотация — профайлить, нет — не профайлить), а формат выводимых сообщений определял где-нибудь в конфиге (не в коде!). Это позволит легко генерить суммарную статистику в дальнейшем — количество вызовов метода, среднее время, минимальное, максимальное и т.д. Какой смысл в произвольном формате для каждого метода? Как потом этим пользоваться?
                      Кстати perf4j все это уже умеет давно и прекрасно используется при разработке проектов, поэтому ИМХО автору стоило акцентировать внимание на новой фиче java 6, а не на профайлинге. «Все украдено до нас» ;)
                        +1
                        Это была первая пришедшая в голову простая задача :) Пойду изучать perf4j
                          0
                          Все правильно, именно так и сделан aspect для jboss. Профайлить можно либо по аннотациям, либо pattern на имя методов\классов\пакетов.
                          Более общее название такого подхода — АОП
                          0
                          для меня этот уровень уже магия.
                            0
                            Судя по тому что вы видимо прочли этот пост:) то магией это останется не на долго:)
                            +1
                            > Наша аннотация будет считать время выполнения метода
                            Вы уж извините, но это звучит абсолютно безграмотно. Аннотация сама по себе ничего не может считать. Аннотации — лишь метаинформация, метаданные. Вы сами это прекрасно знаете, но читателей (новичков) вводит в заблуждение, как будто действительно какая-то магия происходит.
                              0
                              Конечно сама аннотация ничего не считает. Но некоторая магия всё же происходит :) Попробую как-нибудь по другому написать.
                              0
                              Плюсую в топик и в карму. Для меня использование аннотация для профайлинга не очень интересно, т.к. JProfiler-a хватает вполне, но вот сам пример нетривиального использования pluggable annotation processor'a, модифицирующего код — очень интересен. В который раз убеждаюсь, что в недрах com.sun.* лежат сокровища :)
                                0
                                Отличная статья, именно то, что искал для своего проекта

                                Only users with full accounts can post comments. Log in, please.