ExeWatch 1.35: Nested Timing Traces, hierarchisches Profiling deiner Operationen

TL;DR: ExeWatch 1.35 führt Nested Timing Traces ein: verschachtelte Timings als Baum, im Profiler-Stil. Öffne einen Trace mit StartTrace, führe darin die gewohnten StartTiming/EndTiming aus (auch über mehrere Ebenen), schließe ihn mit EndTrace. ExeWatch rekonstruiert die Hierarchie zur Lesezeit und zeigt sie in zwei Ansichten: dem Wasserfall einer einzelnen Ausführung und dem aggregierten Baum (Calling-Context-Tree) aller Ausführungen einer Operation. Eine einheitliche API über Delphi, .NET, Python, JavaScript und die DLL für C++Builder/MSVC, und volle Abwärtskompatibilität mit deinen bestehenden flachen Timings. Probier es auf exewatch.com

ExeWatch wächst, und zwar schnell

Beginnen wir mit guten Nachrichten: ExeWatch wächst richtig stark. In wenigen Monaten sind wir bereits bei Hunderten von Nutzern, die ihre Desktop-, Server- und Web-Anwendungen in Produktion überwachen — und die Community wächst Woche für Woche weiter, quer durch Delphi-, C++Builder-, .NET-, JavaScript- und Python-Entwickler.

Worauf wir am stolzesten sind: Jede Release entsteht aus dem Feedback der Menschen, die ExeWatch täglich nutzen. 1.35 ist keine Ausnahme: Die Nested Timing Traces sind eine der meistgewünschten Funktionen, seit es ExeWatch gibt — und jetzt sind sie endlich da.

Vom einzelnen Timing zum Baum

Timings gehören seit jeher zu den beliebtesten Werkzeugen in ExeWatch: StartTiming('LoadCustomers') … EndTiming('LoadCustomers'), und das Dashboard liefert dir sofort Durchschnittsdauer, p95, Count und Trend jeder Operation. Sie sind der schnellste, direkteste Weg, Performance zu messen, sie bleiben das Herzstück des Produkts und funktionieren genau wie bisher.

Manchmal aber besteht eine wichtige Operation aus vielen verschachtelten Schritten, und über das wie lange es dauert hinaus willst du auch sehen, wie sie innen aufgebaut ist. Wenn GenerateInvoiceReport 250 ms braucht, ist es schön, eine Ebene tiefer gehen zu können: Wie verteilen sich diese 250 ms auf das Laden der Daten, das Rendering und vielleicht eine Schleife, die dieselbe Funktion wiederholt? Nested Timing Traces fügen genau diese Dimension hinzu — die Hierarchie — zusätzlich zu den Timings, die du bereits nutzt, ohne etwas wegzunehmen.

Die Idee ist einfach und folgt dem Modell von Profilern und Distributed Tracing: ein Trace ist ein Baum von Spans, wobei jeder Span eine gemessene Operation mit einem Elternknoten ist. Der Clou: In ExeWatch ist jeder Span einfach ein Timing-Log-Event, angereichert mit trace_id, span_id und parent_span_id. Die Spans werden gestreamt, jeder beim Schließen, und der Baum wird vom Backend zur Lesezeit rekonstruiert. Keine Struktur, die clientseitig im Speicher gehalten werden muss, kein Zusammenbauen zur Ingest-Zeit: nur Logs, wie immer.

Die API: StartTrace / EndTrace

Die Schnittstelle fügt nur zwei Primitive hinzu, konsistent mit den StartTiming/EndTiming, die du schon kennst. Beispiel in Delphi:

EW.StartTrace('GenerateInvoiceReport');
try
  EW.StartTiming('LoadCustomers', 'db');
  // ... Daten laden ...
  EW.EndTiming('LoadCustomers');

  EW.StartTiming('RenderReport', 'cpu');
  EW.StartTiming('RenderRow', 'cpu');   // Kind von RenderReport
  // ...
  EW.EndTiming('RenderRow');
  EW.EndTiming('RenderReport');
finally
  Total := EW.EndTrace;   // Gesamtdauer des Trace, in ms
end;

Die Verschachtelung deklarierst du nicht: ExeWatch leitet sie ab. Jedes SDK führt einen LIFO-Stack pro Thread; wenn du ein Timing innerhalb eines aktiven Trace öffnest, wird dieses Timing automatisch zum Kind der Operation, die gerade oben auf dem Stack liegt. Öffnest du ein StartTrace, während bereits ein Trace aktiv ist, degradiert es elegant zu einem Child-Span (es gibt dir die ID des bereits laufenden Trace zurück); vergisst du ein EndTiming, schließt EndTrace die noch offenen Spans zwangsweise und markiert sie als fehlgeschlagen, statt sie zu verlieren.

