ExeWatch 1.35: Nested Timing Traces para Delphi e .NET

Os Nested Timing Traces transformam os timings do ExeWatch em uma árvore de chamadas estilo profiler: StartTrace, EndTrace, o waterfall de um único trace e a árvore agregada Calling-Context-Tree, em todos os SDKs (Delphi, .NET, Python, JavaScript e a DLL para C++Builder e MSVC).

TL;DR: O ExeWatch 1.35 apresenta os Nested Timing Traces: timings aninhados como uma árvore, no estilo de um profiler. Abra um trace com StartTrace, execute dentro dele os StartTiming/EndTiming de sempre (inclusive em vários níveis), feche-o com EndTrace. O ExeWatch reconstrói a hierarquia em tempo de leitura e a mostra em duas visões: o waterfall de uma única execução e a árvore agregada (Calling-Context-Tree) de todas as execuções de uma operação. API uniforme em Delphi, .NET, Python, JavaScript e a DLL para C++Builder/MSVC, e total compatibilidade com os seus timings planos existentes. Experimente em exewatch.com

O ExeWatch cresce, e cresce rápido

Vamos começar com uma boa notícia: o ExeWatch está crescendo muito. Em poucos meses já somos centenas de usuários monitorando em produção suas aplicações desktop, servidor e web - e a comunidade continua aumentando semana após semana, entre desenvolvedores Delphi, C++Builder, .NET, JavaScript e Python.

O que mais nos orgulha é que cada release nasce do feedback de quem usa o ExeWatch todos os dias. A 1.35 não é exceção: os Nested Timing Traces são um dos recursos mais pedidos desde que o ExeWatch nasceu, e finalmente chegaram.

Do timing individual à árvore

Os timings sempre foram uma das ferramentas mais queridas do ExeWatch: StartTiming('LoadCustomers') … EndTiming('LoadCustomers'), e o dashboard te dá na hora a duração média, o p95, o count e a tendência de cada operação. São a forma mais rápida e direta de medir o desempenho, continuam sendo o coração do produto e funcionam exatamente como antes.

Às vezes, porém, uma operação importante é feita de muitos passos aninhados, e além do quanto demora você também quer ver como ela é por dentro. Quando GenerateInvoiceReport leva 250 ms, é bom poder descer um nível: como esses 250 ms se distribuem entre o carregamento dos dados, o rendering e talvez um loop que repete a mesma função? Os Nested Timing Traces adicionam exatamente essa dimensão - a hierarquia - por cima dos timings que você já usa, sem tirar nada.

A ideia é simples e segue o modelo dos profilers e do distributed tracing: um trace é uma árvore de spans, onde cada span é uma operação cronometrada com um pai. A novidade é que no ExeWatch cada span é simplesmente um log event de timing enriquecido com trace_id, span_id e parent_span_id. Os spans são enviados em streaming, cada um ao fechar, e a árvore é reconstruída em tempo de leitura pelo backend. Nenhuma estrutura para manter em memória no lado do cliente, nenhuma montagem em tempo de ingestão: apenas logs, como sempre.

A API: StartTrace / EndTrace

A interface adiciona apenas duas primitivas, coerentes com os StartTiming/EndTiming que você já conhece. Exemplo em Delphi:

EW.StartTrace('GenerateInvoiceReport');
try
  EW.StartTiming('LoadCustomers', 'db');
  // ... carrego os dados ...
  EW.EndTiming('LoadCustomers');

  EW.StartTiming('RenderReport', 'cpu');
  EW.StartTiming('RenderRow', 'cpu');   // filho de RenderReport
  // ...
  EW.EndTiming('RenderRow');
  EW.EndTiming('RenderReport');
finally
  Total := EW.EndTrace;   // duração total do trace, em ms
end;

O aninhamento você não declara: o ExeWatch o deduz. Cada SDK mantém uma pilha LIFO por thread; quando você abre um timing dentro de um trace ativo, esse timing vira automaticamente filho da operação que está no topo da pilha. Abra um StartTrace enquanto já há um trace ativo e ele degrada com elegância para um span filho (devolve o id do trace em andamento); esqueça um EndTiming e o EndTrace fecha à força os spans que ficaram abertos, marcando-os como falhos em vez de perdê-los.

A mesma API, com a mesma semântica, está disponível em Delphi nativo, .NET, Python, JavaScript e na DLL nativa que leva o ExeWatch ao C++Builder e ao Microsoft Visual C++. Um trace escrito em Python e um escrito em C++Builder produzem a mesma árvore no dashboard.

Visão 1: o waterfall de um único trace

Na lista de logs, um trace se reconhece na hora: a linha raiz é marcada com o ícone da árvore e o rótulo [TRACE]. Um clique abre o waterfall, a hierarquia exata daquela única execução.

Cada nó mostra sua duração, uma barra proporcional ao tempo total e o percentual em relação à raiz (com o detalhe “X% do pai” no tooltip). As operações repetidas no mesmo nível - um timing dentro de um loop - são agrupadas em uma única linha com um badge ×N e as estatísticas média / mín / máx / p95 sobre as execuções bem-sucedidas. A árvore é expansível e recolhível: deixe aberto o que te interessa, recolha os ramos que você não está olhando agora.

