Performance: mein Programm trödelt!

[philipp.hofmann]

Showmessages oder klassisches Logging in ein File, geht auch mit Delphi denkbar einfach, kostet recht wenig Ressourcen und liefert immer Unmengen von Informationen, wenn man mal nicht weiter weiß. Also ich debugge 80% des Codes via Logging, weil es für mich einfach schneller geht. Ich habe dann im Code ein Info- und ein Debug-Logging, so dass in der ausgelieferten Version per Default nur das Info-Logging an ist, man kann es aber zur Laufzeit umstellen (also ein wenig das gute alte Log4J nachempfunden).

Für oftmals durchlaufende Prozeduren erfasse ich nur die Zeit und gebe am Ende des Programms dann die Summen und die Anzahl aus, damit das Logging hier nicht die Performance drückt. Auch dies läuft in einem flexiblen Singleton mit einer Liste von Key/Count/Sum-Werten, also keine globalen Variablen.

[himitsu]

AQTime am Besten als Einzelanwendung benutzen, also sich nach dem Programmstart ans Programm hängen, bzw. die EXE vom AQTime starten lassen.
In der IDE integriert machte es bei uns, und scheinbar auch vielen Anderen, nur Probleme.

[TiGü]

Warum interveniert hier denn keiner?
Ein Debuggen ohne schrittweises Fortschreiten mit F8 und Rein springen in Funktionsaufrufe mit F7 ist doch total sinnlos.
So kann man doch nicht entwickeln!

Da solltest du nochmal Energie reinstecken, ob das Problem nicht eher woanders (Drittanbieter-Tools in der IDE) oder vor dem Gerät sitzt ("Ich weiß nicht richtig, wie man debuggt und möchte das auch nicht lernen").

Mit schrittweisen debuggen hättest du die drei bis vier Sekunden schon lange gefunden.

Das ging auch in XE3!

[NicoleWagner]

hier ist der Quellcode aus der Steinzeit:
Zeit - zeit9 werden verteilt ala:

zeit9:=now;

vor 'end.' steht dann:
Zeit10:=Zeit9 - zeit8;
Zeit10:=Zeit8 - zeit7;
Zeit10:=Zeit7 - zeit6;
Zeit10:=Zeit6 - zeit5;
Zeit10:=Zeit5 - zeit4;
Zeit10:=Zeit4 - zeit3;
Zeit10:=Zeit3 - zeit2;
Zeit10:=Zeit2 - zeit1;
Zeit10:=Zeit1 - zeit;

Da geht man die Werte mit F8 durch und lässt sich jweils Zeit10 anzeigen.
Wo meine Zeit geblieben ist, da bin ich noch nicht sicher. Denn Zeit 10 ist fast immer Null, bis auf eine einzige Differenz mit 2 Millisekunden. Das ist mal ein Kanditat für die Verspätung. Ansonsten werde ich die Zuweisungen noch anders verteilen.

[Lemmy]

Zitat von TiGü:

Mit schrittweisen debuggen hättest du die drei bis vier Sekunden schon lange gefunden.

unter der Annahme, dass die genau bei einem oder vielleicht zwei Funktionsaufrufe verloren gehen sicher.

Kleine Anekdote:
Nach einem wunderbaren Vormittag vor ca. 12 Jahren brauchte meine Anwendung auf einmal mehrere Minuten, bis diese beendet wurde.
Habe lange gesucht. Selbst die ein, zwei Funktionen geprüft, die ich neu eingebaut habe. Liefen in ein paar ms durch...
Am Ende habe ich meinem Chef die 80€ für ProDel aus den Rippen geleiert, damit dauerte es ne knappe halbe Stunde das Problem zu finden (also Download, Installation, kurz über die Anleitung fliegen und anwenden). Meine tolle Funktion die 10 ms dauert wurde halt ein paar mio mal aufgerufen. Seit dem halte ich mich mit Vermutungen über "was dauert da so lange" gar nicht auf: erst messen, dann machen.

Viel geht sicher mit GetTickCOunt und Co. Bei fehlerhaften Aufrufen wird das dann (je nachdem wie man ausgibt) schon komplizierter.

