DbgTimer: Tool zur Laufzeitmessung von Programmblöcken

Zur Vorstellung von Komponenten und Units für Lazarus
Antworten
ruewa
Beiträge: 153
Registriert: Sa 12. Apr 2014, 14:43

DbgTimer: Tool zur Laufzeitmessung von Programmblöcken

Beitrag von ruewa »

Anbei ein (wirklich!) kleines Werkzeug, um während der Programmierung zeitkritische Programmteile (insbesondere Schleifen) zu untersuchen und Performancefallen aufzuspüren. Okay: Programmtechnisch ist die Unit geradezu lächerlich, aber ich denke, die Idee taugt... Nachdem ich mir immer wieder mal zeitkritische Programmteile per Timer angesehen habe, habe ich nun nach dem allereinfachsten Weg gesucht, solche Messungen mal kurz durchzuführen und per Fingerschnips auch wieder (vollständig) rauszuschmeißen.

DbgTimer verwendet intern den EpikTimer, der aber weder in das eigene Projekt eingebunden, noch in der Lazarus-IDE installiert sein muß. Lediglich muß EpikTimer.pas im Suchpfad des Compilers zu finden sein. Der EpikTimer verbraucht praktisch keine Ressourcen, anders als z.B. der TFPTimer, der zusätzliche Click-Events generiert. Für nähere Infos sh. http://wiki.freepascal.org/EpikTimer/de.

Der Grundgedanke ist, wie schon gesagt, den Timer innerhalb der IDE so unaufwändig wie möglich temporär einhängen und ihn genauso einfach auch wieder aus dem eigenen Quellcode entfernen zu können. Eingesetzt wird der DbgTimer folgendermaßen:

  1. "DbgTimer" in die uses-Zeile derjenigen Unit eintragen, die man untersuchen will.
  2. Es gibt nur zwei Anweisungen (ok: Zweieinhalb): "DebugTimerStart" und "DebugTimerStop". Damit umhüllt man den Programmblock, den man vermessen möchte, z.B. so:

    Code: Alles auswählen

    DebugTimerStart;
    for i := 0 to FFiles.Count - 1 do ParseFile(i);
    DebugTimerStop;
    NaechsteAnweisung;         // Hier Breakpoint setzen

    Will man zusätzlich die Zeit pro Schleifendurchlauf wissen, kann man stattdessen auch "DebugTimerStop" mit dem Zählparameter versehen:

    Code: Alles auswählen

    DebugTimerStop({Anzahl der Zyklen, in dem Fall also} i+1);

  3. Nun mal kurz in der DbgTimer-Unit vorbeischauen (z.B. indem man den Cursor auf "DebugTimerStart" setzt und ALT+Up eingibt), die beiden Variablen "DebugTimeTotal" and "DebugTimePerCycle" anklicken und (per Strg+F5) in die Liste der überwachten Ausdrücke aufnehmen.
  4. Jetzt noch einen Breakpoint auf die Zeile unterhalb (!) von "DebugTimerStop" setzen. Läßt man das Programm jetzt laufen, unterbricht der Debugger die Ausführung nach Abschluß der Laufzeitmessung und man kann sich die Werte in der Watchlist anschauen. Das Ergebnis sieht dann z.B. so aus:

    Code: Alles auswählen

    DebugTimeTotal       '0.217390 s'
    DebugTimePerCycle    '1.302 ms   (167 Cycles)'

  5. Wird der Timer nicht mehr benötigt, löscht man einfach den "DbgTimer"-Eintrag wieder aus der uses-Zeile und läßt sich vom Compiler die noch zu entfernenden Überreste zeigen.

Ich denke, noch einfacher geht's nicht mehr. Vielleicht kann's der eine oder andere ja gebrauchen.

Gruß Rüdiger

(Edit: Alte Datei gelöscht, aktuelle Version siehe unten.)
Zuletzt geändert von ruewa am Fr 26. Sep 2014, 23:44, insgesamt 2-mal geändert.

Benutzeravatar
m.fuchs
Lazarusforum e. V.
Beiträge: 2636
Registriert: Fr 22. Sep 2006, 19:32
OS, Lazarus, FPC: Winux (Lazarus 2.0.10, FPC 3.2.0)
CPU-Target: x86, x64, arm
Wohnort: Berlin
Kontaktdaten:

Re: DbgTimer: Tool zur Laufzeitmessung von Programmblöcken

Beitrag von m.fuchs »

Hm, ich habe mich jetzt noch nie mit dem EpikTimer beschäftigt, daher meine dumme Frage: Was ist der Vorteil gegenüber GetTickCount64? Ist die Zeitauflösung genauer?
Software, Bibliotheken, Vorträge und mehr: https://www.ypa-software.de

ruewa
Beiträge: 153
Registriert: Sa 12. Apr 2014, 14:43

Re: DbgTimer: Tool zur Laufzeitmessung von Programmblöcken

Beitrag von ruewa »

m.fuchs hat geschrieben:Was ist der Vorteil gegenüber GetTickCount64? Ist die Zeitauflösung genauer?

Ganz ehrlich: Ich weiß es nicht. Ich fand den EpikTimer halt immer sehr schön zu handhaben und ziemlich ausgereift. Doch wie das immer so ist im Leben: Keineswegs alle, aber immerhin wenigstens drei Wege führen nach Rom... :wink:

