Become a member!

ExeWatch 1.35: Nested Timing Traces, profiling jerárquico de tus operaciones

ExeWatch Logo
🌐
Este artículo también está disponible en otros idiomas:
🇮🇹 Italiano  •  🇬🇧 English  •  🇩🇪 Deutsch  •  🇧🇷 Português

TL;DR: ExeWatch 1.35 presenta los Nested Timing Traces: timings anidados como un árbol, al estilo de un profiler. Abre un trace con StartTrace, ejecuta dentro los StartTiming/EndTiming habituales (también en varios niveles), ciérralo con EndTrace. ExeWatch reconstruye la jerarquía en tiempo de lectura y la muestra en dos vistas: el waterfall de una única ejecución y el árbol agregado (Calling-Context-Tree) de todas las ejecuciones de una operación. API uniforme en Delphi, .NET, Python, JavaScript y la DLL para C++Builder/MSVC, y total compatibilidad con tus timings planos existentes. Pruébalo en exewatch.com

ExeWatch crece, y crece rápido

Empecemos con una buena noticia: ExeWatch está creciendo muchísimo. En pocos meses ya somos cientos de usuarios monitorizando en producción sus aplicaciones de escritorio, servidor y web — y la comunidad sigue ampliándose semana tras semana, entre desarrolladores de Delphi, C++Builder, .NET, JavaScript y Python.

Lo que más nos enorgullece es que cada release nace del feedback de quienes usan ExeWatch a diario. La 1.35 no es una excepción: los Nested Timing Traces son una de las funcionalidades más pedidas desde que ExeWatch existe, y por fin están aquí.

Del timing individual al árbol

Los timings han sido siempre una de las herramientas más queridas de ExeWatch: StartTiming('LoadCustomers')EndTiming('LoadCustomers'), y el dashboard te da al instante la duración media, el p95, el count y la tendencia de cada operación. Son la forma más rápida y directa de medir el rendimiento, siguen siendo el corazón del producto y funcionan exactamente igual que antes.

A veces, sin embargo, una operación importante está hecha de muchos pasos anidados, y más allá del cuánto dura también quieres ver cómo está hecha por dentro. Cuando GenerateInvoiceReport tarda 250 ms, está bien poder bajar un nivel: ¿cómo se reparten esos 250 ms entre la carga de datos, el rendering y quizá un bucle que repite la misma función? Los Nested Timing Traces añaden exactamente esa dimensión — la jerarquía — encima de los timings que ya usas, sin quitar nada.

La idea es sencilla y sigue el modelo de los profilers y del distributed tracing: un trace es un árbol de spans, donde cada span es una operación cronometrada con un padre. La novedad es que en ExeWatch cada span es simplemente un log event de timing enriquecido con trace_id, span_id y parent_span_id. Los spans se envían en streaming, cada uno al cerrarse, y el árbol se reconstruye en tiempo de lectura en el backend. Ninguna estructura que mantener en memoria en el lado cliente, ningún ensamblaje en tiempo de ingesta: solo logs, como siempre.

La API: StartTrace / EndTrace

La interfaz añade solo dos primitivas, coherentes con los StartTiming/EndTiming que ya conoces. Ejemplo en Delphi:

EW.StartTrace('GenerateInvoiceReport');
try
  EW.StartTiming('LoadCustomers', 'db');
  // ... cargo los datos ...
  EW.EndTiming('LoadCustomers');

  EW.StartTiming('RenderReport', 'cpu');
  EW.StartTiming('RenderRow', 'cpu');   // hijo de RenderReport
  // ...
  EW.EndTiming('RenderRow');
  EW.EndTiming('RenderReport');
finally
  Total := EW.EndTrace;   // duración total del trace, en ms
end;

El anidamiento no lo declaras: lo deduce ExeWatch. Cada SDK mantiene una pila LIFO por hilo; cuando abres un timing dentro de un trace activo, ese timing se convierte automáticamente en hijo de la operación que está en la cima de la pila. Abre un StartTrace mientras hay un trace ya activo y degrada con elegancia a un span hijo (te devuelve el id del trace en curso); olvida un EndTiming y EndTrace cierra forzosamente los spans que quedaron abiertos, marcándolos como fallidos en lugar de perderlos.

