tifyty

pure Java, what else ?

Hamis ébresztés

Amikor wait-et használunk, azt mindig ciklusban kell tennünk. Valahogy így:

Ez egy pszeudo kód

while( someConditionIsNotMet ){
  wait();
  if( conditionIsMet ){
    doSomething();
    }
  }

De miért?


Megjegyzés: amikor wait-et használunk, akkor mielőtt nekilátnánk, előtte erősen elgondolkozunk azon, hogy miért is tesszük ezt. Nem lehet, hogy éppen keretrendszert fejlesztek? Mélyen magamba nézek, és elolvasom Viczián István cikkét, minden szava arany. És abbahagyom a keretrendszer írását.

Ez a blog azonban pont olyan dolgokkal foglalkozik, amik ilyen “érdekes” Java technológiák. Ez pedig nem jelenti azt, hogy ezeket az eszközöket használni kell, de érdemes ismerni őket, azért, hogy ha egyszer szembejönnek, akkor ne érjen meglepetés. Végül is, a Java open source és néha előfordul, hogy debuggolás közben le kell ásni akár egy keretrendszer mélyére is. Néha. És akkor jó, ha legalább esélyünk van, hogy megértsük mi történik ott a mélyben.

Az egyik mondás az, hogy azért, mert a notifyAll() meghívása esetén minden olyan szál felébred, amelyik ebben a wait()-ben van, és futtatható, de nem feltétlenül futó állapotba kerül. Egész pontosan egy szál kerül futó állapotba, hiszen az ébredés után meg kell szereznie a futásához azt a monitort, amelyik a wait végrehajtásakor megvolt. A futó szál elvégzi amit kell, és utána a someConditionIsNotMet már lehet ismét true a második, sokadik szálnak nem feltétlenül marad mit tennie.

Ez logikus, (nem én találtam ki, coderanch-on írták ezt a marhaságot) de sajnos félrevezető. Lehetne ez is az ok, ám ha ez lenne az ok, akkor a notifyAll() száműzésével a probléma megoldódott. Ha csak egy notify() hívás történik, akkor csak az egyik szál ébred fel, elvégzi a dolgát, majd alszik tovább, vagy kiszáll, bent marad, teszi, amit akar, vagy pontosabban amit a programozó leprogramozott (és nem azt amit a programozó akart, mert a kettő nem mindig ugyan az 🙂 ).

A valóság az, hogy azért kell a ciklus, mert egy wait() felébredhet úgy is, hogy egyetlen egy notify() vagy notifyAll() sem történt a rendszerben, sőt a szál interruptot sem kapott. (Az interrupt egy másik történet, mot abba nem megyünk bele.) A Java szabvány az 566. oldalon azt mondja, hogy

Implementations are permitted, although not encouraged, to perform “spurious wake-ups”, that is, to remove threads from wait sets and thus enable resumption without explicit instructions to do so.

Azaz, az implementációk (java környezetek) számára megengedett, bár nem javasolt, hogy “hamis ébresztést” hajtsanak végre, azaz kivegyék az alvó szálat a várakozók közül, és engedélyezzék a folytatást anélkül, hogy ilyen utasítást kaptak volna.

Ezzel véget is érhetne a történet ha a programozók katonák lennének, és parancsot hajtanának végre: ez van, így kell, kész. Végrehajtani. Minden wait() ciklusba kerül és kész.

A programozó (a jó programozó) azonban nem ilyen. Sokkal inkább hasonlít egy három éves gyerekre, aki mindenre azt kérdezi “miért?”. Miért megy az autó? Mert a belső égésű motor… Megérti ezt egy gyerek? Nem. Akkor mit mond a szülő? Vagy azt, hogy fogd be a szádat édes fiam/lányom, és ne kérdezzél, mert attól csak dühös lesz az apád, vagy kitalál valamit. (Szerintem mind a kettő rossz, azt kell elmondani ami igaz, és meg fogsz lepődni, hogy milyen sokat megért belőle.) A kitalálás az itt is megy. Spurious wakeup. Mi az, miért van? Mert a kis manók, azok… Aha!

