Masterfield

A Masterfield Oktatóközpont szakmai blogja. Minden, ami a tanfolyamokról kimaradt

Friss topikok

  • gyuria: Na végre, már nagyon vártam Már annyi téma összejött, hogy egy jó darabig biztos kitart :) (2008.10.24. 08:04) Elindultunk

Linkblog

Java holtpont vizsgálata thread dump segítségével - 1. rész

2008.09.17. 12:41 | gbujdoso | Szólj hozzá!

Címkék: java collection jvm stack thread holtpont dump masterfield thread dump hashtable deadlock util

Szinte minden Java programozó kedvenc és legtöbbet használt adatszerkezetei a java.util csomag osztályai: Hashtable, LinkedList, Vector, LinkedHashMap, stb. Szeretjük őket használni, hiszen könnyen kezelhetőek, dinamikusak, kényelmesen hívható függvényeket tartalmaznak és generikus adattárolást tesznek lehetővé.

Azonban van két alapvető problémájuk, ami miatt mindig alaposan meg kell gondolni használatukat. Illetve nagyon pontosan ismernünk kell a működésüket a háttérben. Az első a performancia alakulás használatukkor, a második pedig a holtpont  kialakulásának veszélye. Előbbiről egy másik posztban fogok írni. Most inkább a másodikra mutatok be egy példát és közben megnézzük egy hasznos "eszköz", a thread dump használatát és azt, hogy hogyan segít megtalálni a kódban a holtpontokat.

 

Később részletesen foglalkozunk a holtponttal, itt most csak a definícióját szeretném megadni: Holtpont egyrészt akkor fordulhat elő a vezérlés során, ha a folyamatok egy adott halmazában minden egyes elem leköt néhány erőforrást, és ugyanakkor várakozik is néhányra. Ha ilyen esetben a folyamatok egy része olyan erőforrásra várakozik, amelyek mások elfoglaltak, akkor a tevékenységek "megmerevedhetnek".

Ref.: http://hu.wikipedia.org/wiki/Holtpont

 

Sokan nem is sejtik, hogy ezek a beépített osztályok nem mennének át a Nasa stabilitás tesztjén :) Számos alkalmazásnál kritikusnak számít egy esetleges holtpont vagy végtelen ciklusba kerülés, éppen ezért matematikai úton vagy átfogó teszttel szükséges kimutatni egy adott kódrészletről, hogy abban soha sem alakulhat ki holtpont.

 

A CUTE (Concolic Unit Testing Engine) fejlesztői szerint a Java 1.4-es java.util.Collection könyvtárában számos holtpontot vagy végtelen ciklust okozó hiba van.

