Как бы вы разбили и записали время выполнения различных частей вашего приложения?

Question

Мы создали веб-приложение, которое принимает сообщения SOAP, выполняет некоторую обработку, вызывает другой веб-сервис, массирует ответ и отправляет его обратно исходному абоненту.

Мы бы хотели в одной строке записать разное время выполнения для этих разных шагов. Мы используем log4j со стеком JBossWS. Другими словами, мы бы хотели, чтобы вывод журнала выглядел примерно так:

2009-06-10T16:19:31.487 3336/2449/861

, где 3336 мс - общее время, потраченное на обработку запроса, 2449 мс - время ожидания ответа веб-службы, а 861 мс - время внутренней обработки данных.

Эти разные вычисления происходят в разных местах в нашем коде, и мы не можем просто рассчитать время каждого из них и сделать вызов регистратору в конце одного метода. Один из нас предложил использовать MDC log4j для этого как набор глобальных переменных для бедного человека, чтобы отслеживать различные времена выполнения.

Итак, мои вопросы следующие:

1. Это ужасное злоупотребление основным намерением MDC?
2. Если да, как бы вы поступили иначе?

Answer 1

Пожалуйста, посмотрите на SLF4J profiler . Достаточно интересно tt был разработан для удовлетворения точно такой же потребности, то есть для измерения и улучшения производительности вызовов SOAP.

Answer 2

Звучит как работа для Perf4J .

Answer 3

Я бы сделал следующее:

1. создать класс PerformanceTimer, который предоставляет:
   • recordWaitedForWebServerReponse (идентификатор операции, время);
   • recordMassagedData (идентификатор операции, время);
   • другие методы, если необходимо
2. введите этот класс там, где это необходимо;
3. позволяет PerformanceTimer поддерживать одновременную карту OperationId -> OperationTimingData;
4. при вызове метода, известного как последний, вызовите Log4j с желаемым выводом.

Answer 4

Мы просто используем это в нашем первом фильтре запросов:

logger.trace("Init");
long start = System.currentTimeMillis();

//do stuff here 

long stop = System.currentTimeMillis();
String time = Util.getTimeDifferenceInSec(start, stop);
logger.trace("Complete in " + time + " sec");

Answer 5

Один простой способ - использовать System.currentTimeMillis(), который возвращает время в миллисекундах. Разница между миллисекундами в начале метода и миллисекундами в конце метода даст миллисекунды, затраченные на выполнение этого конкретного метода. Надеюсь System.currentTimeMillis() поможет вам.

Answer 6

Я бы использовал Spring и аспектно-ориентированное программирование, чтобы сделать это. Приятно, что я однажды написал логику и применил ее декларативно везде, где мне было нужно.

Answer 7

Хотя это, безусловно, сработает, я тоже съеживаюсь от этой мысли. Мое предложение было бы создать класс синхронизации именно для этой цели, который использует ThreadLocal для создания переменной для запроса.

Когда приходит запрос, вы создаете переменную (long со временем начала). Когда переменная уже существует, вы оставляете ее в покое. Когда результат отправляется обратно клиенту, вы рассчитываете продолжительность и записываете это.