Az egyik ilyen történet az volt, hogy a processz kaphat egy signal-t. A másik, hogy egyes processzor megvalósításokon elég költséges (idő, memória whatever) lenne ennek az elkerülése. Na ez utóbbit nem tudom ellenőrizni, ám a signal-t igen! És akkor most jöjjön a recept: végy egy egyosztályos programot:

package tifyty;

public class App {

	private synchronized void  run() {

		try {
			wait();
			System.out.println("Woke up");
		} catch (InterruptedException e) {
			System.out.println("Interrupted.");
		}
	}

	public static void main(String[] args) {
		new App().run();
	}
}

(Ez most tényleges copy/paste, minden egyes sor.) Fordítsd le maven-nel:

$ mvn clean install
[INFO] Scanning for projects...
[INFO]                                                                         
[INFO] ------------------------------------------------------------------------
[INFO] Building spurious 1.0-SNAPSHOT
[INFO] ------------------------------------------------------------------------
[INFO] 
[INFO] --- maven-clean-plugin:2.4.1:clean (default-clean) @ spurious ---
[INFO] Deleting /Users/verhasp/blogcode/spurious/target
[INFO] 
[INFO] --- maven-resources-plugin:2.4.3:resources (default-resources) @ spurious ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /Users/verhasp/blogcode/spurious/src/main/resources
[INFO] 
[INFO] --- maven-compiler-plugin:2.3.2:compile (default-compile) @ spurious ---
[INFO] Compiling 1 source file to /Users/verhasp/blogcode/spurious/target/classes
[INFO] 
[INFO] --- maven-resources-plugin:2.4.3:testResources (default-testResources) @ spurious ---
[INFO] Using 'UTF-8' encoding to copy filtered resources.
[INFO] skip non existing resourceDirectory /Users/verhasp/blogcode/spurious/src/test/resources
[INFO] 
[INFO] --- maven-compiler-plugin:2.3.2:testCompile (default-testCompile) @ spurious ---
[INFO] Compiling 1 source file to /Users/verhasp/blogcode/spurious/target/test-classes
[INFO] 
[INFO] --- maven-surefire-plugin:2.7.2:test (default-test) @ spurious ---
[INFO] Surefire report directory: /Users/verhasp/blogcode/spurious/target/surefire-reports

-------------------------------------------------------
 T E S T S
-------------------------------------------------------
Running tifyty.AppTest
Tests run: 1, Failures: 0, Errors: 0, Skipped: 0, Time elapsed: 0.02 sec

Results :

Tests run: 1, Failures: 0, Errors: 0, Skipped: 0

[INFO] 
[INFO] --- maven-jar-plugin:2.3.1:jar (default-jar) @ spurious ---
[INFO] Building jar: /Users/verhasp/blogcode/spurious/target/spurious-1.0-SNAPSHOT.jar
[INFO] 
[INFO] --- maven-install-plugin:2.3.1:install (default-install) @ spurious ---
[INFO] Installing /Users/verhasp/blogcode/spurious/target/spurious-1.0-SNAPSHOT.jar to /Users/verhasp/.m2/repository/tifyty/spurious/1.0-SNAPSHOT/spurious-1.0-SNAPSHOT.jar
[INFO] Installing /Users/verhasp/blogcode/spurious/pom.xml to /Users/verhasp/.m2/repository/tifyty/spurious/1.0-SNAPSHOT/spurious-1.0-SNAPSHOT.pom
[INFO] ------------------------------------------------------------------------
[INFO] BUILD SUCCESS
[INFO] ------------------------------------------------------------------------
[INFO] Total time: 5.156s
[INFO] Finished at: Wed Aug 15 09:30:57 CEST 2012
[INFO] Final Memory: 15M/138M
[INFO] ------------------------------------------------------------------------

Utána indítsd el a programot,

$ java -cp target/spurious-1.0-SNAPSHOT.jar tifyty.App

