log optimierung gesucht

[schoschy]

Moin,

aktuell logge ich aus allen möglichen richtungen in eine Textdatei.
Das Funktioniert ohne Probleme mit SSDs, bei HDDs kann es aber schon mal zu problemen führen wenn das I/O-delay im dreistelligen ms-Bereich ankommt.

Code: Alles auswählen

    if FileExists(logfile) then
      stream := TFileStream.Create(logfile, fmOpenWrite)
    else
      stream := TFileStream.Create(logfile, fmCreate); 

Das wird für jede Zeile aufgerufen, was mittels FileExists jedes mal überprüft, ob der File vorhanden ist.

Gibt es hier eine elegante Lösung, den File einfach immer mit fmOpenWrite zu öffnen und wenn er dann doch mal nicht vorhanden ist, selbigen zu erstellen und anschließend zu befüllen? Das sollte einen enormen Leistungsschub geben.

Danke für Ideen und Anregungen,
Gruß

[Zvoni]

Ein Try/Except?

Aircode

Code: Alles auswählen

Try
  s:=TFileStream.Create(logfile,fmOpenWrite);
Except
  On EFOpenError Do s:=TFileStream.Create(logfile,fmCreate);
End;

https://www.freepascal.org/docs-html/rt ... reate.html

If the file could not be opened in the requested mode, an EFOpenError exception is raised.

[af0815]

Nur so eine Frage - warum nicht LazLogger oder MultiLog ? Die sind in sich optimiert und der LazLogger ist in Lazarus auch vorhanden und wird deswegen auch entsprechend gepflegt.

Es gibt sogar Programme, wo ich beides zugleich verwende. LazLogger um aktuelle Ereignisse zu dokumentieren (Console oder Ram-Disk) und den MultiLog um damit echt fatale Sachen persistent zu dokumentieren

[alfware17]

Zvoni war schneller mit der try/except Idee.
Allerdings müßte das fmWrite nach dem fmCreate dann irgendwie doch noch kommen?

Ich hatte mich anfangs gefragt, warum du immer fmOpenWrite versuchst - aber ich gebe zu, ich kenne als Anfänger das Schreiben in den Stream nicht so.
Ich würde die Logdatei einfach immer offen lassen, und das Ganze absichern durch eine Ampel, die am Anfang gestellt wird oder eben wenn du das Log auf/zu machst.

if ioLogOpen then Write()

[schoschy]

Ein Try/Except?

Aircode

Code: Alles auswählen

Try
  s:=TFileStream.Create(logfile,fmOpenWrite);
Except
  On EFOpenError Do s:=TFileStream.Create(logfile,fmCreate);
End;

https://www.freepascal.org/docs-html/rt ... reate.html

If the file could not be opened in the requested mode, an EFOpenError exception is raised.

Danke dir, vor lauter Baum den Wald nicht gefunden, oder so.

Zvoni war schneller mit der try/except Idee.
Allerdings müßte das fmWrite nach dem fmCreate dann irgendwie doch noch kommen?

Ich hatte mich anfangs gefragt, warum du immer fmOpenWrite versuchst - aber ich gebe zu, ich kenne als Anfänger das Schreiben in den Stream nicht so.
Ich würde die Logdatei einfach immer offen lassen, und das Ganze absichern durch eine Ampel, die am Anfang gestellt wird oder eben wenn du das Log auf/zu machst.

if ioLogOpen then Write()

Warum ich den File immer wieder auf mache - mehrere Threads die hinein schreiben. Hat sich so ergeben.

Kleines Testprogramm:

Code: Alles auswählen

  procedure TMyApplication.DoRun;
  var
    ErrorMsg, s1: string;
    n, testCount: integer;
    StartTime: QWord;
    stream: TFileStream;
  begin
    ....
    { add your program here }
    StartTime := GetTickCount64;
    testCount := 10000;
    s1 := 'TestZeile' + LineEnding;
    for n := 0 to testCount do
    begin
      try
        try
          stream := TFileStream.Create('text.log', fmOpenWrite);
        except
          On EFOpenError do
            stream := TFileStream.Create('text.log', fmCreate);
        end;
        stream.Position := stream.Size;
        stream.WriteBuffer(Pointer(s1)^, Length(s1));

      finally
        stream.Free;
      end;
    end;
    WriteLn('tryExcept: ',IntToStr(GetTickCount64 - StartTime), ' ms');

