Mandelbug auf die Schliche kommen

[Medium]

Ich habe in einem unserer Programme ein verflucht ekeliges Problem, dass einem Mandelbug fast nahe kommt. (Ein wenig Heisenbug ist auch dabei, da das Problem im Debugger noch nie auftauchte bisher.)

Letztlich ist das Problem, dass das Programm einfach irgendwann mitten drin einfach stehen bleibt, und nicht mehr reagiert. Dies tut es vornehmlich dann, wenn es gerade nicht bedient wird (hab ich aber auch schon gesehen). Es ist keine Endlosschleife - ich vermute hier eher ein böses Zusammenspiel aus Sockets, Threads und VCL, obgleich ich schon sehr aufgepasst habe Critical Sections entsprechend einzusetzen. Interessant ist vor allem, dass das Problem auf manchen Rechnern sehr oft vorkommt, auf anderen hingegen noch nie beobachtet wurde :?

Interessant ist vor allem, dass das Programm teils über Tage am Stück ohne zu murren immer ein und die selbe Tätigkeit ausführt, und irgendwann aus dem Nichts heraus knallt es dann. Keiner war am PC, die vom Programm verarbeiteten Daten sind immer gleichförmig (ein paar Werte aus einer SPS darstellen), keine sonstigen besonderen Umstände. Einfach "puff".
Im Taskmanager hat das Programm dann 0% CPU Last, normal viel Speicher, und die gewohnte Anzahl Threads und andere Resourcen. Es scheint also zumindest schon mal nichts "überzulaufen".

Da ich keinem zumuten kann das Teil für mich zu debuggen, würde ich gerne ein paar Ideen einholen, wie ich der Sache am besten Herr werden könnte. Insbesondere ist problematisch dabei, dass ich das Problem auf meinem Entwicklungs-PC einfach nicht habe! Zur Zeit hätte ich aber noch übers Wochenende einen PC vom Kunden hier, bei dem es recht zuverlässig zumindest 3-4 Mal am Tag passiert, so dass das die Gelegenheit wäre.

Wie debugged man so etwas so, dass man zumindest schon mal grob weiss, in welchem Modul man überhaupt anfangen müsste nach dem konkreten Problem zu suchen?

[Elvis]

Verpacke deine critical sections in eine eigene Klasse. Wann immer jemand ein lock will, starte einen Timeout (fast vollkommen egal wie du den implementierst) . Wenn der abläuft, wirf eine Exception. Denn lange laufende locks sind fast immer ein Indikator für ein deadlock.
Wenn du (conditional compiling nur für debug builds!) in deiner CriticalSection-Implementierung eine Liste aller aktuell offenen locks vorhältst, kannsu einfacher sehen wo sich die Schlange in den Schwanz beißt.

[Medium]

Das ist schon mal eine gute Idee, die ich auch gerade fix umgesetzt habe. Danke! Mal sehen, ob da ggf. schon mehr zu sehen ist. Ich hoffe, dass mein Problem-PC fix wieder "Mist" macht :)

[divBy0]

So ein ähnliches Problem hatte ich bei einer unsere Visualisierungen auch mal. Es hatte damals nur einen PC betroffen, auf allen anderen lief es problemlos. Nach längerer Standzeit kam die Meldung "Programm funktioniert nicht mehr", ohne Fehlermeldung, ohne Exception, ohne Logeintrag.
Ich hatte mir per Syslog dann viele, viele Meldung ausgeben lassen (in Threads, CriticalSections, DB-Zugriffen, Indy TCP, usw.)und im Endeffekt hatte das Problem mit dem DHCP-Server des Kunden zu tun, da dieser aus irgendeinem Grund immer zwei verschiedene IP-Adressen verteilt hatte. Die Verbindung zur SPS fand das nicht so toll... Nach Umstellung auf feste IP-Adressen (wie es bei allen Kunden üblich ist) gab es keine Probleme mehr.

[Medium]

Der Hänger trat wieder auf, jedoch leider nicht in einer CS - der Timeout kam nicht. Die SPS-Verbindung macht ein separates Programm, dass die Daten in eine DB schaufelt, und die Clients (die Problemkinder) via Socket auf neue Daten aufmerksam macht. Die Clients lesen diese daraufhin aus der DB und versorgen die nötigen Controls.

Detailexkurs: Das Lesen aus der DB passiert dabei in je einem Thread pro Anlagenbild. Der Lesethread füllt (eine per CS geschützte) Liste an Controls die Updates bekommen, mitsamt der neuen Werte und der Properties. Dann wird dem Formular eine Message geposted, woraufhin dieses dann im Mainthread Kontext diese Liste (ebenfalls innerhalb der CS) abarbeitet bis sie leer ist.
Genau diese Update-Routine habe ich jetzt mit ausgiebigem Logging bestückt, um zu schauen ob sich da nicht ggf. ein Control verschluckt. Zuvor hatte ich meine Socketkommunikation "verloggt", da hier ebenfalls Listen in einer CS befüllt werden. Hier lief aber bis zum Hänger alles sauber.