A weboldalukon (http://osl.cs.uiuc.edu/~ksen/cute/?page=cases) lévő táblázat alapján ezek a következők:

Name

Run time

# of

# of

% Branch

# of Functions

# of Bugs Found

 

in seconds

Paths

Threads

Coverage

Tested

data races/deadlocks/infinite loops/exceptions

Vector

5519

20000

5

76.38

16

1/9/0/2

ArrayList

6811

20000

5

75

16

3/9/0/3

LinkedList

4401

11523

5

82.05

15

3/3/1/1

LinkedHashSet

7303

20000

5

67.39

20

3/9/0/2

TreeSet

7333

20000

5

54.93

26

4/9/0/2

HashSet

7449

20000

5

69.56

20

19/9/0/2

 

Gondoljunk csak a lefagyott marsjáróra vagy egy irányíthatatlanná vált repülőre és máris megértjük, hogy miért írnak ezekre a célszámítógépekre saját operációs rendszert és alakítanak ki rajtuk saját programozási környezetet, akár saját programnyelvet is és miért vetik alá átfogó tesztnek programjaikat.

 

Ha fellapozzuk a Sun hivatalos Java hiba adatbázisát, akkor néhány perc keresgélés után máris találunk élő, a legutolsó 1.6-os verzióban is létező hibát a Hashtable osztályban.

http://bugs.sun.com/bugdatabase/view_bug.do?bug_id=6582568

A leírás szerint a Hashtable.equals metódusa holtpontot okoz. Az biztos, hogy nem az equals függvény a Hashtable leggyakrabban használt függvénye, de azért ez érdekes.

 

Próbáljuk ki a hiba leírásában szereplő (egyszerűsített!) példakódot, ami két hash táblát hasonlít össze egymással párhuzamosan két különböző szálon:

 

public class Bug {

 

    static Hashtable makeTable() {

            Hashtable h = new Hashtable();

            h.put(1,1);

            return h;

    }

 

    static Thread comparer(final Hashtable h1, final Hashtable h2) {

             return new Thread(new Runnable() {

public void run() {

                        long t0 = System.nanoTime();

                        while (System.nanoTime() - t0 < 1000*1000*1000)

                              h1.equals(h2);

      System.out.println("Finish!");

}

 });

    }

 

    public static void main(String[] args) throws Throwable {

            final Hashtable h1 = makeTable();

            final Hashtable h2 = makeTable();

            Thread job1 = comparer(h1, h2);

            Thread job2 = comparer(h2, h1);

            job1.start();

            job2.start();

            job1.join();

            job2.join();

    }

}

 

Elindítva azonnal elő is áll a holtpont, a „Finish!” üzenet soha nem íródik ki, a program „lefagy”. Pedig elvileg a ciklus csak 1 másodpercig fut, utána kilép(ne).

 

Mi történhetett a futás alatt?

 

Indítsuk a fenti példát Windows cmd ablakból és nyomjuk meg a Ctrl+Break gombokat. Windows alatt a Ctrl+Break együttes megnyomásával a Sun JVM kiírja a standard outputra a teljes thread dumpját:

 

2008-11-01 13:06:15

Full thread dump Java HotSpot(TM) Client VM (11.0-b12 mixed mode, sharing):

 

"Thread-1" prio=6 tid=0x02a9bc00 nid=0x120 waiting for monitor entry [0x02e6f000..0x02e6fb14]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at java.util.Hashtable.size(Hashtable.java:206)

        - waiting to lock <0x24100158> (a java.util.Hashtable)

        at java.util.Hashtable.equals(Hashtable.java:742)

        - locked <0x24100180> (a java.util.Hashtable)

        at Bug$1.run(Bug.java:16)

        at java.lang.Thread.run(Thread.java:619)

 

"Thread-0" prio=6 tid=0x02a9ac00 nid=0x9bc waiting for monitor entry [0x02e1f000..0x02e1fb94]

   java.lang.Thread.State: BLOCKED (on object monitor)

        at java.util.Hashtable.get(Hashtable.java:333)

        - waiting to lock <0x24100180> (a java.util.Hashtable)

        at java.util.Hashtable.equals(Hashtable.java:755)

        - locked <0x24100158> (a java.util.Hashtable)

        at Bug$1.run(Bug.java:16)

        at java.lang.Thread.run(Thread.java:619)

 

"Low Memory Detector" daemon prio=6 tid=0x02a81800 nid=0x27c runnable [0x00000000..0x00000000]

   java.lang.Thread.State: RUNNABLE

 

"CompilerThread0" daemon prio=10 tid=0x02a7b400 nid=0x920 waiting on condition [0x00000000..0x02d2f6c0]

   java.lang.Thread.State: RUNNABLE

 

"Attach Listener" daemon prio=10 tid=0x02a79c00 nid=0x9d0 runnable [0x00000000..0x00000000]

   java.lang.Thread.State: RUNNABLE

 

"Signal Dispatcher" daemon prio=10 tid=0x02a78800 nid=0xe70 waiting on condition [0x00000000..0x00000000]

   java.lang.Thread.State: RUNNABLE

 

"Finalizer" daemon prio=8 tid=0x02a73800 nid=0xf5c in Object.wait() [0x02c3f000..0x02c3fa14]

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

        - waiting on <0x241003c0> (a java.lang.ref.ReferenceQueue$Lock)

        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:116)

        - locked <0x241003c0> (a java.lang.ref.ReferenceQueue$Lock)

        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:132)

        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

 

"Reference Handler" daemon prio=10 tid=0x02a6f000 nid=0x434 in Object.wait() [0x02bef000..0x02befb14]

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

        - waiting on <0x24100150> (a java.lang.ref.Reference$Lock)

        at java.lang.Object.wait(Object.java:485)

        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)

        - locked <0x24100150> (a java.lang.ref.Reference$Lock)

 