La misma API, con la misma semántica, está disponible en Delphi nativo, .NET, Python, JavaScript y en la DLL nativa que lleva ExeWatch a C++Builder y Microsoft Visual C++. Un trace escrito en Python y otro escrito en C++Builder producen el mismo árbol en el dashboard.

Vista 1: el waterfall de un único trace

En la lista de logs, un trace se reconoce enseguida: la fila raíz está marcada con el icono del árbol y la etiqueta [TRACE]. Un clic abre el waterfall, la jerarquía exacta de esa única ejecución.

Waterfall de un único Nested Timing Trace en ExeWatch: cada operación anidada con su duración, su porcentaje sobre el total y los bucles agrupados

Cada nodo muestra su duración, una barra proporcional al tiempo total y el porcentaje respecto a la raíz (con el detalle “X% del padre” en el tooltip). Las operaciones repetidas en el mismo nivel — un timing dentro de un bucle — se agrupan en una única fila con un badge ×N y las estadísticas media / mín / máx / p95 sobre las ejecuciones correctas. El árbol se puede expandir y plegar: deja abierto lo que te interesa, pliega las ramas que ahora no estás mirando.

Vista 2: el árbol agregado (Calling-Context-Tree)

El waterfall te cuenta un run. Pero para cazar una regresión de rendimiento necesitas la visión de conjunto: ¿cómo se comporta esa operación en todas sus ejecuciones? Por eso, en la página de Timings, las operaciones que son raíces de trace abren una segunda vista — el árbol agregado, un Calling-Context-Tree.

Árbol agregado (Calling-Context-Tree) en ExeWatch: todas las ejecuciones de una operación fusionadas por ruta de llamada, con count y estadísticas por nodo y las rutas divergentes como ramas separadas

Es la técnica clásica de los profilers. Cada ejecución de una operación sigue una ruta de llamada; el árbol agregado fusiona los spans por ruta, no solo por nombre. Las ejecuciones que siguen la misma ruta colapsan en un único nodo — con el count acumulado de todas las ejecuciones, bucles incluidos — mientras que una ruta que diverge en algunos runs se ramifica en un nodo propio. El resultado es un único árbol que te dice, para cada nodo, count, media, mínimo, máximo y p95 agregados sobre cientos de ejecuciones. Adónde va el tiempo, de media, deja de ser una conjetura.

Compatibilidad total hacia atrás

Una regla que cuidamos en ExeWatch: no se rompe nada. Los Nested Timing Traces son completamente aditivos.

  • Tus timings planos existentes siguen apareciendo igual que antes, tanto en la lista de logs como en los agregados de la página de Timings. Un span hijo no contamina las vistas de nivel superior: aparece solo en el drill-down de su trace.
  • Las versiones antiguas de los SDK siguen funcionando sin cambios. La API de tracing es nueva, pero quien no la usa no nota nada.
  • Para la DLL (C++Builder/MSVC) hemos hecho el upgrade lo más suave posible: una DLL más reciente funciona incluso bajo una unit de import más antigua, así que actualizar la biblioteca no obliga a una recompilación coordinada.

Para empezar a usar los traces solo tienes que actualizar el SDK desde la página Integration del dashboard y añadir StartTrace/EndTrace alrededor de las operaciones que quieras perfilar. Todo el resto de tu código de logging se queda como está.

Si ya usas ExeWatch, los Nested Timing Traces ya están activos en tu cuenta: actualiza el SDK y empieza a tracear. Si todavía no lo has probado, el plan Hobby es gratuito y no requiere tarjeta de crédito.


Enlaces y Recursos


ExeWatch: Application Performance Monitoring para aplicaciones de servidor, escritorio y web, con Artificial Intelligence Engine integrado. Creado por bit Time Professionals.

Comments

comments powered by Disqus