// Fehler gemacht, reset Zeiterfassung vergessen
    StartTime := GetTickCount64;  
    for n := 0 to testCount do
    begin
      try
        if FileExists('text.log') then
          stream := TFileStream.Create('text.log', fmOpenWrite)
        else
          stream := TFileStream.Create('text.log', fmCreate);
        stream.Position := stream.Size;
        stream.WriteBuffer(Pointer(s1)^, Length(s1));
      finally
        stream.Free;
      end;
    end;
    WriteLn('FileExists: ',IntToStr(GetTickCount64 - StartTime), ' ms');

    ReadLn;
    // stop program loop
    Terminate;
  end;   

und raus kommt das

Code: Alles auswählen

tryExcept: 2438 ms
FileExists: 2547 ms

Im Groben ist das schon mal ein Anfang.

Edit1: Reset Zeitmessung vergessen. - Daten sind angepasst.
Edit2: Ergebnisse nichtsaussagend.

[schoschy]

Nur so eine Frage - warum nicht LazLogger oder MultiLog ? Die sind in sich optimiert und der LazLogger ist in Lazarus auch vorhanden und wird deswegen auch entsprechend gepflegt.

Es gibt sogar Programme, wo ich beides zugleich verwende. LazLogger um aktuelle Ereignisse zu dokumentieren (Console oder Ram-Disk) und den MultiLog um damit echt fatale Sachen persistent zu dokumentieren

Hats mir garnicht angezeigt, dass du auch noch was geschrieben hast.
Schau ich mir auch mal an.

[schoschy]

Ich hab eben mal noch weiter gegengetestet.
Jetzt ist so ein test natürlich recht kurz gehalten und wird von jeglichem Flash akzeptiert.
auf einer HDD die hier noch zum test vorhanden war sind es aber schonmal 600ms zeitversatz. hier kann aber immernoch OS und flash der HDD (in dem fall vorhanden) abfedern.
5.000.000 Durchgänge - Test 2.

Den Lazlogger schmeiß ich im anschluss mal dagegen.

[Zvoni]

Hier mal ein Ansatz (in Delphi) ohne FileStream --> runter scrollen bis letzte Antwort
https://stackoverflow.com/questions/165 ... hread-safe

Logfile am Anfang aufmachen, die Threads schreiben rein, am Schluss zu machen
Das einzige was du anpassen müsstest wäre die "Flush"-Funktionalität

EDIT: Als zweiter Ansatz:
Dein FileStream bleibt im Main Thread. Bei Programmstart aufmachen, bei Programmende zu machen
Die jeweiligen Threads greifen NICHT auf die Datei selbst zu, sondern schicken per Synchronize den String, der in die Datei geschrieben werden soll, zurück an den Main-Thread.

[schoschy]

Kurz einmal verwertbare Ergebnisse, dass man hier auch etwas damit anfangen kann.

Code: Alles auswählen

tryExcept: 264047 ms
FileExists: 269812 ms
Filestream schreiben: 2516 ms
LazLogger: 312 ms

Lesen ist noch nichtsaussagend, aufgrund meiner Testumgebung.
Auf einer HDD ist hier Faktor 1,6 mehr im gegentest gewesen bei 18min im tryExcept als basis. (5mio samplesize)

Kann man beim LazLogger im laufenden betrieb die Datei ändern?

Code: Alles auswählen

    DebugLogger.LogName := 'text.log';  
    ... 1h späer
    DebugLogger.LogName := 'neuerText.log';  

Wenn ja, ist das von der Implementierung der kleinste Aufwand und somit zielführend anhand der Ergebnisse.

[Zvoni]

Wird dir ein
DebugLogger.OpenFile/CloseFile angeboten?

[schoschy]

