Discussion:
JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem
(zu alt für eine Antwort)
Christian H. Kuhn
2016-08-24 14:36:42 UTC
Permalink
Hallo Gemeinde,

Immer noch die Schachuhr.
Projekt: https://www.qno.de/gitweb/?p=qchessclock.git;a=summary
Snapshot unter
https://www.qno.de/gitweb/?p=qchessclock.git;a=snapshot;h=9ad77df87ad2dc11c8fa72816bec8c5e5459ea77;sf=tgz

Alles lief, und da musste ich doch was ändern :-)

Ich glaubte, die Multithreading-Probleme gelöst zu haben. Um die
Systemlast ein klein wenig zu reduzieren, bin ich auf die Idee gekommen,
in der QChessClock in notifyObservers() auf changed zu prüfen. changed
wird gesetzt, wenn von außen ein Knopf gedrückt oder die Bedenkzeit
verändert wird. Bei jedem Aufruf von notifyObservers wird außerdem
überprüft, ob sich die anzuzeigende (also auf Sekunden gerundete)
Bedenkzeit geändert hat oder ob ein Blättchen gefallen ist. Auch dann
wird changed gesetzt. Nur wenn sich etwas geändert hat, wird das Objekt
zum Übertragen des Status gefüllt, und nur dann werden die Observer mit
diesem Objekt benachrichtigt.

Dies führt wie erhofft dazu, dass Observer nicht mehr alle 20 ms,
sondern nur bei einer Benutzeraktion bzw. beim Umspringen der
Sekundenanzeige benachrichtigt werden. In der Swing-GUI funktioniert
auch weiterhin alles.

Schwierigkeiten machen die JUnit-Tests. Die Testklasse implementiert die
Funktionen einer GUI, um die zu testende Klasse anzusprechen. Die
Testklasse registriert sich als Observer. Bislang wurde alle 20 ms die
Update-Funktion von notifyObservers() aufgerufen:

@Override
public final void update(final QChessClockSTO _sto) {
synchronized (this) {
state = _sto.getStatus();
(...) // weitere übertragene Daten
notified = true;
notifyAll();
}
}

Im Test wurde eine Aktion auf der zu testenden Klasse aufgerufen, mit
waitForNotify() auf den eintreffenden update() gewartet und dann die
entsprechenden asserts vorgenommen. Ob ein update() verpasst wurde oder
nicht, war nicht wichtig, der nächste kam ja 20 ms später.

private void waitForNotify() throws InterruptedException {
synchronized (this) {
notified = false;
while (!notified) {
wait();
}
}
}

Durch den Test auf changed erfolgt jetzt nur noch ein einziger update()
als Reaktion auf die Benutzeraktion. Wird der verpasst, kommt kein
weiterer mehr, und waitForNotify hängt in der Endlosschleife. Also
folgende Hilfsfunktion:

private void pressButton(final Buttons _button) throws
InterruptedException {
synchronized (this) {
notified = false;
switch (_button) {
case LEFT_:
sut.moveButtonPressed(LEFT);
break;
(...) // weitere Knöpfe
default:
sut.resetPressed();
break;
}
while (!notified) {
wait();
}
}
}

Im Test wird pressButton() aufgerufen, danach die Asserts durchgeführt.

Ich glaubte, folgendes erreicht zu haben: pressButton holt sich den
Lock, löscht notified und führt die Benutzeraction an der Uhr aus.
Danach wird die Endlosschleife betreten, der Lock freigegeben und auf
notifyAll() gewartet. Irgendwann kommt der update(). Der braucht den
Lock. Kommt der update, bevor wait() erreicht ist, ist der Lock noch
belegt, und update() muss warten. Bekommt update() den Lock, werden die
Daten aktualisiert, notified wird gesetzt, notifyAll() aufgerufen und
der Lock freigegeben. wait() erkennt den notifyAll(), beendet das
Warten, bekommt den Lock zurück. Die Endlosschleife wird beendet, die
Daten sind aktuell und können mit Assert überprüft werden.

