Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > de.comp.lang.java > #13035 > unrolled thread

JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem

Back to article view | Back to de.comp.lang.java

Contents

  JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem "Christian H. Kuhn" <qno-news@qno.de> - 2016-08-24 16:36 +0200
    Re: JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem Lothar Kimmeringer <news200709@kimmeringer.de> - 2016-08-24 22:30 +0200
      Re: JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem "Christian H. Kuhn" <qno-news@qno.de> - 2016-08-26 19:10 +0200
    Re: JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem Marcel Mueller <news.5.maazl@spamgourmet.org> - 2016-08-25 11:03 +0200
      Re: JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem "Christian H. Kuhn" <qno-news@qno.de> - 2016-08-26 20:21 +0200

#13035 — JUnit-Tests funktionieren nur manchmal: Synchronisations-Problem

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

[toc] | [next] | [standalone]

#13036

Christian H. Kuhn wrote:

> 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();
>             }
>         }
>     }

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: spamfang@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: news@netfront.net ---

[toc] | [prev] | [next] | [standalone]

#13038

Am 24.08.2016 um 22:30 schrieb 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

[toc] | [prev] | [next] | [standalone]

#13037

On 24.08.16 16.36, Christian H. Kuhn wrote:
> Immer noch die Schachuhr.
[langer code...]

Das ist mir jetzt etwas zu aufregend, alles durchzugehen, aber 
vielleicht ein paar Tips.

> 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.


> 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.

> 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();
>              }
>          }
>      }

Hier passt das Pattern im Prinzip.
Wobei natürlich auf jedes beliebige "notified" gewartet wird. Der Name 
ist also nicht sonderlich sprechend.

> 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.)

> 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.


> 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.

> 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.

> 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.

> Ich halte das für ein deutliches Zeichen, dass da was mit der
> Nebenläufigkeit nicht stimmt.

Auf jeden Fall.

> 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

[toc] | [prev] | [next] | [standalone]

#13039

Am 25.08.2016 um 11:03 schrieb Marcel Mueller:
> On 24.08.16 16.36, Christian H. Kuhn wrote:
> - 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 ...

> 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

[toc] | [prev] | [standalone]

Back to top | Article view | de.comp.lang.java

csiph-web