2014-06-16

Java Performance Monitoring

Book


Addison Wesley - Java Performance (2012)
Chapter 4 - Java Performance Monitoring 













需要被關注的 GC 資料

  • 目前使用的 Garbage collector
  • Java heap 的大小
  • The young/old/permanent generation 空間大小
  • Minor/Full GC 的周期、頻率、回收情況
  • GC 之前與之後，Java heap 使用情況
  • GC 之前與之後，young/old/permanent generation 使用情況
  • Old 和 Permanent generation 空間不足時，都會觸發 full GC
  • Java 應用程式是否呼叫了 System.gc()

GC 報告

  • 在預設的行為下，Full GC 會同時釋放 young/old/permanent generation 的空間。好處是，可以利用少量的 GC 工作去回收很多在 young generation 的物件，這樣一來 old generation 原本參考 young generation 物件的物件，就會解除參考關係，就能夠沒有牽掛的被回收。
  • 「-XX:-ScavengeBeforeFullGC」可以關閉 Full GC 時，也進行 Minor GC的行為。
  • 「-XX:+PrintGCDetails」可以用來列印 GC 資訊。
  • GC 資訊：
    （一）Throughput 垃圾回收器的 minor GC，log 如下：
    [GC
        [PSYoungGen: 99952K->14688K(109312K)]
        422212K->341136K(764672K), 0.0631991 secs]
        [Times: user=0.83 sys=0.00, real=0.06 secs]
    1. GC 標籤表示這是一個 minor GC
    2. PSYoungGen 表示是一個使用 throughput collector 的 多執行緒 young generation garbage collector，格式與解釋如下：
       GC 種類 GC前
       佔用空間
      		 GC後
       佔用空間      		 young generation
       總容量 
       PSYoungGen: 99952K-> 14688K (109312K)
    3. 「+XX:+UseParallelGC」或「+XX:+UseParallelOldGC」可以啟動 PSYoungGen。
    4. 422212K->341136K(764672K), 0.0631991 secs，這行資訊代表在 GC 前後 Java heap 的使用狀況，格式與解釋如下：
      GC 前
       Java heap 被佔用大小      		  GC 後
       Java heap 被佔用大小      		 Java heap
       總容量      		 GC 運行時間
       422212K -> 341136K (764672K)  , 0.0631991 secs
    5. Old generation 空間的計算：Java heap 總容量 - young generation 總容量
                                                  764672K - 109312K = 655360K
    6. [Times: user=0.83 sys=0.00, real=0.06 secs]，user 是與OS無關，單純 GC 所花的 CPU 時間；sys 是代表 OS 使用代表 GC 指令所花的 CPU 時間；real 是 GC 運行時，真正時鐘的時間，以秒為單位，四捨五入到小數第二位。



    （二）Throughput 垃圾回收器的 full GC
    [Full GC
        [PSYoungGen: 11456K->0K(110400K)]
        [PSOldGen: 651536K->58466K(655360K)]
        662992K->58466K(765760K)
        [PSPermGen: 10191K->10191K(22528K)],
        1.1178951 secs]
        [Times: user=1.01 sys=0.00, real=1.12 secs]
    1. Full GC 標籤表示這是一個 full GC
    2. PSYoungGen 同（一）解釋
    3. PSOldGen 表示是一個使用 throughput collector 的 多執行緒 old generation garbage collector，格式與解釋如下：
       GC 種類 GC前
       佔用空間
      		 GC後
       佔用空間      		 young generation
       總容量 
       PSOldGen: 651536K-> 58466K (655360K)
    4. 「+XX:+UseParallelOldGC」可以啟動 PSOldGen。
    5. 662992K->58466K(765760K) 代表 Java heap 的使用率，這是 young 和 old generation 空間在 GC 前後所共同累積的使用量。
    6. [PSPermGen: 10191K->10191K(22528K)] 代表 Permanent generation 空間的資訊，格式與解釋如下：
      GC 種類 GC前
      佔用空間
      		 GC後
      佔用空間      		 Permanent generation  總容量
       PSPermGen: 10191K-> 10191K (22582K)
    7. 「+XX:+UseParallelGC」或「+XX:+UseParallelOldGC」可以啟動 PSPermGen。
    8. 1.1178951 secs 代表 GC 運行的時間。
    9. 最後一行，提供 CPU 時間與運行時間的資訊，同（一）解釋。

    （三）CMS GC 生命週期
    [GC
        [1 CMS-initial-mark: 13991K(773376K)]
        14103K(773376K), 0.0023781 secs]
        [Times: user=0.00 sys=0.00, real=0.00 secs]
    [CMS-concurrent-mark-start]
    [GC
        [ParNew: 2077K->63K(2112K), 0.0126205 secs]
        17552K->15855K(773376K), 0.0127482 secs]
        [Times: user=0.01 sys=0.00, real=0.01 secs]
    [CMS-concurrent-mark: 0.267/0.374 secs]
        [Times: user=4.72 sys=0.01, real=0.37 secs]
    [GC
        [ParNew: 2111K->64K(2112K), 0.0190851 secs]
        17903K->16154K(773376K), 0.0191903 secs]
        [Times: user=0.01 sys=0.00, real=0.02 secs]
    [CMS-concurrent-preclean-start]
    [CMS-concurrent-preclean: 0.044/0.064 secs]
        [Times: user=0.11 sys=0.00, real=0.06 secs]
    [CMS-concurrent-abortable-preclean-start]
    [CMS-concurrent-abortable-clean] 0.031/0.044 secs]
        [Times: user=0.09 sys=0.00, real=0.04 secs]
    [GC
        [YG occupancy: 1515 K (2112K)
        [Rescan (parallel) , 0.0108373 secs]
        [weak refs processing, 0.0000186 secs]
        [1 CMS-remark: 16090K(20288K)]
        17242K(773376K), 0.0210460 secs]
        [Times: user=0.01 sys=0.00, real=0.02 secs]
    [GC
        [ParNew: 2112K->63K(2112K), 0.0716116 secs]
        18177K->17382K(773376K), 0.0718204 secs]
        [Times: user=0.02 sys=0.00, real=0.07 secs]
    [CMS-concurrent-sweep-start]
    [GC
        [ParNew: 2111K->63K(2112K), 0.0830392 secs]
        19363K->18757K(773376K), 0.0832943 secs]
        [Times: user=0.02 sys=0.00, real=0.08 secs]
    [GC
        [ParNew: 2111K->0K(2112K), 0.0035190 secs]
        17527K->15479K(773376K), 0.0036052 secs]
        [Times: user=0.00 sys=0.00, real=0.00 secs]
    [CMS-concurrent-sweep: 0.291/0.662 secs]
        [Times: user=0.28 sys=0.01, real=0.66 secs]
    [GC
        [ParNew: 2048K->0K(2112K), 0.0013347 secs]
        17527K->15479K(773376K), 0.0014231 secs]
        [Times: user=0.00 sys=0.00, real=0.00 secs]
    [CMS-concurrent-reset-start]
    [CMS-concurrent-reset: 0.016/0.016 secs]
        [Times: user=0.01 sys=0.00, real=0.02 secs]
    [GC
        [ParNew: 2048K->1K(2112K), 0.0013936 secs]
        17527K->15479K(773376K), 0.0014814 secs]
        [Times: user=0.00 sys=0.00, real=0.00 secs]
    1. CMS 生命週期從 initial mark（CMS-initial-mark）階段開始，一直到 concurrent reset（CMS-concurrent-reset）結束。
    2. CMS-concurrent-mark 代表 concurrent mark 階段結束
    3. CMS-concurrent-sweep 代表 concurrent sweep 階段結束
    4. CMS-concurrent-preclean 和 CMS-concurrent-abortable-preclean 代表標示了一個可以併行且準備好要執行 remake 階段的工作。
    5. CMS-concurrent-reset 代表 CMS 已經完成，可以準備下一次的 CMS GC。
    6. 觀察 CMS-concurrent-sweep-start 和 CMS-concurrent-sweep 之間所進行的 minor GC 資訊，就可以知道 Java heap 有多少空間被釋放了。如果 Java heap 只有被釋放一點點，代表 "浪費了 CPU 去回收一點點物件" 或是 "物件被提升到 old generation 空間的速率等於或大於 CMS concurrent sweep 階段回收物件的速率"，可以用這個觀察點來進行調效。
    7. 「-XX:+PrintTenuringDistribution」，tenuring distribution 是一個用來顯示 young generation 空間中，survivor 區域內物件的年紀，當一個物件年紀超過了年老閥值（tenuring threshold），它就會從 young generation 空間提升到 old generation 空間。
    8. 如果物件太快被提升到 old generation 空間，CMS garbage collector 就無法保持一定的速率進行 GC，這樣會導致 old generation 沒有足夠空間容納從 young generation 提升過來的物件而導致 "concurrent mode failure" 。這樣也會更容易讓 old generation 的空間變得更加破碎，所以 JVM 遇到這種情況，就會進行 full GC，把破碎的空間進行壓實（compacting），而這個操作是非常耗時的，被暫停的執行緒也必須等待更久的時間。可以注意 GC 報告裡，是否有 "concurrent mode failure" 的訊息，如果有就要判斷是不是應該調整。

Date 和 Time stamps

  • 「-XX:+PrintGCTimeStamps」可以在每次 GC 報告中印出 time stamp。time stamp 表示 JVM 啟動後所經過的秒數，與「-XX:+PrintGCDetails」一起使用。
    77.233: [GC
        [PSYoungGen: 99952K->14688K(109312K)]
        422212K->341136K(764672K), 0.0631991 secs]
        [Times: user=0.83 sys=0.00, real=0.06 secs]
    在 GC 標籤前面帶有 time stamp。
  • 「-XX:+PrintGCDateStamps」在 Java 6 update 4 以後有提供，格式如下：
    『YYYY-MM-DD-T-HH-MM-SS-mmm』
    2010-11-21T09:57:10.518-0500:[GC
        [PSYoungGen: 99952K->14688K(109312K)]
        422212K->341136K(764672K), 0.0631991 secs]
        [Times: user=0.83 sys=0.00, real=0.06 secs]
  • 「-Xloggc:<filename>」可以將 GC 報告導到檔案，這樣就可以進行離線分析，同樣需要跟「-XX:+PrintGCDetails」一起使用。

Application Stopped Time and Concurrent Time

  • 「-XX:+PrintGCApplicationConcurrentTime」和「-XX:+PrintGCApplicationStoppedTime」可以得知 safepoint 操作間的運作時間和 Java 執行緒被阻塞的時間。觀察 safepoint 的延遲事件可以用來判斷這個操作對 JVM 的衝擊。
    Application time: 0.5279058 seconds
    [GC
        [ParNew: 4032K->64K(4032K), 0.0447854 secs]
        10154K->8648K(32704K), 0.0449156 secs]
        [Times: user=0.01 sys=0.00, real=0.04 secs]
    Total time for which application threads were stopped: 0.0453124 seconds
    Application time: 0.9063706 seconds
    [GC
        [ParNew: 4032K->64K(4032K), 0.0464574 secs]
        12616K->11187K(32704K), 0.0465921 secs]
        [Times: user=0.01 sys=0.00, real=0.05 secs]
    Total time for which application threads were stopped: 0.0470484 seconds

    當你看到 "Application time:" 和 "Total time for which application threads where stopped:" 就表示進行了 safepoint 操作。

    以上報告說明了，程式運行的時間大約花了 0.53秒～0.91秒，而 minor GC 大約花了 0.045秒～0.047秒，表示應用程式大約花了 5%～8% 的時間進行 minor GC。


JIT Compiler

  • 「-XX:+PrintCompilation」可以用來監控 HotSpot JIT compiler 的活動，會輸出類似已下的報告：
    7 java.lang.String::indexOf (151 bytes)
    8% ! sun.awt.image.PNGImageDecoder::produceImage @ 960 (1920 bytes)
    9 ! sun.awt.image.PNGImageDecoder::produceImage (1920 bytes)
    10 java.lang.AbstractStringBuilder::append (40 bytes)
    11 n java.lang.System::arraycopy (static)
    12 s java.util.Hashtable::get (69 bytes)
    13 b java.util.HashMap::indexFor (6 bytes)
    14 made zombie java.awt.geom.Path2D$Iterator::isDone (20 bytes)
    其格式是：<id> <type> <method name> [bci] <(# of bytes)>

        id: compile id
        type: none 或 以下之一:
                 % (osr)、
                 * | n (native method)、
                 s (synchronized method)、
                 ! (method has exception handler)、
                 b (interpreter blocked)、
                 1 (compile without full optimization),
                 made zombie (compile method no longer valid),
                 made not entrant (method deoptimized)
        bci: @ ## 為 osr 編譯器的 bytecode index
        # of bytes: 方法 bytecode 的 bytes 數


Class Loading

  • HotSpot VM 會載入在 permanent generation space 內所有類別的metadata。
  • 因為只要 permanent generation 空間滿了，HotSpot 就會啟動 full GC ，因此，監控類別載入活動和 permanent generation 空間的使用率是非常重要的。
  • full GC 報告中會顯示類別被卸載的情況：
    [Full GC
        [Unloading class sun.reflect.GeneratedConstructorAccessor3]
        [Unloading class sun.reflect.GeneratedConstructorAccessor8]
        [Unloading class sun.reflect.GeneratedConstructorAccessor11]
        [Unloading class sun.reflect.GeneratedConstructorAccessor6]
        8566K->5871K(193856K), 0.0989123 secs]
    報告中指出，有四個類別被卸載 (Uloading)，底下的空間釋放也許 permanent generation 空間需要大一些喔!
  • 「-XX: PermSize」指定 permanent generation 空間的初始大小
  • 「-XX: MaxPermSize」指定 permanent generation 空間的最大容量
  • 為了要避免 full GC 讓 permanent generation 的 committed 空間有放大或縮小的可能，最好將 PermSize 和 MaxPermSize 設成一樣大。


Java Application Monitoring

  • 應用程式等級的監控，通常會使用 log 來觀察效能，但有一些應用程式會內件使用 MBean 來監控。
  • Quick Lock Contention Monitoring
    1. 「jstack」命令，可以用來截取 thread dumps，以觀察目前是否有鎖的競爭。報告顯示如下：

      ”Read Thread-33” prio=6 tid=0x02b1d400 nid=0x5c0 runnable
      [0x0424f000..0x0424fd94]
          java.lang.Thread.State: RUNNABLE
              at Queue.dequeue(Queue.java:69)
              - locked <0x22e88b10> (a Queue)
              at ReadThread.getWorkItemFromQueue(ReadThread.java:32)
              at ReadThread.run(ReadThread.java:23)


      ”Writer Thread-29” prio=6 tid=0x02b13c00 nid=0x3cc waiting for monitor
      entry [0x03f7f000..0x03f7fd94]
          java.lang.Thread.State: BLOCKED (on object monitor)
              at Queue.enqueue(Queue.java:31)
              - waiting to lock <0x22e88b10> (a Queue)
              at WriteThread.putWorkItemOnQueue(WriteThread.java:54)
              at WriteThread.run(WriteThread.java:47)


      ”Writer Thread-26” prio=6 tid=0x02b0d400 nid=0x194 waiting for monitor
      entry [0x03d9f000..0x03d9fc94]
          java.lang.Thread.State: BLOCKED (on object monitor)
              at Queue.enqueue(Queue.java:31)
              - waiting to lock <0x22e88b10> (a Queue)
              at WriteThread.putWorkItemOnQueue(WriteThread.java:54)
              at WriteThread.run(WriteThread.java:47)


      ”Read Thread-23” prio=6 tid=0x02b08000 nid=0xbf0 waiting for monitor entry
      [0x03c0f000..0x03c0fb14]
          java.lang.Thread.State: BLOCKED (on object monitor)
              at Queue.dequeue(Queue.java:55)
              - waiting to lock <0x22e88b10> (a Queue)
              at ReadThread.getWorkItemFromQueue(ReadThread.java:32)
              at ReadThread.run(ReadThread.java:23)
      執行緒 Thread-33 成功獲得共享佇列鎖 (Shared queue lock) ，這個鎖被標示成：- locked <0x22e88b10> (a Queue)

      其他的執行緒，正在等待同樣的鎖(位址一樣)： - waiting to lock <0x22e88b10> (a Queue)
    2. 如果鎖的位址在堆疊追踪裡是不同的，就表示執行緒不是在競爭同樣的鎖。



Graphical Tools

JConsole
  • 發佈在 Java 5 之後的 JDK。
  • 應用程式啟動時必須加上 "-Dcom.sun.management.jmxremote" 屬性，若沒有，JConsole 連入時看到的應用程式會是灰色的。JDK 6 之後的版本不需要加這個屬性。
  • 要進行遠端監控應用程式，在應用程式啟動時必須加上 "-Dcom.sun.management.port" 以及 "-Dcom.sun.management.ssl" 。
  • JConsole 最有的是 heap memory 的圖形化分析報告，可以用來觀察一段時間裡 JVM 記憶體的使用狀況。
  • JConsole 定義 heap 是由 eden space、survivor space、old/tenured generation space 所組成。Non-heap 是由 permanent generaion space 和 code cache 組成。

    上面 5 個長條圖，依序是 old gen / eden space / survivor space / code cache / perm gen
  • JVM 記憶體衡量指標

    Used：目前記憶體使用量，包含 "reachable" 和 "unreachable"。
    Committed：JVM 保證還可以使用的空間，永遠大於 Used。
    Max：目前記憶體還可以被使用的量，JVM 若要增加記憶體用量，一但增加超過這個值，記憶體配置就會失敗。
    GC time：每一次 GC 的生命週期和暫停所累積的時間，會有很多行。



VisualVM
  • 發佈在 Java 6 update 7 JDK，表示啟動必須要 JDK 6。
  • 另快，可以下載獨立版本：http://visualvm.dev.java.net
  • 選單的三個節點：Local、Remote、Snapshots
    1. Local 節點：VisualVM 會自動偵測本地端的 Java 應用程式，並加到 Local 清單中。
    2. Remote 節點：偵測遠端主機裡，可被監控的 Java 應用程式，並加到 Remote 清單中。Java 應用程式可以透過兩種方式提供 VisualVM 連接：
      方式
      步驟
      jstatd daemon
      (1)    建立權限原則檔
      grant codebase "file:${java.home}/../lib/tools.jar" {
         permission java.security.AllPermission;
      };

      (2)    啟動 jstatd 並指定要使用的 port 和權限原則檔
      JAVA_HOME/bin/jstatd -p 1199 -J-Djava.security.policy=jstatd.all.policy

      (3)    透過 jps 連入遠端 jstatd daemon 以監控應用程式
      JMX
      (1)    啟動時加入 system properties
      -Dcom.sun.management.jmxremote.authenticate=<true/false>
      -Dcom.sun.management.jmxremote.ssl=<true/false>
      -Dcom.sun.management.jmxremote.port=<number>
      (2)    啟動 JVM
      (3)    檢查 port 是否已經打開並在偵聽
    3. Snapshots 節點：Java 應用程式狀態的 shapshot 檔案清單。
  • Threads 視窗的功用
    1. 執行緒的顏色代表：running/sleeping/blocked/waiting/contenting on a monitor lock。
    2. 可用來觀察哪些執行緒最活躍？哪些執行緒在競爭鎖。
    3. 可以獲得 thread dump 的資訊。
    4. 可以 profiling 並存成 snapshot，供其他開發人員討論。遠端應用程式只能進行 CPU profiling，而本地端應用程式則能進行 CPU 與 Memory profiling。
    5. 載入 binary heap dumps 功能，則可以載入由 JConsole、jmap 或是由「-XX:+HeapDumpOnOutOfMemoryError」鎖產生的 heap dump。

張貼者： 於
標籤：

沒有留言 :

張貼留言

訂閱： 張貼留言 ( Atom )