és egy másik terminál ablakból küldj neki signal-okat:

$ kill -1 `jps |grep App|awk '{print $1;}'`

És a program kilép. Még lehet neki küldeni más signal-okat is. Ezek közül

$ kill -3 `jps |grep App|awk '{print $1;}'`

esetén a program nem áll le, viszont érdekes dolgokat ír ki:

2012-08-15 09:38:52
Full thread dump Java HotSpot(TM) 64-Bit Server VM (23.0-b21 mixed mode):

"Service Thread" daemon prio=5 tid=0x00007f904984f000 nid=0x1162ef000 runnable [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread1" daemon prio=5 tid=0x00007f904984e000 nid=0x1161ec000 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" daemon prio=5 tid=0x00007f904984c800 nid=0x1160e9000 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=5 tid=0x00007f9049849800 nid=0x115fe6000 waiting on condition [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=5 tid=0x00007f904905c000 nid=0x115cde000 in Object.wait() [0x0000000115cdd000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007e4e057f0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:135)
	- locked <0x00000007e4e057f0> (a java.lang.ref.ReferenceQueue$Lock)
	at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:151)
	at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:177)

"Reference Handler" daemon prio=5 tid=0x00007f904905b000 nid=0x115bdb000 in Object.wait() [0x0000000115bda000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007e4e05370> (a java.lang.ref.Reference$Lock)
	at java.lang.Object.wait(Object.java:503)
	at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:133)
	- locked <0x00000007e4e05370> (a java.lang.ref.Reference$Lock)

"main" prio=5 tid=0x00007f9049800800 nid=0x10e0a1000 in Object.wait() [0x000000010e0a0000]
   java.lang.Thread.State: WAITING (on object monitor)
	at java.lang.Object.wait(Native Method)
	- waiting on <0x00000007e4eb3708> (a tifyty.App)
	at java.lang.Object.wait(Object.java:503)
	at tifyty.App.run(App.java:12)
	- locked <0x00000007e4eb3708> (a tifyty.App)
	at tifyty.App.main(App.java:20)

"VM Thread" prio=5 tid=0x00007f904982f800 nid=0x115ad8000 runnable 

"GC task thread#0 (ParallelGC)" prio=5 tid=0x00007f904980d800 nid=0x1116f4000 runnable 

"GC task thread#1 (ParallelGC)" prio=5 tid=0x00007f904980e000 nid=0x1117f7000 runnable 

"VM Periodic Task Thread" prio=5 tid=0x00007f9049837800 nid=0x1163f2000 waiting on condition 

JNI global references: 117

Heap
 PSYoungGen      total 24320K, used 858K [0x00000007e4e00000, 0x00000007e6920000, 0x0000000800000000)
  eden space 20864K, 4% used [0x00000007e4e00000,0x00000007e4ed6b60,0x00000007e6260000)
  from space 3456K, 0% used [0x00000007e65c0000,0x00000007e65c0000,0x00000007e6920000)
  to   space 3456K, 0% used [0x00000007e6260000,0x00000007e6260000,0x00000007e65c0000)
 ParOldGen       total 55552K, used 0K [0x00000007aea00000, 0x00000007b2040000, 0x00000007e4e00000)
  object space 55552K, 0% used [0x00000007aea00000,0x00000007aea00000,0x00000007b2040000)
 PSPermGen       total 21248K, used 2692K [0x00000007a9800000, 0x00000007aacc0000, 0x00000007aea00000)
  object space 21248K, 12% used [0x00000007a9800000,0x00000007a9aa10d0,0x00000007aacc0000)

Ezzel tehát lehet használni futó programból információk kinyerni? Igen, lehet, dokumentált lehetőség.

$ kill -4 `jps |grep App|awk '{print $1;}'`

esetén a program