Wird dir ein
DebugLogger.OpenFile/CloseFile angeboten?

Wird es mir nicht - finde ich aber raus, ob und wie es geht.

Noch als Zusatz:

Code: Alles auswählen

    DebugLogger.CloseLogFileBetweenWrites:=True;   

Das reiht sich in die anderen beiden Ergebnisse ein. ~4min

Im Fazit bin ich mit meiner Applikation wohl am Limit der HDD-I/O angekommen, weshalb hier anpassungen getan werden müssen.
Immerhin 4 Jahre hat es durchgehalten

Danke und Gruß

Edit:
Einfach ein neuer Aufruf von
DebugLogger.LogName := 'text.log';
macht eine neue Datei.

[af0815]

Das teuerste ist immer ein IO auf Ebene des Filesystems, das lernt man in allen DB Admin Kursen als erstes. Deswegen ist auch immer zu überlegen wie und was man wirklich loggen muß.
Ist es nur Applikationsspezifisch und braucht nicht persistent eine Reboot/Absturz des Rechners zu überleben, so ist eine Ram-Disk nicht unbedingt das schlechteste, wenn man es auch von der Größe her planen kann. Ev. kann man einen extra Prozess drauf ansetzen ältere Logs von dem Ramdrive auf ein anderes Medium zu verschieben und dort auch mit LogRotate für Ordnung zu sorgen.

Bei LazLogger muss man nicht unbedingt in eine Datei loggen, man kann zur unmittelbaren Fehlersuche das ganze stattdessen auf die Konsole loggen. Das geht auch unter Windows ohne Probleme und es erkennt, wenn gerade keine Konsole offen ist und stürzt deswegen nicht gleich ab, wie schon öfters bei selbstgebastelten Versionen mit Writeln zu beobachten ist.

Mann merkt schon, das das auch von den Entwicklern von Lazarus selbst verwendet wird.

[schoschy]

Das teuerste ist immer ein IO auf Ebene des Filesystems, das lernt man in allen DB Admin Kursen als erstes. Deswegen ist auch immer zu überlegen wie und was man wirklich loggen muß.

ist klar - das erste Provisorium ist aber auch immer das permanenteste.

Ist es nur Applikationsspezifisch und braucht nicht persistent eine Reboot/Absturz des Rechners zu überleben, so ist eine Ram-Disk nicht unbedingt das schlechteste, wenn man es auch von der Größe her planen kann. Ev. kann man einen extra Prozess drauf ansetzen ältere Logs von dem Ramdrive auf ein anderes Medium zu verschieben und dort auch mit LogRotate für Ordnung zu sorgen.

Bei LazLogger muss man nicht unbedingt in eine Datei loggen, man kann zur unmittelbaren Fehlersuche das ganze stattdessen auf die Konsole loggen. Das geht auch unter Windows ohne Probleme und es erkennt, wenn gerade keine Konsole offen ist und stürzt deswegen nicht gleich ab, wie schon öfters bei selbstgebastelten Versionen mit Writeln zu beobachten ist.

Mann merkt schon, das das auch von den Entwicklern von Lazarus selbst verwendet wird.

Ich hab heute morgen mal noch etwas mit LazLogger gespielt. Eine Frage stellt sich in meiner Situation.
Gibt es die Option, auf die geschriebene Zeile im File zu warten? Wenn ich meine Applikation in Lazarus schließe, ist die letzte Zeile des logfiles immer unterbrochen an einer undefinierbaren stelle.


Hintergrund:

Ich habe mehrere Kunden die eine Applikation verwenden, bei einem hängt sich die Applikation auf.
Für mich ist der entscheidende Teil, dass ich sicherstellen kann, dass der api-call der zum Abstuz führt auch in der log steht.
Selbst habe ich schon viele Wege versucht, diesen Fehler zu finden, bin aber ratlos - keine Testmöglichkeiten.

Der api-call ist deshalb wichtig, da diese aus einem Fremdsystem kommen.
Ich könnte auch nur diesen Teil in eine Textfile schreiben, dann fehlen aber die Daten dahinter - sind aber reproduzierbar.