"main" prio=6 tid=0x002a6800 nid=0x1c8 in Object.wait() [0x0090f000..0x0090fe54]

   java.lang.Thread.State: WAITING (on object monitor)

        at java.lang.Object.wait(Native Method)

        - waiting on <0x241000e8> (a java.lang.Thread)

        at java.lang.Thread.join(Thread.java:1143)

        - locked <0x241000e8> (a java.lang.Thread)

        at java.lang.Thread.join(Thread.java:1196)

        at Bug.main(Bug.java:29)

 

"VM Thread" prio=10 tid=0x02a6d800 nid=0xeac runnable

 

"VM Periodic Task Thread" prio=10 tid=0x02a83400 nid=0x448 waiting on condition

 

JNI global references: 608

 

 

Found one Java-level deadlock:

=============================

"Thread-1":

  waiting to lock monitor 0x02a736ec (object 0x24100158, a java.util.Hashtable),

  which is held by "Thread-0"

"Thread-0":

  waiting to lock monitor 0x02a73754 (object 0x24100180, a java.util.Hashtable),

  which is held by "Thread-1"

 

Java stack information for the threads listed above:

===================================================

"Thread-1":

        at java.util.Hashtable.size(Hashtable.java:206)

        - waiting to lock <0x24100158> (a java.util.Hashtable)

        at java.util.Hashtable.equals(Hashtable.java:742)

        - locked <0x24100180> (a java.util.Hashtable)

        at Bug$1.run(Bug.java:16)

        at java.lang.Thread.run(Thread.java:619)

"Thread-0":

        at java.util.Hashtable.get(Hashtable.java:333)

        - waiting to lock <0x24100180> (a java.util.Hashtable)

        at java.util.Hashtable.equals(Hashtable.java:755)

        - locked <0x24100158> (a java.util.Hashtable)

        at Bug$1.run(Bug.java:16)

        at java.lang.Thread.run(Thread.java:619)

 

Found 1 deadlock.

 

Heap

 def new generation   total 960K, used 64K [0x24010000, 0x24110000, 0x244f0000)

  eden space 896K,   0% used [0x24010000, 0x24010028, 0x240f0000)

  from space 64K, 100% used [0x24100000, 0x24110000, 0x24110000)

  to   space 64K,   0% used [0x240f0000, 0x240f0000, 0x24100000)

 tenured generation   total 4096K, used 50K [0x244f0000, 0x248f0000, 0x28010000)

   the space 4096K,   1% used [0x244f0000, 0x244fc868, 0x244fca00, 0x248f0000)

 compacting perm gen  total 12288K, used 21K [0x28010000, 0x28c10000, 0x2c010000)

   the space 12288K,   0% used [0x28010000, 0x28015408, 0x28015600, 0x28c10000)

    ro space 8192K,  66% used [0x2c010000, 0x2c56a540, 0x2c56a600, 0x2c810000)

    rw space 12288K,  53% used [0x2c810000, 0x2ce723f8, 0x2ce72400, 0x2d410000)

 

A dumpban láthatjuk, hogy a JVM maga is felismerte a holtpontot és erről ad is információt:

Found one Java-level deadlock:

=============================

"Thread-1":

  waiting to lock monitor 0x02a736ec (object 0x24100158, a java.util.Hashtable),

  which is held by "Thread-0"

"Thread-0":

  waiting to lock monitor 0x02a73754 (object 0x24100180, a java.util.Hashtable),

  which is held by "Thread-1"

 

A két szál, amit a példában létrehoztunk a közös hash táblákhoz való hozzáféréskor holtpontba kerül. Ez a holtpont lényege: mindkét szál valamilyen közös erőforrásra vár, amit a másik foglal, így egymást kölcsönösen blokkolják. A végrehajtás egyik szálon sem tud folytatódni.

 

 

A bejegyzés trackback címe:

https://masterfield.blog.hu/api/trackback/id/tr41745333

Kommentek:

A hozzászólások a vonatkozó jogszabályok  értelmében felhasználói tartalomnak minősülnek, értük a szolgáltatás technikai  üzemeltetője semmilyen felelősséget nem vállal, azokat nem ellenőrzi. Kifogás esetén forduljon a blog szerkesztőjéhez. Részletek a  Felhasználási feltételekben és az adatvédelmi tájékoztatóban.

Nincsenek hozzászólások.
süti beállítások módosítása