Auf QChessClock benutzen die Benutzer-Zugriffsmethoden und
notifyObservers den gleichen Lock. Wenn ein Knopf gedrückt wird, kann
der Lock für die angeforderte Methode nur erhalten werden, wenn
notifyObservers gerade nicht läuft. Während diese Methode ausgeführt
wird, an deren Schluss setChanged(true) aufgerufen wird, kann
notifyObservers nicht ausgeführt werden. Erst wenn die
Benutzer-Zugriffsmethode beendet ist, erfolgt der nächste
notifyObservers. Der sieht changed = true und ruft auf der Testklasse
update() auf.

Soweit die Theorie. Beim Ausführen der Tests kommt es unregelmäßig zu
Fehlern. Tests bleiben einfach mal stehen, weil notified false bleibt.
Da wird ein update() verschluckt. Im Debugger funktioniert alles immer
bestens. Da ist das update schon am Warten, wenn das wait() erreicht
ist, sobald wait() ausgeführt ist, ist notified true, und alles ist gut.
Im echten Ablauf passiert das aus mir unbekannten Gründen anscheinend nicht.

Diesen Fehler konnte ich nicht beobachten, wenn ich eine Testmethode
einzeln ausführe. Führe ich die Testklasse aus, egal ob in Eclipse oder
mit Gradle, tritt der Fehler an einer anscheinend zufälligen Testmethode
auf.

Ich halte das für ein deutliches Zeichen, dass da was mit der
Nebenläufigkeit nicht stimmt. Ich finde den Fehler aber nicht. Wer winkt
mit dem Zaunpfahl?

TIA
QNo
Lothar Kimmeringer
2016-08-24 20:30:10 UTC
Permalink
Post by Christian H. Kuhn
Bislang wurde alle 20 ms die
@Override
public final void update(final QChessClockSTO _sto) {
synchronized (this) {
state = _sto.getStatus();
(...) // weitere übertragene Daten
notified = true;
notifyAll();
}
}
Im Test wurde eine Aktion auf der zu testenden Klasse aufgerufen, mit
waitForNotify() auf den eintreffenden update() gewartet und dann die
entsprechenden asserts vorgenommen. Ob ein update() verpasst wurde oder
nicht, war nicht wichtig, der nächste kam ja 20 ms später.
private void waitForNotify() throws InterruptedException {
synchronized (this) {
notified = false;
while (!notified) {
wait();
}
}
}
Hohl dir den Lock vor dem Aufruf der waitForNotify-Methode. Fuer
detaillierte Analysen wuerde die Nennung der konkreten Klassen
helfen, in denen die Dinge passieren. Ansonsten muesste ich mich
auf die Suche durch deine komplette Sourcebasis machen.


Gruesse, Lothar
--
Lothar Kimmeringer E-Mail: ***@kimmeringer.de
PGP-encrypted mails preferred (Key-ID: 0x8BC3CD81)

Always remember: The answer is forty-two, there can only be wrong
questions!

--- news://freenews.netfront.net/ - complaints: ***@netfront.net ---
Christian H. Kuhn
2016-08-26 17:10:54 UTC
Permalink
Post by Lothar Kimmeringer
Fuer
detaillierte Analysen wuerde die Nennung der konkreten Klassen
helfen, in denen die Dinge passieren.
Zu testende Klasse: de.qno.qchessclock.common.QChessClock (hier
besonders der TimerTask im Konstruktor)
Testklasse: de.qno.qchessclock.common.QChessClockTest

lg
QNo
Marcel Mueller
2016-08-25 09:03:41 UTC
Permalink
Post by Christian H. Kuhn
Immer noch die Schachuhr.
[langer code...]