#
# A fatal error has been detected by the Java Runtime Environment:
#
#  SIGILL (0x4) at pc=0x00007fff939e667a, pid=928, tid=140735251044704
#
# JRE version: 7.0_04-b21
# Java VM: Java HotSpot(TM) 64-Bit Server VM (23.0-b21 mixed mode bsd-amd64 compressed oops)
# Problematic frame:
# C  [libsystem_kernel.dylib+0x1567a]  mach_msg_trap+0xa
#
# Failed to write core dump. Core dumps have been disabled. To enable core dumping, try "ulimit -c unlimited" before starting Java again
#
# An error report file with more information is saved as:
# /Users/verhasp/blogcode/spurious/hs_err_pid928.log
#
# If you would like to submit a bug report, please visit:
#   http://bugreport.sun.com/bugreport/crash.jsp
#
Abort trap: 6

ezt írja ki a konzolra. Ez is érdekes. A hs_err_pid928.log fájl tartalmát nem másolom ide. 🙂

Ki lehet próbálgatni a többi signal-t is. Én megtettem. Egyik esetben sem írta ki, hogy Woke up.

Konklúzió

Továbbra sem tudjuk, hogy miért ébredhet fel egy szál notify vagy intterupt nélkül, de nem az operációs rendszer szintű signal az, ami miatt. De felébredhet, mert a szabvány ezt mondja, és a szabvány, az szabvány.

3 responses to “Hamis ébresztés

  1. István Verhás (@verhasi) szeptember 19, 2012 10:00 de.

    A konklúzió csak arra az egy jvm implementációra vonatkozik amit kipróbáltál. A szabvány megengedi a jvm implementációnak, hogy ilyet tegyen de az az egy amit kipróbáltál nem csinál ilyet az operációs rendszer szintű signal-ok hatására.

  2. Kofa szeptember 19, 2012 10:28 de.

    Igen, a SIGQUIT (3-as signal) dokumentált dolog, további lehetőség a jstack tool; konzolon Ctrl+Break ugyanezt csinálja, illetve JMX-en is lehet dumpot kérni:
    http://www.java2s.com/Code/Java/Development-Class/ThisFullThreadDumpclassdemonstratesthecapabilitytogetafullthreaddumpandalsodetectdeadlockremotely.htm

    Mi csinálunk olyat, hogy shutdown-kor thread dumpot készítünk, amiből látszik, ha pl. szálak socket olvasáson állnak a JDBC driverben (tehát van egy sejtésünk arról, miért indította újra az ügyfél a Tomcatet). Sőt, egy spéci URL-en keresztül is tudunk dumpot generálni a szerver logjába (mivel signalokat nem feltétlenül van jogosultságunk küldeni production környezetben).

  3. Richard O. Legendi szeptember 22, 2012 2:55 du.

    A signalos kísérletek érdekesek. BTW az Effective Javaban is írnak erről valahol a Threades részben.

    Small suggestion: Mavent minek kevertél bele? 🙂 Ha a közérthetőség a lényeg, akkor full felesleges, teljesen irreleváns, egyszerűbb a kísérleted reprodukálása egy sima `javac` paranccsal, így csak zavaró zaj. Ha a részletesség, akkor meg a `pom.xml`-t hiányolom 🙂

    PS: A SyntaxHighlighteren van gomb, ami copy&paste-eli az egész kódot (külön kiemelted, hogy minden sort másolni kell) – btw van benne egy typo a hoveren: “másoláa”. About-ra is @ABOUT@-ot ír ki. Bár ezt nem tudom, hogy a cucc ilyen, vagy csak a customizálás maradt ki.

Vélemény, hozzászólás?

Adatok megadása vagy bejelentkezés valamelyik ikonnal:

WordPress.com Logo

Hozzászólhat a WordPress.com felhasználói fiók használatával. Kilépés / Módosítás )

Twitter kép

Hozzászólhat a Twitter felhasználói fiók használatával. Kilépés / Módosítás )

Facebook kép

Hozzászólhat a Facebook felhasználói fiók használatával. Kilépés / Módosítás )

Google+ kép

Hozzászólhat a Google+ felhasználói fiók használatával. Kilépés / Módosítás )

Kapcsolódás: %s

%d blogger ezt kedveli: