Profiling with Java Visual VM ~ Basic usage ~

About this article

In this article, I will describe the basic usage of Visual VM, which is a Java Profiler.

What is Java Visual VM?

Java Visual VM is a Java Profiling Tool. The explanation on the official website is as follows. It seems that the function can be extended by Plugin.

Java VisualVM is an intuitive graphical user interface that provides detailed information about a Java Technology-based application (Java application) running in a specified Java Virtual Machine (JVM). is. Java VisualVM helps Java application developers troubleshoot their applications and monitor and improve their performance. Java VisualVM allows developers to generate and analyze heap dumps, identify memory leaks, perform and monitor garbage collection, and perform simple memory and CPU profiling.

Install and boot (ubuntu)

For ubuntu Installation is ʻapt-getone shot. Start withvisualvm` after installation

$ 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 Visual VM screen

Monitor screen

Threads screen

CPU Sampler

Memory Sampler

CPU Profiler

Memory Profiler

Profile / Sample result output

A set of visualizations is possible on Visual VM. On the other hand, if you want to perform more detailed analysis or other visualization, you want to extract only that data. Visual VM also provides a mechanism for that.

Export Profile Result

Execute with Profiler-> Output the result of Stop. It can be output in xml, html, csv, etc. format. An example of csv is shown below. One line for each method is formatted and output in the form of Self Time, Total Time, ʻInvocations`. It's easy. (I didn't know until I wrote this article ...

"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

You can take a snapshot by pressing the Snapshot button during Profiling and Sampling. The result can be output in Profiler Snapshot File (nps), xml, html, csv format. An example of csv is shown below. The leading whitespace is exported as a csv file that represents the depth of the Call Tree. As Column, since it is Total Time, the value including the execution time of Method of Sub Tree is written. In addition, the line with Self time in the child is the execution time (Self time) and the number of invocations of the parent itself. Parsing this csv from the beginning and totaling it as self time, ʻinvocations` of Total of each Method corresponds to the above 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"

(Reference) Sampling / Profiling load, etc.

The Java Process used here is a Web + DB application started by Spring Boot. Therefore, the load can be increased by throwing a large number of Requests. Here, the effect of Profiling is shown from the response time.

Basic performance

First of all, performance without Sampling and 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

First, throughput performance ** 14,000 req / sec ** when only Sampling is used without Profiling. Although some deterioration is seen, the performance is comparable to that when nothing is done.

$ 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

Next, the throughput performance during Profiling deteriorates significantly to ** 368 req / sec **. It is natural, but if you want to have some performance while grasping the performance in real time, the policy is basic 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)

Reference material

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