Become a member!

ExeWatch 1.35: Nested Timing Traces für Delphi & .NET

· 8 min read
ExeWatch Logo
🌐
Dieser Artikel ist auch in anderen Sprachen verfügbar:
🇮🇹 Italiano  •  🇬🇧 English  •  🇪🇸 Español  •  🇧🇷 Português

Nested Timing Traces machen aus den Timings von ExeWatch einen Aufrufbaum im Profiler-Stil: StartTrace, EndTrace, der Einzel-Trace-Wasserfall und der aggregierte Calling-Context-Tree, in jedem SDK (Delphi, .NET, Python, JavaScript und die DLL für C++Builder und MSVC).

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.

Wasserfall eines einzelnen Nested Timing Trace in ExeWatch: jede verschachtelte Operation mit ihrer Dauer, ihrem Anteil am Gesamtwert und zusammengefassten Schleifen

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.

Aggregierter Baum (Calling-Context-Tree) in ExeWatch: jede Ausführung einer Operation nach Aufrufpfad zusammengeführt, mit Count und Statistiken pro Knoten und divergierenden Pfaden als separate Zweige

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.

Häufige Fragen zu den Nested Timing Traces

Was sind die Nested Timing Traces von ExeWatch?

Es sind verschachtelte Timings, die als Baum organisiert sind, genau wie in einem Profiler. Du öffnest einen Trace mit StartTrace, führst darin die gewohnten StartTiming/EndTiming aus (über beliebig viele Ebenen verschachtelt) und schließt ihn mit EndTrace. ExeWatch rekonstruiert die Eltern-Kind-Hierarchie zur Lesezeit und zeigt sie als Wasserfall: jede Operation mit ihrer Dauer, ihrem Anteil am Gesamtwert und zusammengefassten Schleifen.

Sind die Nested Timing Traces in jedem SDK verfügbar?

Ja. Die StartTrace/EndTrace-API ist einheitlich über das native Delphi-SDK, .NET, Python, JavaScript und die native DLL, die von C++Builder und Microsoft Visual C++ genutzt wird. Die Semantik ist überall identisch: ein LIFO-Stack pro Thread bestimmt die Verschachtelung, ein StartTrace innerhalb eines bereits aktiven Trace degradiert zu einem Child-Span, und EndTrace schließt vergessene Spans zwangsweise.

Was ist der Unterschied zwischen dem Einzel-Trace-Wasserfall und dem aggregierten Baum?

Der Wasserfall zeigt eine einzelne Ausführung: die exakte Hierarchie genau dieses Laufs. Der aggregierte Baum (Calling-Context-Tree) führt alle Ausführungen derselben Operation zusammen, indem er sie nach Aufrufpfad gruppiert: divergierende Pfade werden zu separaten Zweigen, Schleifen und wiederholte Ausführungen summieren sich, und für jeden Knoten siehst du Count, Durchschnitt, Minimum, Maximum und p95. Das ist die Profiler-Ansicht, die dir verrät, wohin die Zeit wirklich geht.

Muss ich das Backend aktualisieren oder meinen bestehenden Code ändern?

Nein. Nested Timing Traces sind voll abwärtskompatibel. Deine bestehenden flachen Timings funktionieren weiter und erscheinen genau wie zuvor, sowohl in der Log-Liste als auch auf der Timings-Seite. Ältere SDK-Versionen funktionieren unverändert weiter: Tracing ist additiv. Um es zu nutzen, aktualisierst du einfach das SDK und fügst StartTrace/EndTrace um die Operationen herum ein, die du profilen möchtest.

Wie werden Schleifen und wiederholte Operationen behandelt?

Wenn dieselbe Operation mehrmals auf derselben Ebene läuft (zum Beispiel ein Timing innerhalb einer Schleife), fasst ExeWatch sie zu einem einzigen Knoten mit einem ×N-Badge zusammen und zeigt Durchschnitt, Minimum, Maximum und p95 über die erfolgreichen Ausführungen. So bleibt eine Schleife mit zehntausend Iterationen als eine einzige Zeile lesbar, ohne den Wasserfall zu überfluten.

Sind die Nested Timing Traces in jedem Plan enthalten?

Ja. Wie jede Kernfunktion von ExeWatch sind die Nested Timing Traces in jedem Plan verfügbar, einschließlich des kostenlosen Hobby-Plans. Zum Ausprobieren ist keine Kreditkarte erforderlich.

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

Tags

Comments

comments powered by Disqus