Become a member!

ExeWatch 1.35: Nested Timing Traces, il profiling gerarchico delle operazioni

· 6 min read
ExeWatch Logo
🌐
Questo articolo è disponibile anche in altre lingue:
🇬🇧 English  •  🇩🇪 Deutsch  •  🇪🇸 Español  •  🇧🇷 Português

TL;DR: ExeWatch 1.35 introduce i Nested Timing Traces: timing annidati ad albero, in stile profiler. Apri un trace con StartTrace, esegui dentro i normali StartTiming/EndTiming (anche su più livelli), chiudi con EndTrace. ExeWatch ricostruisce la gerarchia a tempo di lettura e la mostra in due viste: il waterfall di una singola esecuzione e l’albero aggregato (Calling-Context-Tree) di tutte le esecuzioni di un’operazione. API uniforme su Delphi, .NET, Python, JavaScript e la DLL per C++Builder/MSVC, e piena retrocompatibilità con i timing piatti esistenti. Provalo su exewatch.com

ExeWatch cresce, e cresce in fretta

Partiamo da una bella notizia: ExeWatch sta crescendo davvero tanto. In pochi mesi siamo già a centinaia di utenti che monitorano in produzione le loro applicazioni desktop, server e web — e la community continua ad allargarsi settimana dopo settimana, tra sviluppatori Delphi, C++Builder, .NET, JavaScript e Python.

La cosa che ci rende più orgogliosi è che ogni release nasce dal feedback di chi usa ExeWatch tutti i giorni. La 1.35 non fa eccezione: i Nested Timing Traces sono una delle funzionalità più richieste da quando ExeWatch è nato, e finalmente sono qui.

Dal singolo timing all’albero

I timing sono da sempre uno degli strumenti più amati di ExeWatch: StartTiming('LoadCustomers') … EndTiming('LoadCustomers'), e in dashboard hai subito durata media, p95, conteggio e trend di ogni operazione. Sono il modo più rapido e diretto per misurare le performance, restano il cuore del prodotto e continuano a funzionare esattamente come prima.

A volte, però, un’operazione importante è fatta di tanti passi annidati, e oltre al quanto dura vuoi vedere anche com’è fatta dentro. Quando GenerateInvoiceReport impiega 250 ms, è bello poter scendere di un livello: quei 250 ms come si distribuiscono tra caricamento dati, rendering e magari un ciclo che ripete la stessa funzione? I Nested Timing Traces aggiungono esattamente questa dimensione — la gerarchia — sopra ai timing che usi già, senza togliere nulla.

L’idea è semplice e segue il modello dei profiler e del distributed tracing: un trace è un albero di span, dove ogni span è un’operazione cronometrata con un genitore. La novità è che in ExeWatch ogni span è semplicemente un log event di timing arricchito con trace_id, span_id e parent_span_id. Gli span vengono spediti in streaming, ognuno alla sua chiusura, e l’albero viene ricostruito a tempo di lettura dal backend. Nessuna struttura da tenere in memoria lato client, nessun assemblaggio a tempo di ingest: solo log, come sempre.

L’API: StartTrace / EndTrace

L’interfaccia aggiunge due sole primitive, coerenti con StartTiming/EndTiming che già conosci. Esempio in Delphi:

EW.StartTrace('GenerateInvoiceReport');
try
  EW.StartTiming('LoadCustomers', 'db');
  // ... carico i dati ...
  EW.EndTiming('LoadCustomers');

  EW.StartTiming('RenderReport', 'cpu');
  EW.StartTiming('RenderRow', 'cpu');   // figlio di RenderReport
  // ...
  EW.EndTiming('RenderRow');
  EW.EndTiming('RenderReport');
finally
  Total := EW.EndTrace;   // durata totale del trace, in ms
end;

L’annidamento non lo dichiari: lo deduce ExeWatch. Ogni SDK mantiene uno stack LIFO per thread; quando apri un timing dentro un trace attivo, quel timing diventa automaticamente figlio dell’operazione correntemente in cima allo stack. Apri un StartTrace mentre un trace è già attivo e degrada con eleganza a span figlio (ti restituisce l’id del trace già in corso); dimentichi un EndTiming e EndTrace chiude forzatamente gli span rimasti aperti, marcandoli come falliti invece di perderli.