Die SPS (bzw. alles in dem Netz) hat statische IPs, damit sind wir auch schon sonst zu oft auf die Nase gefallen :)

[Medium]

Joa, so als kleine Rückmeldung hier: Es ist doch ein voll ausgewachsener Heisenbug. Seit meinem letzten Beitrag läuft das Programm nun durchgehend ohne weiteres Auftreten des Problems. Da ich die Kiste morgen wieder abgeben muss, heisst das wohl erst Mal Logfile Größe begrenzen, und sie mit aktivem Logging in dieser Routine ausliefern. Entweder ist das dann ein mir Bauchweh bereitender Quasi-Fix (:?), oder irgend wann passiert es dann doch noch mal und liefert eine brauchbare Stelle zum Weiterforschen. Himmel, wie ich so einen Murks hasse! Danke dennoch schon mal euch beiden.

[Zacherl]

Eventuell tritt das Problem auch in einer CriticalSection auf, die du gar nicht selbst erstellst, sondern indirekt von den Socket Komponenten verwendet wird, etc. Du könntest mal die RtlEnterCriticalSection() und RtlLeaveCriticalSection() APIs hooken und dort den Timeout implementieren. Dann bekommst du zu hundert Prozent auch DeadLocks mit, die durch Fremdkomponenten oä. erzeugt werden.

[Sir Rufo]

Diese Art von Fehlern haben aber auch die Eigenart manchmal durch ein Logging zu verschwinden.

Vorher konnten alle Threads ungehindert wuseln und sich verknoten, mit dem Logging wird aber u.U. dort eine gewisse Ordnung geschaffen.

Nehmen wir mal an du loggst in eine Datei.
Damit immer nur ein Thread schreibt, nimmt man eine CS und schon hat man dem System eine andere Ordnung aufgezwungen, wo der Fehler evtl. nicht mehr auftaucht oder die Wahrscheinlichkeit erheblich reduziert wird.

[Morphie]

Könnte man nicht mittels Remote Debugger nachsehen wo es knallt?

[Medium]

@Zacherl: Die Socket-Kommunikation scheint nach aktuellen Erkenntnissen als Übeltäter auszuschließen zu sein. Es ist auch nur ein einfacher TClientSocket ohne Aufbauten und Schickschnack. Den würde ich vorerst als unschuldig und abgehakt ansehen glaube ich.

@Sir Rufo: Das war eine Befürchtung die ich hatte, wobei die CS-Struktur in etwa so aussieht:

Code:

procedure UpdateVCLControls;
begin
  EnterUpdateCS;
  try
    while UpdateList.Count > 0 do
    begin
      try
        LogSomething;
        DoSometingWithUpdateListItem(0);
        LogSomething;
        DoSometingWithUpdateListItem(0);
        ...
      finally
        UpdateList.Delete(0);
      end;
    end;
  finally
    LeaveUpdateCS;
  end;
end;

procedure LogSomething;
begin
  EnterLogCS;
  try
    Log;
  finally
    LeaveLogCS;
  end;
end;

Das Anfügen an die UpdateList würde daher imho durch die CS des Loggings eigentlich nicht weiter beeinflusst werden, da diese immer nur betreten und verlassen wird, während die UpdateList ohnehin schon gelockt ist. Dennoch: Lasse ich die LogSomething-Aufrufe weg, habe ich wieder meine sporadischen Hänger.

Die UpdateList ist eine TObjectList (OwnsObjects=true), die Items dieser Klasse trägt:

Delphi-Quellcode:

  TVCLUpdateData = class
  public
    Instance: TObject;
    ClassType: TClass;
    PropName: String;
    Value: Variant;
    constructor Create(aInstance: TObject; aType: TClass; aPropName: String; aValue: Variant);
  end;

Der UpdateThread füllt diese Liste anhand neuer Daten aus der Datenbank, wobei die Komponenten anhand ihres Names per FindComponent() ausfindig gemacht wurden (und auch die gesamte Programmdauer existieren). Es sind geprüfterweise immer gültige Referenzen.
Die Update-Loop (die Prozedur oben im Pseudocode) macht letztlich innerhalb der while-Schleife nur dieses:

Delphi-Quellcode:

SetPropValue((item.Instance as item.ClassType), item.PropName, item.Value);

(Mit zuvoriger Prüfung, ob item.Value ungleich NULL ist und die Instanz wirklich vom Typ "ClassType" ist.) "item" wird zuvor

Delphi-Quellcode:

UpdateList[0] as TVCLUpdateData

zugewiesen.
Die Update-Loop wird per PostMessage() vom UpdateThread angestoßen, nachdem dieser alle im aktuellen Zyklus anstehenden Updates gesammelt hat.