Das ist mir jetzt etwas zu aufregend, alles durchzugehen, aber
vielleicht ein paar Tips.
Post by Christian H. Kuhn
Im Test wurde eine Aktion auf der zu testenden Klasse aufgerufen, mit
waitForNotify() auf den eintreffenden update() gewartet und dann die
entsprechenden asserts vorgenommen. Ob ein update() verpasst wurde oder
nicht, war nicht wichtig, der nächste kam ja 20 ms später.
private void waitForNotify() throws InterruptedException {
synchronized (this) {
notified = false;
while (!notified) {
wait();
}
}
}
Du musst mit der notify() aufpassen wie ein Höllenhund, denn wenn der
Zielthread gerade mit etwas anderem beschäftigt ist, als mit wait(),
geht selbiges ins Leere. Daher die Booleans. Aber es ist erstaunlich
Fettnäpfchenreich Bedingungsvariablen korrekt zu implementieren.

So ist die Funktion waitForNotify() so wie sie implementiert ist, m.E.
nicht fehlerfrei nutzbar. Sie löscht als erstes notified, und dann
wartet sie. Das notwendige Pattern ist aber:
- notified einmalig initialisieren (eigentlich sogar optional),
- jetzt erst alle thread anstupsen, die notified setzen können,
- und dann wait(),
- notified löschen
- und dann das Ereignis, das zu notified gehört, verarbeiten.
Das kann man mit obiger Funktion nicht erreichen, weil man ja nicht
weiß, wann es so weit ist, die anderen Threads arbeiten zu lassen,
respektive notified unkontrolliert gelöscht wird.
In jedem Fall sind Funktionsname und Funktionsinhalt inkonsistent. Die
Funktion wartet nicht nur.

Die Regel ist, wer notified löscht, muss auch die damit verbundenen
Ereignisse verarbeiten. Wenn das Ereignis also bereits vor Aufruf der
Funktion eintritt, geht es ins Nirwana.