La stessa API, con la stessa semantica, è disponibile su Delphi nativo, .NET, Python, JavaScript e sulla DLL nativa che porta ExeWatch su C++Builder e Microsoft Visual C++. Un trace scritto in Python e uno scritto in C++Builder producono lo stesso albero in dashboard.

Vista 1: il waterfall del singolo trace

Nella lista log, un trace si riconosce subito: la riga radice è marcata con l’icona dell’albero e l’etichetta [TRACE]. Un click apre il waterfall, la gerarchia esatta di quella singola esecuzione.

Waterfall di un singolo Nested Timing Trace in ExeWatch: ogni operazione annidata con la sua durata, la percentuale sul totale e i loop accorpati

Ogni nodo mostra la sua durata, una barra proporzionale al tempo totale e la percentuale rispetto alla radice (con il dettaglio “X% del genitore” nel tooltip). Le operazioni ripetute allo stesso livello — un timing dentro un ciclo — vengono accorpate in un’unica riga con un badge ×N e le statistiche media / min / max / p95 sulle esecuzioni riuscite. L’albero è espandibile e collassabile: tieni aperto ciò che ti interessa, chiudi i rami che ora non guardi.

Vista 2: l’albero aggregato (Calling-Context-Tree)

Il waterfall ti racconta un run. Ma per scovare una regressione di performance ti serve il quadro d’insieme: come si comporta quell’operazione su tutte le sue esecuzioni? Per questo, nella pagina Timings, le operazioni che sono radici di trace aprono una seconda vista — l’albero aggregato, ovvero un Calling-Context-Tree.

Albero aggregato (Calling-Context-Tree) in ExeWatch: tutte le esecuzioni di un'operazione fuse per percorso di chiamata, con count e statistiche per nodo e i percorsi divergenti come rami separati

È la tecnica classica dei profiler. Ogni esecuzione di un’operazione segue un percorso di chiamata; l’albero aggregato fonde gli span per percorso, non solo per nome. Le esecuzioni che seguono lo stesso path collassano in un nodo unico — con il conteggio cumulato di tutte le esecuzioni, loop inclusi — mentre un percorso che in alcune run diverge si ramifica in un nodo a sé. Il risultato è un singolo albero che ti dice, per ogni nodo, count, media, minimo, massimo e p95 aggregati su centinaia di esecuzioni. Dove se ne va il tempo, in media, smette di essere una congettura.

Retrocompatibilità totale

Una regola di ExeWatch a cui teniamo: non si rompe niente. I Nested Timing Traces sono completamente additivi.

  • I timing piatti esistenti continuano a comparire come prima, sia nella lista log sia negli aggregati della pagina Timings. Uno span figlio non inquina le viste top-level: appare solo nel drill-down del suo trace.
  • Le vecchie versioni degli SDK continuano a funzionare senza modifiche. L’API di tracing è nuova, ma chi non la usa non se ne accorge.
  • Per la DLL (C++Builder/MSVC) abbiamo reso l’upgrade il più morbido possibile: una DLL più recente funziona anche sotto una unit di import più vecchia, così aggiornare la libreria non impone una ricompilazione coordinata.

Per iniziare a usare i trace ti basta aggiornare l’SDK dalla pagina Integration della dashboard e aggiungere StartTrace/EndTrace attorno alle operazioni che vuoi profilare. Tutto il resto del tuo codice di logging resta com’è.

Se usi già ExeWatch, i Nested Timing Traces sono già attivi sul tuo account: aggiorna l’SDK e inizia a tracciare. Se non l’hai ancora provato, il piano Hobby è gratuito e non richiede carta di credito.

ExeWatch: Application Performance Monitoring per applicazioni server, desktop e web, con Artificial Intelligence Engine integrato. Creato da bit Time Professionals.

Tags

Comments

comments powered by Disqus