@Morphie: Leider bleibt der Debugger nicht an einer sinnvollen Stelle stehen. Da das Problem offenbar keine Exception auslöst, und ich nicht 6h durchsteppen kann bis der Fehler freundlicherweise mal auftritt (und es dann vermutlich auch nicht tut), hatte ich das aufgegeben :?

[Sir Rufo]

Wenn du das Update per PostMessage anstösst, warum dann eine CS?
Dann läuft das doch auch im MainThread-Kontext und eine CS ist dann überflüssig.

Du solltest abprüfen, ob beim Aufruf der Update-Methode auch

Delphi-Quellcode:

MainThreadID = GetCurrentThreadID

ist (sollte ja so sein).
Die VCL reagiert auch dann komisch, wenn man trotz CS aus einem anderen Thread darauf zugreift ;)

[Namenloser]

Wo gerade schon PostMessage in einem anderen Zusammenhang erwähnt wurde: Bau doch deinen Logger so um, dass er mit Messages arbeitet (Also einen neuen Logger-Thread mit eigener Message-Loop machen, und dann immer mit PostThreadMessage die Log-Einträge an ihn schicken). Dann sollte das Logging IMO auf den Programmablauf keinen Einfluss mehr haben.

Zum Remote-Debugging: Man vergisst es manchmal, weil man damit meistens nur in den Untiefen des WinAPI-Assemblercodes landet, aber es gibt beim Debugger auch noch den Pause-Button ;). Ich hab damit z.B. gestern rausgefunden, dass mein Multi-Thread-Programm sich in WaitForSingleObjectEx aufgehängt hatte. Vielleicht kannst du den Fehler damit doch eingrenzen.

[Medium]

Zitat:

Zitat von Sir Rufo (Beitrag 1219576)

Wenn du das Update per PostMessage anstösst, warum dann eine CS?
Dann läuft das doch auch im MainThread-Kontext und eine CS ist dann überflüssig.

Die Liste, die in der Update-Prozedur abgearbeitet wird, wird in einem anderen Thread mit neuen Items versorgt. Diese wird dort abgesichert, nicht die VCL Controls.

Remote-Debugging hat sich mittlerweile erledigt, da ich das Gerät vorhin wieder beim Kunden hin gehängt habe. Ich durfte das Teil leider nur über das Wochenende haben, die Mittagsschicht heute brauchte es wieder :(
Die Idee das Logging so zu entkoppeln ist aber interessant. Das könnte ich da mal bei Gelegenheit rein bauen! Cool.

[nahpets]

Hallo,

weiß nicht, ob ich hier hilfreich sein kann.

Habe ein Programm, das aber ein ähnliches Verhalten an den Tag legt.

Es dient dazu per TIDHTTP diverse Listen von Dateien von unterschiedlichen Server abzuholen und als Dateien lokal zu speichern bzw. abhängig vom Inhalt der Dateien Einträge in einer Datenbank vorzunehmen.

Es laufen immer mehrere Threads, die jeweils eine eigenen HTTP-Verbindung aufmachen.

Ab und an klappt da was nicht und ein Thread bleibt stehen.

Habe dann ein Logging eingebaut, das mir alle Fehler protokolliert. Das klappt auch soweit. Wenn ein Thread stehen bleibt, muss aber kein Fehler aufgetreten sein. Was mir aber in den Logdateien aufgefallen ist, ist folgendes: Bevor ein Thread stehen bleibt, ist in diesem oder einem anderen Thread, mit einer Verbindung zu dem gleichen Server, ein Fehler aufgetreten (meist Fehler 500 - interner Serverfehler - auf Serverseite). D. h.: Nachdem ein Fehler auftrat, scheint eine neue Verbindung zu dem entsprechenden Server (häufig, aber nicht immer) zu scheitern, aber nicht so, dass ein abfangbarer Fehler auftritt, sondern die Verbindung per TIDHTTP scheint in einen nicht definierten Zustand zu treten. Sie kommt nicht zurück, es ist auch keine Tätigkeit im Netz von dieser Verbindung zu erkennen, die Verbindung bleibt aber (laut Firewall) bestehen, ein Timeout tritt auch nach Stunden nicht auf. Dieser Zustand läßt sich nur durch das Beenden des Programmes beheben.

Eine Lösung habe ich nicht, bei meinem Programm gehe ich momentan her und beende die weitere Verarbeitung, sobald ich eine Fehlermeldung im Logging feststellen kann. Es wird dann eine Meldung ausgegeben. Wird die Verarbeitung dann (ohne Programmneustart) neu gestartet, kann es sein, dass sie über Stunden problemlos weiterläuft (bis irgendwann der nächste "Hänger" auftritt).

Könnte es sein, dass bei dem hier beschriebenen Problem ein ähnlicher "Zustand" eintritt?