¿Cómo desglosaría y registraría los tiempos de ejecución de diferentes partes de su aplicación?

Question

Hemos creado una aplicación web que acepta mensajes SOAP, procesa un poco, llama a otro servicio web, da masajes a la respuesta y la envía de nuevo a la persona que llama.

Nos gustaría registrar, en una sola línea, los diferentes tiempos de ejecución para estos diferentes pasos. Usamos log4j con la pila JBossWS. En otras palabras, nos gustaría que la salida del registro se vea así:

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

donde 3336 ms es el tiempo total dedicado a atender la solicitud, 2449 ms es el tiempo dedicado a esperar la respuesta del servicio web y 861 ms es el tiempo dedicado a masajear los datos internamente.

Estos cálculos diferentes ocurren en diferentes lugares en nuestro código y no podemos simplemente cronometrar cada uno de ellos y hacer una llamada al registrador al final de un solo método. Uno de nosotros ha sugerido usar el MDC de log4j para esto como el conjunto de variables globales de un pobre para rastrear los diferentes tiempos de ejecución.

Entonces mis preguntas son las siguientes:

1. ¿Es este un abuso horrible de la intención principal del MDC?
2. En caso afirmativo, ¿cómo haría esto de otra manera?

Answer 1

Consulte SLF4J profiler . Suficientemente interesante. Se desarrolló para responder exactamente a la misma necesidad, es decir, medir y mejorar el rendimiento de las llamadas SOAP.

Answer 2

Suena como un trabajo para Perf4J .

Answer 3

Yo haría lo siguiente:

1. crea una clase PerformanceTimer, que expone:
   • recordWaitedForWebServerReponse (operationId, time);
   • recordMassagedData (operationId, time);
   • otros métodos, si es necesario
2. inyecta esa clase donde sea necesario;
3. haga que PerformanceTimer mantenga un mapa concurrente de OperationId - > OperationTimingData;
4. en la llamada al método que se sabe que es la última, invoque Log4j con la salida que desea.

Answer 4

Aunque ciertamente funcionaría, también me estremezco ante la idea. Mi sugerencia sería crear una clase de temporización solo para ese propósito que use ThreadLocal para crear una variable por solicitud.

Cuando llega la solicitud, crea la variable (un largo con la hora de inicio). Cuando la variable ya existe, la dejas sola. Cuando el resultado se devuelve al cliente, usted calcula la duración y lo registra.

Answer 5

Usaría Spring y la programación orientada a aspectos para hacerlo. Lo bueno es que escribiría la lógica una vez y la aplicaría declarativamente en todas partes donde la necesitara.

Answer 6

Una forma simple es usar System.currentTimeMillis () que devuelve el tiempo en milisegundos. La diferencia entre el milisegundo al inicio del método y los milisegundos al final del método dará los milisegundos que se tomaron para ejecutar ese método en particular. Espero que System.currentTimeMillis() te ayude.

Answer 7

Simplemente usamos esto en nuestro primer filtro de solicitud:

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");