Java VisualVMでProfiling 〜基本の使い方〜

本記事について

本記事では、JavaのProfilierであるVisualVMの基本的な使い方について記す。

Java VisualVMとは

Java VisualVMはJavaのProfiling Toolである。公式サイトによる説明は以下の通り。Pluginによって機能拡張も可能なようである。

Java VisualVMは、指定されたJava仮想マシン(JVM)でJavaテクノロジベースのアプリケーション(Javaアプリケーション)が実行されているときに、そのJavaアプリケーションに関する詳細な情報を提供する直感的なグラフィカル・ユーザー・インタフェースです。
Java VisualVMは、Javaアプリケーションの開発者がアプリケーションのトラブルシューティングを行なったり、アプリケーションのパフォーマンスをモニターおよび改善したりするのに役立ちます。Java VisualVMを使用すると、開発者はヒープ・ダンプの生成および解析、メモリー・リークの特定、ガベージ・コレクションの実行およびモニタリング、およびメモリーとCPUの簡易プロファイリングの実行が可能になります。

Installと起動 (ubuntu)

ubuntuの場合インストールはapt-get一発。インストールが終わったら visualvmで起動

$ apt-cache search visualvm
libvisualvm-jni - All-in-One Java Troubleshooting Tool (JNI libraries)
visualvm - All-in-One Java Troubleshooting Tool
$ sudo apt-get install visualvm
...
$ visualvm

Java VisualVM画面

Monitor画面

Threads画面

CPU Sampler

Memory Sampler

CPU Profiler

Memory Profiler

Profile/Sample結果の出力

一通りの可視化はVisualVM上で可能である。一方でさらに詳細な解析や他の可視化をしたい場合にはそのデータのみを抜き出したくなる。そのための仕組みもVisualVMは提供している。

Export Profile Result

Profilerにて実行 -> Stopの結果を出力する。xml, html, csvなどの形式で出力できる。以下にcsvの例を示す。Methodごと1行で, Self Time, Total Time, Invocationsの形で整形されて出力される。楽である。（本記事書くまで知らんかった...

"Hot Spots - Method","Self Time [%]","Self Time","Total Time","Invocations"
"org.apache.tomcat.util.net.SocketProcessorBase.run()","44.50689","99142.459 ms","222583.639 ms","1338"
"com.zaxxer.hikari.util.ConcurrentBag.borrow(long, java.util.concurrent.TimeUnit)","21.153963","47122.053 ms","47152.68 ms","1293"
"org.apache.coyote.AbstractProcessorLight.process(org.apache.tomcat.util.net.SocketWrapperBase, org.apache.tomcat.util.net.SocketEvent)","11.541287","25709.091 ms","110834.896 ms","1309"
"org.springframework.jdbc.datasource.DataSourceUtils.doGetConnection(javax.sql.DataSource)","10.117057","22536.51 ms","72184.265 ms","1310"
"org.apache.tomcat.util.net.NioBlockingSelector$BlockPoller.remove(org.apache.tomcat.util.net.NioEndpoint.NioSocketWrapper, int)","3.0905285","6884.386 ms","6896.103 ms","2657"
"org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse)","2.8102305","6260.001 ms","35805.26 ms","7722"
"org.apache.catalina.connector.CoyoteAdapter.service(org.apache.coyote.Request, org.apache.coyote.Response)","2.0718734","4615.255 ms","52156.903 ms","1290"

Export Snapshot

Profiling途中, Sampling中にSnapshotボタンによってSnapshotを取得することができる。その結果を、Profiler Snapshot File (nps), xml, html, csv形式で出力できる。以下にcsvの例を示す。先頭の空白がCall Treeの深さを表すcsv fileとしてexportされる。Columnとして、Total Timeことから、Sub TreeのMethodの実行時間を含んだ値が記される。また、子の中でSelf timeとある行がその親自身の実行時間(Self time), Invocation回数である。このcsvを頭からParseして、各MethodのTotalのself time, invocationsとして集計したものが、上記 Export Profile Resultに相当する。