Nachtrag: ein guter Logger kann hier natürlich auch helfen - Synlog das im Mormot dabei ist finde ich z.B. Klasse, das hat auch einen Viewer dabei, mit dem hätte ich das Problem oben auch gefunden (aber sicherlich mehr Zeit dafür gebraucht, weil du eben jeden Prozedureinsprung selbst mit einem Logaufruf impfen musst...

[Andreas13]

Zitat von NicoleWagner:

... Trotzdem ist F7 und F8 zu ungenau, denn das wäre dann möglicherweise der IDE-Schluckauf statt meines potentiellen Fehlers. Und F7 springt mir in den Maschinenquellcode, auch wenn ich es "einstelle", dass es das nicht tun soll.

Kann es sein, daß Du Dein Programm nicht im Debug- sondern im Relaese-Modus kompiliert hast?
Gruß, Andreas

[Benmik]

Ich bin schon ein bisschen baff, weil ich dauernd an meinen Routinen (Grafikverarbeitung) herumbastle und schaue, ob ich sie nicht ein bisschen schneller kriege. Ich nehme dazu schlicht und einfach GetTickCount , in den seltensten Fällen QueryPerformanceCounter , und ich dachte, alle anderen täten das auch.

Meine einfachste Messvorrichtung geht so:

Delphi-Quellcode:

procedure Zeit(var GTC:Cardinal;Anzeigen:Boolean = False);
begin
  If Anzeigen
    then Showmessage('Benötigte Zeit: ' + FormatFloat('0,',GetTickCount - GTC) + ' Millisekunden.   ')
    else GTC := GetTickCount;
end;

procedure MachWas;
var GTC:Cardinal; 
begin
  Zeit(GTC);
  Sleep(100);
  Zeit(GTC,True);
end;

Die aufgebohrte Fassung, mit der ich beliebig viele Verarbeitungen auf einen Schlag erwische, egal, wo sie sich befinden, geht so (habe allerdings erst kürzlich daran herumgebosselt, Bugs sind also möglich):

Delphi-Quellcode:

procedure Zeit(Titel:string;var Txt:string;var GTC:Cardinal;ZeitEnde:Boolean = False;Anzeigen:Boolean = False);
var AnzMsec:Cardinal;
const LZ5 = #32#32#32#32#32;
begin
  // Schluss aller Zeitmessungungen, Anzeige Ergebnis
  If Anzeigen then begin
    AnzMsec := GetTickCount - GTC;
    Txt := Txt + FormatFloat('0,',AnzMsec) + ' msec';
    Showmessage(Txt);
  // Endpunkt der aktuellen Zeitmessung ohne sofortigen Beginn der nächsten Zeitmessung
  end else if ZeitEnde then begin
    AnzMsec := GetTickCount - GTC;
    Txt := Txt + FormatFloat('0,',AnzMsec) + ' msec' + sLineBreak;
  // Endpunkt der aktuellen Zeitmessung mit sofortigem Beginn der nächsten Zeitmessung
  end else if EndsText(LZ5,Txt) then begin
    AnzMsec := GetTickCount - GTC;
    Txt := Txt + FormatFloat('0,',AnzMsec) + ' msec' + sLineBreak;
    Txt := Txt + Titel + ': ' + LZ5;
    GTC := GetTickCount;
  // Beginn der allerersten Zeitmessung oder Aufruf einer neuen Zeitmessung ohne andere Messung unmittelbar davor
  end else if (Txt = '') or EndsText(sLineBreak,Txt) then begin
    Txt := Txt + Titel + ': ' + LZ5;
    GTC := GetTickCount;
  end else begin
    Showmessage('Fehler bei der Anordnung der Aufrufe.');
  end;
end;

procedure TForm1.FormCreate(Sender: TObject);
var GTC:Cardinal; Txt:string;
begin
  Zeit('procedure Zeitfresser1',Txt,GTC);
  Sleep(100);
  Zeit('procedure Zeitfresser2',Txt,GTC);
  Sleep(200);
  Zeit('',Txt,GTC,True);
  // Andere Verarbeitungen
  Zeit('procedure Zeitfresser3',Txt,GTC);
  Sleep(300);
  Zeit('',Txt,GTC,False,True);
  Application.Terminate;
end;

Während der Entwicklungszeit (also ein paar Jahre lang...) benutze ich globale Variablen für GTC und Txt, damit ich sie nicht immer deklarieren muss.

[himitsu]

DateTime/String (vor allem für längere Logs), GetTickCount und es git auch eine neuere Stopuhrklasse, deren Name ich immer vergesse.

Zitat:

#10#13

Falsch, denn für viele Programme/Codes sind #10#13 zwei Zeilenumgrüche (#10 + #13), anstatt Einem (#13#10).
#10 (Linux/Unix), #13 (Apple) oder #13#10 (Windows)
(wobei Apple inzwischen von #13 zu #10 gewechselt ist, aber z.B. das aktuelle RichEdit im Windows nutzt eigenartiger Weise #13)

[Benmik]

Manchmal geht #10#13, manchmal #10, manchmal #13, ich probiere es einfach aus. #9 geht in Showmessage leider nicht, daher meine Konstruktion mit Leerzeichen.
Vielleicht noch hier die Version mit QueryPerformanceCounter :

Delphi-Quellcode:

function  HLStoppUhr(Start:Boolean;var Zeitwert:Int64;MSek:Boolean = False;Meldung:Boolean = True):Extended;
var Frequenz,EndWert:Int64;
begin
  If Start then begin
    QueryPerformanceCounter(Zeitwert);
    Result := 0;
  end else begin
    QueryPerformanceFrequency(Frequenz);
    QueryPerformanceCounter(EndWert);
    Result := (EndWert - Zeitwert) * (1 / Frequenz);
    If MSek
      then Result := Result * 1000;
    If Meldung then begin
      If MSek
        then Showmessage('Benötigte Zeit: ' + MitTPkt(Result) + ' Millisekunden     ')
        else Showmessage('Benötigte Zeit: ' + MitTPkt(Result) + ' Sekunden     ');
    end;
  end;
end;

[Sherlock]

TStopwatch ist eine ganz Super Sache.
Und auf jeden Fall (ich lasse mich da auf keine Diskussionen rund um Sonderfälle ein) immer #13#10.

Sherlock