Das ist letztlich, wie bei einem Interrupt-Handler. Der IRQ tritt ein,
ein Handler wird aufgerufen, und /der/ setzt das Flag zurück,
üblicherweise /bevor/ er mit seiner Arbeit der Abarbeitung beginnt, denn
es könnten während der Verarbeitung ja schon weitere Ereignisse
reinpurzeln. Falls er die nach dem Rücksetzen doch schon mit bearbeitet
hat, wird er im schlimmsten Fall noch genau ein weiteres mal ohne
Arbeitsvorrat aufgerufen.
Post by Christian H. Kuhn
Durch den Test auf changed erfolgt jetzt nur noch ein einziger update()
als Reaktion auf die Benutzeraktion. Wird der verpasst, kommt kein
weiterer mehr, und waitForNotify hängt in der Endlosschleife.
So schaut's.
Post by Christian H. Kuhn
Also
private void pressButton(final Buttons _button) throws
InterruptedException {
synchronized (this) {
notified = false;
switch (_button) {
sut.moveButtonPressed(LEFT);
break;
(...) // weitere Knöpfe
sut.resetPressed();
break;
}
while (!notified) {
wait();
}
}
}
Hier passt das Pattern im Prinzip.
Wobei natürlich auf jedes beliebige "notified" gewartet wird. Der Name
ist also nicht sonderlich sprechend.
Post by Christian H. Kuhn
Ich glaubte, folgendes erreicht zu haben: pressButton holt sich den
Lock, löscht notified und führt die Benutzeraction an der Uhr aus.
Danach wird die Endlosschleife betreten, der Lock freigegeben und auf
notifyAll() gewartet. Irgendwann kommt der update(). Der braucht den
Lock. Kommt der update, bevor wait() erreicht ist, ist der Lock noch
belegt, und update() muss warten. Bekommt update() den Lock, werden die
Daten aktualisiert, notified wird gesetzt, notifyAll() aufgerufen und
der Lock freigegeben. wait() erkennt den notifyAll(), beendet das
Warten, bekommt den Lock zurück. Die Endlosschleife wird beendet, die
Daten sind aktuell und können mit Assert überprüft werden.
Hört sich soweit korrekt an, aber überprüfe nochmal die Zugriffe auf die
Bedingungsvariable notified. Normalerweise will man Bedingungsvariablen
nur an genau einer Stelle im Code setzen und nur an genau einer anderen
Löschen. Alles andere ist zumindest potentiell gefährlich, weil dann
verschiedene Bedingungen sich gegenseitig stören können.
(Man muss ein bisschen mit den Begrifflichkeiten hier aufpassen, eine
Bedingung ist nicht notwendigerweise durch ein einziges Boolean
repräsentiert, es kann auch komplexer sein. Und in dem Fall gibt es dann
i.a. auch mehrere Zugriffe auf die Variablen. Das scheint mir aber hier
nicht gegeben.)
Post by Christian H. Kuhn
Auf QChessClock benutzen die Benutzer-Zugriffsmethoden und
notifyObservers den gleichen Lock. Wenn ein Knopf gedrückt wird, kann
der Lock für die angeforderte Methode nur erhalten werden, wenn
notifyObservers gerade nicht läuft. Während diese Methode ausgeführt
wird, an deren Schluss setChanged(true) aufgerufen wird, kann
notifyObservers nicht ausgeführt werden. Erst wenn die
Benutzer-Zugriffsmethode beendet ist, erfolgt der nächste
notifyObservers. Der sieht changed = true und ruft auf der Testklasse
update() auf.
Wie gehören "changed" und "notified" zusammen? Ich habe jetzt keine
Muße, den kompletten Code durchzulesen.
Post by Christian H. Kuhn
Soweit die Theorie. Beim Ausführen der Tests kommt es unregelmäßig zu
Fehlern. Tests bleiben einfach mal stehen, weil notified false bleibt.
Wenig überraschend, falls waitForNotify() dabei jemals durchlaufen wird.
Post by Christian H. Kuhn
Da wird ein update() verschluckt. Im Debugger funktioniert alles immer
bestens.
Das alte Spiel mit Race-Conditions. Die kann man nicht Debuggen. Selbst
ein Logging, kann manchmal durch die dafür erforderliche Synchronisation
schon dafür sorgen, dass es geht.
Post by Christian H. Kuhn
Diesen Fehler konnte ich nicht beobachten, wenn ich eine Testmethode
einzeln ausführe. Führe ich die Testklasse aus, egal ob in Eclipse oder
mit Gradle, tritt der Fehler an einer anscheinend zufälligen Testmethode
auf.
Bei Race Conditions weiß man nie, wann sie Zünden. Das Kann sein, wenn
schönes Wetter ist, wenn in China ein Sack Reis platzt oder auch nur
einmal in der Lebensdauer des Universums.
Post by Christian H. Kuhn
Ich halte das für ein deutliches Zeichen, dass da was mit der
Nebenläufigkeit nicht stimmt.
Auf jeden Fall.
Post by Christian H. Kuhn
Ich finde den Fehler aber nicht. Wer winkt
mit dem Zaunpfahl?
Guck Dir mal die Bedingungsvariablen genau an (Verwendunganachweis),
Nicht nur in waitForNotify(). Wie gesagt, eine Bedingung sollte
normalerweise nur an genau einer Stelle zurückgesetzt werden, nämlich
da, wo sie behandelt wird.


Marcel
Christian H. Kuhn
2016-08-26 18:21:04 UTC
Permalink
Post by Marcel Mueller
- notified einmalig initialisieren (eigentlich sogar optional),
- jetzt erst alle thread anstupsen, die notified setzen können,
- und dann wait(),
- notified löschen
- und dann das Ereignis, das zu notified gehört, verarbeiten.
Ja. Eigentlich selbstverständlich. Mach ich sonst immer so. Hier hab ich
dem Oracle-Tutorial geglaubt, ohne selbst zu denken ...
Post by Marcel Mueller
Wie gehören "changed" und "notified" zusammen? Ich habe jetzt keine
Muße, den kompletten Code durchzulesen.
Dank dieser Frage fand ich den Fehler. Hoffe ich. Bislang sind keine
JUnit-Tests mehr gescheitert. Was eine notwendige, keine hinreichende
Bedingung ist, da bin ich inzwischen mißtrauisch ...