"Call Tree - Method","Total Time [%]","Total Time","Invocations",
" All threads","0.0","0","0"
"  HikariPool-1 connection adder","100.0","18030427","1"
"   java.util.concurrent.ThreadPoolExecutor$Worker.run()","100.0","18030427","1"
"    Self time","99.29557","17903416","1"
"    java.util.concurrent.FutureTask.run()","0.70442593","127011","6416"
"     com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call()","0.52456886","94582","6416"
"      com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.call()","0.428692","77295","6416"
"       Self time","0.30533385","55053","6416"
"       com.zaxxer.hikari.pool.HikariPool$PoolEntryCreator.shouldCreateAnotherConnection()","0.123352595","22241","6416"
"        com.zaxxer.hikari.pool.HikariPool.getTotalConnections()","0.10495592","18924","6416"
"         Self time","0.08798461","15864","6416"
"         com.zaxxer.hikari.util.ConcurrentBag.size()","0.016965766","3059","6416"
"        Self time","0.01839668","3317","6416"
"      Self time","0.09587682","17287","6416"
"     Self time","0.17985153","32428","6416"
"  http-nio-8080-exec-200","100.0","10865782","1"
"   org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run()","100.0","10865783","1"
"    java.util.concurrent.ThreadPoolExecutor$Worker.run()","99.99997","10865779","1"
"     org.apache.tomcat.util.net.SocketProcessorBase.run()","97.8199","10628897","14"

(参考) Sampling/Profiling負荷など

ここで用いているJava ProcessはSpring Bootで起動したWeb+DBアプリである。よって大量のRequestを投げ込むことでその負荷を上げることができる。ここでは、その応答時間からProfilingの影響を示す。

Basic performance

まずはSampling, Profilingをしない場合の性能 15,500 req/sec

$ ab -c 100 -n 10000 http://localhost:8080/
...
Concurrency Level:      100
Time taken for tests:   0.643 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      5020000 bytes
HTML transferred:       3650000 bytes
Requests per second:    15558.12 [#/sec] (mean)
Time per request:       6.428 [ms] (mean)
Time per request:       0.064 [ms] (mean, across all concurrent requests)
Transfer rate:          7627.13 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   0.6      0       3
Processing:     1    6   2.7      5      27
Waiting:        1    5   2.7      5      27
Total:          1    6   2.6      6      27
WARNING: The median and mean for the initial connection time are not within a normal deviation
        These results are probably not that reliable.

Percentage of the requests served within a certain time (ms)
  50%      6
  66%      7
  75%      7
  80%      8
  90%     10
  95%     11
  98%     14
  99%     16
 100%     27 (longest request)

With Sampling

まずProfilingをせず、Samplingのみの場合のスループット性能 14,000 req/sec。多少の劣化が見られるものの、何もしない場合と比較しても遜色ない性能である。

$ ab -c 100 -n 10000 http://localhost:8080/
...
Concurrency Level:      100
Time taken for tests:   0.718 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      5020000 bytes
HTML transferred:       3650000 bytes
Requests per second:    13918.23 [#/sec] (mean)
Time per request:       7.185 [ms] (mean)
Time per request:       0.072 [ms] (mean, across all concurrent requests)
Transfer rate:          6823.20 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   1.0      0       9
Processing:     1    6   3.1      6      30
Waiting:        1    6   3.1      5      29
Total:          1    7   3.2      7      31

Percentage of the requests served within a certain time (ms)
  50%      7
  66%      7
  75%      8
  80%      9
  90%     11
  95%     13
  98%     16
  99%     18
 100%     31 (longest request)

With Profiling

次にProfiling時のスループット性能 368 req/sec と大幅に劣化する。当たり前ですけれど、性能をリアルタイムに把握しつつも性能もある程度は欲しい、という場合には基本Sampling、という方針になる。

$ ab -c 100 -n 10000 http://localhost:8080/
...
Document Length:        365 bytes

Concurrency Level:      100
Time taken for tests:   27.130 seconds
Complete requests:      10000
Failed requests:        0
Total transferred:      5020000 bytes
HTML transferred:       3650000 bytes
Requests per second:    368.60 [#/sec] (mean)
Time per request:       271.299 [ms] (mean)
Time per request:       2.713 [ms] (mean, across all concurrent requests)
Transfer rate:          180.70 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    1   1.3      0      13
Processing:     1  270 1248.8     40   23375
Waiting:        1  261 1202.5     37   23375
Total:          1  271 1248.7     41   23377

Percentage of the requests served within a certain time (ms)
  50%     41
  66%     94
  75%    121
  80%    153
  90%    304
  95%    722
  98%   3112
  99%   6118
 100%  23377 (longest request)

参考資料

• Java VisualVM
  • https://docs.oracle.com/javase/jp/8/docs/technotes/tools/unix/jvisualvm.html