Visão 2: a árvore agregada (Calling-Context-Tree)

O waterfall te conta um run. Mas para caçar uma regressão de desempenho você precisa do panorama geral: como essa operação se comporta em todas as suas execuções? Por isso, na página de Timings, as operações que são raízes de trace abrem uma segunda visão - a árvore agregada, uma Calling-Context-Tree.

É a técnica clássica dos profilers. Cada execução de uma operação segue um caminho de chamada; a árvore agregada funde os spans por caminho, não só por nome. As execuções que seguem o mesmo caminho colapsam em um único nó - com o count acumulado de todas as execuções, loops incluídos - enquanto um caminho que diverge em alguns runs se ramifica em um nó próprio. O resultado é uma única árvore que diz, para cada nó, count, média, mínimo, máximo e p95 agregados sobre centenas de execuções. Para onde o tempo vai, em média, deixa de ser um palpite.

Compatibilidade total com versões anteriores

Uma regra que prezamos no ExeWatch: nada quebra. Os Nested Timing Traces são completamente aditivos.

• Os seus timings planos existentes continuam aparecendo como antes, tanto na lista de logs quanto nos agregados da página de Timings. Um span filho não polui as visões de nível superior: ele aparece apenas no drill-down do seu trace.
• As versões antigas dos SDKs continuam funcionando sem alterações. A API de tracing é nova, mas quem não a usa nem percebe.
• Para a DLL (C++Builder/MSVC) deixamos o upgrade o mais suave possível: uma DLL mais recente funciona até sob uma unit de import mais antiga, então atualizar a biblioteca não obriga a uma recompilação coordenada.

Para começar a usar os traces, basta atualizar o SDK na página Integration do dashboard e adicionar StartTrace/EndTrace em volta das operações que você quer perfilar. Todo o resto do seu código de logging fica como está.

Se você já usa o ExeWatch, os Nested Timing Traces já estão ativos na sua conta: atualize o SDK e comece a tracear. Se ainda não experimentou, o plano Hobby é gratuito e não exige cartão de crédito.

Perguntas frequentes sobre os Nested Timing Traces

O que são os Nested Timing Traces do ExeWatch?

São timings aninhados organizados como uma árvore, exatamente como em um profiler. Você abre um trace com StartTrace, executa dentro dele os StartTiming/EndTiming de sempre (aninhados em quantos níveis quiser) e o fecha com EndTrace. O ExeWatch reconstrói a hierarquia pai-filho em tempo de leitura e a mostra como um waterfall: cada operação com sua duração, seu percentual sobre o total e os loops agrupados.

Os Nested Timing Traces estão disponíveis em todos os SDKs?

Sim. A API StartTrace/EndTrace é uniforme no SDK nativo do Delphi, .NET, Python, JavaScript e na DLL nativa usada por C++Builder e Microsoft Visual C++. A semântica é idêntica em todos: uma pilha LIFO por thread determina o aninhamento, um StartTrace dentro de um trace já ativo degrada para um span filho, e EndTrace fecha à força os spans esquecidos.

Qual é a diferença entre o waterfall de um único trace e a árvore agregada?

O waterfall mostra uma única execução: a hierarquia exata daquele run. A árvore agregada (Calling-Context-Tree) funde todas as execuções da mesma operação agrupando-as por caminho de chamada: os caminhos que divergem viram ramos separados, os loops e as execuções repetidas se acumulam, e para cada nó você vê count, média, mínimo, máximo e p95. É a visão de profiler que diz para onde o tempo realmente vai.

Preciso atualizar o backend ou mudar meu código existente?

Não. Os Nested Timing Traces são totalmente compatíveis com versões anteriores. Os seus timings planos existentes continuam funcionando e aparecendo como antes, tanto na lista de logs quanto na página de Timings. As versões antigas dos SDKs continuam funcionando sem alterações: o tracing é aditivo. Para usá-lo, basta atualizar o SDK e adicionar StartTrace/EndTrace em volta das operações que você quer perfilar.

Como os loops e as operações repetidas são tratados?

Quando a mesma operação roda várias vezes no mesmo nível (por exemplo, um timing dentro de um loop), o ExeWatch a agrupa em um único nó com um badge ×N e mostra média, mínimo, máximo e p95 sobre as execuções bem-sucedidas. Assim, um loop de dez mil iterações continua legível como uma única linha, sem inundar o waterfall.

Os Nested Timing Traces estão incluídos em todos os planos?

Sim. Como todo recurso core do ExeWatch, os Nested Timing Traces estão disponíveis em todos os planos, incluindo o plano Hobby gratuito. Não é preciso cartão de crédito para experimentá-los.

---

Links e Recursos

• Site oficial: exewatch.com
• Changelog completo: exewatch.com/ui/changelog
• Pricing e On Premise: exewatch.com/ui/pricing
• Exemplos de integração: github.com/danieleteti/ExeWatchSamples
• Contato On Premise: exewatch@bittime.it
• Artigos anteriores:
  • ExeWatch 1.30: SDK para C++Builder, MSVC e Delphi anterior ao XE8, Global Tags e alertas por cliente

---

ExeWatch: Application Performance Monitoring para aplicações de servidor, desktop e web, com Artificial Intelligence Engine integrado. Criado pela bit Time Professionals.