notified ist die Kontrollvariable in der /Test/-Klasse
de.qno.qchessclock.common.QChessClockTest. Nach den von dir angeregten
Änderungen wird sie in setUp() gelöscht, in update() gesetzt und in
waitForNotify() NACH der Endlosschleife wieder gelöscht. Das ist auch
der Sinn: Die Testklasse ist eine Mock-GUI, simuliert Benutzeraktionen
und muss nach den Aktionen auf eine Reaktion der zu testenden Klasse
warten, bevor die Asserts verarbeitet werden können.

changed ist die Kontrollvariable in der /zu testenden/ Klasse
de.qno.qchessclock.common.QChessClock. Hier wird alle 20 ms über einen
TimerTask notifyObservers() aufgerufen. notifyObservers() erstellt und
verschickt nur dann ein Status-Objekt (durch Aufruf von
QChessClockObservers.update()), wenn sich der sichtbare Zustand der Uhr
verändert hat.

changed wird gesetzt:
- durch Betätigen eines Knopfes (moveButtonPressed(), stopPressed(),
resetPressed()),
- durch Setzen einer neuen Bedenkzeit (setNewTimers()),
- durch Ändern der Bedenkzeit um mindestens eine Sekunde (wird in
notifyObservers() selbst festgestellt),
- durch Blättchenfall (wird in notifyObservers() selbst festgestellt).

changed wird an einer einzigen Stelle gelösch:
- in notifyObservers() (der Methode, die changed auch auswertet) nach
Erstellen und Verschicken des Status-Objekts.

notified kann also in update() nur gesetzt werden, wenn der Aufruf von
update durch gesetztes changed in notifyObservers() erlaubt wird. Dieses
Problem war in alten Versionen nicht sichtbar. Dort wurde changed nicht
verwendet, update() wurde alle 20 ms aufgerufen. Wurde ein Aufruf
verpasst, wirkte der nächste, und der Fehler wäre nur mit Zeitmessungen
feststellbar gewesen.

Der Fehler war folgender: Ich wollte Resourcen sparen, indem ich den
durch synchronized gelockten Code-Abschnitt kurz halten wollte.
Insbesondere ist es nicht nötig, die for-Schleife mit den
update()-Aufrufen im synchronized-Abschnitt zu haben, da hier nicht mehr
auf den Status von QChessClock zugegriffen wird. Das ist auch richtig.
Dabei ist mir allerding auch eine Abfrage von changed und das
abschließende setChanged(false) aus dem synchronized gerutscht.

Dadurch ist eine race condition entstanden. Folgende Event-Reihenfolge
wurde möglich:
1. der synchronized-Teil von notifyObservers() wird ausgeführt. changed
ist am Ende des Blocks true
2. die for-Schleife mit QChessClockObservers.update() wird begonnen
3. „gleichzeitig“ tritt ein Ereignis ein, das changed wieder auf true setzt
4. die for-Schleife in notifyObservers() wird beendet, changed wird
gelöscht.
5. jetzt erst startet der nächste getimte Lauf von notifyObservers().
changed sollte durch die Aktion in 3. true sein, ist aber in 4. ohne
Auswertung gelöscht worden.

Durch ein paar Zeilentranspositionen kam setChanged(false) in den
gelockten Bereich. Dadurch wurde diese race condition vermieden.

Snapshot:
https://www.qno.de/gitweb/?p=qchessclock.git;a=snapshot;h=304120d97a7ca850851b3c913d344494162b4597;sf=tgz

Eclipse, Gradle (lokal) und Jenkins/Gradle (remote) führten die Tests
wiederholt ohne Fehler aus. Das gibt Hoffnung.

Vielen Dank
QNo

Lesen Sie weiter auf narkive:
Loading...