http://wiki.freepascal.org/EpikTimer hat geschrieben:EpikTimer ermöglicht dem Programmierer eine extrem genaue Zeitmessung - etwa für sehr kurz aufeinanderfolgende Ereigniss. Epiktimer lässt sich einfach verwenden, verbraucht keine CPU-Resourcen und benötigt nur 25 Bytes zusätzlichen RAM bei der Ausführung des Programms.
(...)
Die Komponente EpikTimer ist plattformunabhängig und wurde spezielle für die Lazarus-IDE sowie den FreePascal-Compiler geschrieben.
(...)
Für eine nanosekundengenaue Zeitmessung wird eine Intel-Pentium-kompatible CPU mit einem "Timestamp Counter" benötigt.
Eine mikrosekundengenaue Zeitmessung wird auf allen Systemen unterstützt.

Der EpikTimer bietet übrigens auch die Option, die Zeitquelle zu wählen:
EpikTimer.pas hat geschrieben:Dual selectable timebases: Default:System (uSec timeofday or "now" in Win32)
Optional: Pentium Time Stamp Counter.
Default timebase should work on most Unix systems of any architecture.
Timebase correlation locks time stamp counter accuracy to system clock.
(...)
Designed to support other hardware tick sources

Also für diesen Zweck ist er allemal hinreichend genau. Denn worum geht's eigentlich?

Kürzlich stand ich vor dem Problem, eine Stringliste mit >4000 (ASCII-) Einträgen auf case-insensitive Übereinstimmung mit Such-Teilstrings (sprich Textschnipseln) durchforsten zu müssen. Mit RTL-Bordmitteln stellte sich das als zu mühselig heraus, also habe ich mir eine trickreiche case-insensitive (ASCII-beschränkte) Funktion analog zu Pos() gebastelt. Nachdem ich zusätzlich die Stringliste durch eine TFPHashList ersetzt habe und die Treffer in einer TBits-Struktur markiere, juckelt der ganze Suchvorgang in 1,3 Hundertstel Sekunden durch (= 3 Microsekunden pro Stringvergleich - ich bin schier vom Hocker gefallen und hab erstmal nachgeprüft, ob die Anzahl der Treffer denn auch plausibel ist...).

Also ob das auf meiner Uraltkiste jetzt 0,013359 Sekunden für 4112 Einträge braucht oder doch eher 0,0134789 Sekunden - darüber mache ich mir wirklich keine Gedanken. Das Redesign hat sich jedenfalls als überaus hilfreich erwiesen. Daß das Sortieren ebenjener 4112 Einträge in einer zwecks Anzeige rückkopierten Stringliste dann aber 0,45 Sekunden dauert, ist somit in der Problemliste auf Platz 1 vorgerückt...

Also, sieh's mal so rum: Du mußt die Entfernung des Mondes nicht auf den Zentimeter genau wissen, um dennoch abschätzen zu können, daß er bei scheinbar gleicher Größe viel näher dran ist als die Sonne. Denn es könnte ja auch umgekehrt sein - wer weiß das schon so genau...

Gruß Rüdiger


Edit: Ich sehe gerade, daß noch bis vor kurzem um die Implementierung von GetTickCount64 heftig gerungen wurde: http://comments.gmane.org/gmane.comp.ide.lazarus.general/75319, in zum Teil auch reichlich gereiztem Ton: http://lists.lazarus.freepascal.org/pipermail/lazarus/2014-May/086973.html. Jedenfalls werden die entsprechenden Verbesserungen, falls sie sich durchsetzen, erst in späteren FPC-Versionen ausgetestet verfügbar sein.

Ist aber auch egal, ich habe auch gar nicht vor, zum Experten für die beste Zeitmessungsmethode zu werden. Wahrscheinlich hätte es jeder andere Timer bzw. Zeitabgriff genauso getan. Ich will keinen Fusionsreaktor steuern, sondern Laufzeitprobleme in meinen Programmen aufspüren. Die entstehen vornehmlich in großen Loops, deshalb sehe ich auch gar keinen Sinn darin, für diesen Zweck eine Auflösung unterhalb des Mikrosekundenbereichs anzustreben.

ruewa
Beiträge: 153
Registriert: Sa 12. Apr 2014, 14:43

Re: DbgTimer: Tool zur Laufzeitmessung von Programmblöcken

Beitrag von ruewa »

Aktuelle, leicht verbesserte, Version 0.7.2.

Sie vereinfacht u.a. das Modifizieren der Auflösung (wem Mikrosekunden noch zu grob sind - wer freilich damit versuchen wollte, in die unerforschten Zeitskalen des Urknalls vorzudringen, den wird der Compiler schon zur Vernunft bringen... :roll: )

Edit: Version 0.7.6: DebugTimerStop ist jetzt als Funktion (statt wie bisher als Prozedur) ausgeführt und liefert den Sekundenwert als Extended. An der Benutzung ändert sich nichts, die Stringvariable zum Ablegen auf der Liste der überwachten Ausdrücke existiert unverändert weiter. Wer aber mit dem Wert noch irgendwas berechnen will, kann nun außerdem das Funktionsergebnis auswerten.

Edit: Version 0.9.0:
* Pausenfunktionalität mittels optionalem Parameter "DebugTimerStart(NoReset)" - die virtuelle Stoppuhr zählt dort weiter, wo sie beim letzten Stop aufgehört hat (der parameterlose Aufruf von "DebugTimerStart" setzt die Uhr hingegen auf Null).
* Verbesserte Anzeige: Die beiden Überwachungs-Variablen "DebugTimeTotal" und "DebugTimePerCycle" werden nun je nach Größenordnung als Sekunden, Millisekunden, Microsekunden oder Nanosekunden dargestellt, durchgehend auf 4 signifikante Stellen formatiert.
* Überarbeitete Dokumentation

Version 0.9.0-4 Bug entfernt, siehe viewtopic.php?f=29&t=8233&p=72883#p72883


Gruß Rüdiger
Dateianhänge
dbgtimer.pas
Version 0.9.0-4
(12 KiB) 104-mal heruntergeladen

Antworten