Dieselbe API mit derselben Semantik ist verfügbar in nativem Delphi, .NET, Python, JavaScript und in der nativen DLL, die ExeWatch zu C++Builder und Microsoft Visual C++ bringt. Ein in Python geschriebener Trace und einer in C++Builder erzeugen denselben Baum im Dashboard.

Ansicht 1: der Einzel-Trace-Wasserfall

In der Log-Liste erkennst du einen Trace sofort: Die Wurzelzeile ist mit dem Baum-Icon und dem [TRACE]-Label markiert. Ein Klick öffnet den Wasserfall, die exakte Hierarchie genau dieser einen Ausführung.

Jeder Knoten zeigt seine Dauer, einen Balken proportional zur Gesamtzeit und den Prozentsatz relativ zur Wurzel (mit dem Detail „X% des Elternknotens" im Tooltip). Operationen, die auf derselben Ebene wiederholt werden — ein Timing in einer Schleife — werden zu einer einzigen Zeile mit einem ×N-Badge zusammengefasst, mit den Statistiken Durchschnitt / Min / Max / p95 über die erfolgreichen Ausführungen. Der Baum ist auf- und zuklappbar: Lass offen, was dich interessiert, klapp die Zweige zu, die du gerade nicht ansiehst.

Ansicht 2: der aggregierte Baum (Calling-Context-Tree)

Der Wasserfall erzählt dir von einem Lauf. Aber um eine Performance-Regression aufzuspüren, brauchst du das Gesamtbild: Wie verhält sich diese Operation über alle ihre Ausführungen? Deshalb öffnen auf der Timings-Seite Operationen, die Trace-Wurzeln sind, eine zweite Ansicht — den aggregierten Baum, einen Calling-Context-Tree.

Es ist die klassische Profiler-Technik. Jede Ausführung einer Operation folgt einem Aufrufpfad; der aggregierte Baum führt die Spans nach Pfad zusammen, nicht nur nach Name. Ausführungen, die demselben Pfad folgen, kollabieren zu einem einzigen Knoten — mit dem kumulierten Count aller Ausführungen, Schleifen inklusive — während ein Pfad, der in manchen Läufen divergiert, in einen eigenen Knoten abzweigt. Das Ergebnis ist ein einziger Baum, der dir für jeden Knoten Count, Durchschnitt, Minimum, Maximum und p95 aggregiert über Hunderte von Ausführungen verrät. Wohin die Zeit im Durchschnitt geht, ist keine Vermutung mehr.

Volle Abwärtskompatibilität

Eine Regel, die uns bei ExeWatch wichtig ist: Es bricht nichts. Nested Timing Traces sind vollständig additiv.

• Deine bestehenden flachen Timings erscheinen weiterhin genau wie zuvor, sowohl in der Log-Liste als auch in den Aggregaten der Timings-Seite. Ein Child-Span verschmutzt die Top-Level-Ansichten nicht: Er taucht nur im Drill-down seines Trace auf.
• Ältere SDK-Versionen funktionieren unverändert weiter. Die Tracing-API ist neu, aber wer sie nicht nutzt, merkt nichts davon.
• Für die DLL (C++Builder/MSVC) haben wir das Upgrade so reibungslos wie möglich gemacht: Eine neuere DLL funktioniert sogar unter einer älteren Import-unit, sodass das Aktualisieren der Bibliothek keine koordinierte Neukompilierung erzwingt.

Um Traces zu nutzen, aktualisierst du einfach das SDK über die Integration-Seite des Dashboards und fügst StartTrace/EndTrace um die Operationen herum ein, die du profilen möchtest. Der Rest deines Logging-Codes bleibt, wie er ist.

Wenn du ExeWatch bereits nutzt, sind die Nested Timing Traces schon auf deinem Account aktiv: Aktualisiere das SDK und leg mit dem Tracing los. Falls du es noch nicht ausprobiert hast — der Hobby-Plan ist kostenlos und verlangt keine Kreditkarte.

Links und Ressourcen

• Offizielle Website: exewatch.com
• Vollständiges Changelog: exewatch.com/ui/changelog
• Pricing & On Premise: exewatch.com/ui/pricing
• Integrationsbeispiele: github.com/danieleteti/ExeWatchSamples
• On-Premise-Kontakt: exewatch@bittime.it
• Frühere Artikel:
  • ExeWatch 1.30: SDK für C++Builder, MSVC und Delphi vor XE8, Global Tags und Alerts pro Kunde
  • ExeWatch und madExcept: friedliche Koexistenz in Delphi-Projekten

ExeWatch: Application Performance Monitoring für Server-, Desktop- und Web-Anwendungen, mit integrierter Artificial Intelligence Engine. Erstellt von bit Time Professionals.