Profilage avec Java Visual VM ~ Utilisation de base ~

À propos de cet article

Cet article décrit l'utilisation de base de Visual VM, qui est un Java Profiler.

Qu'est-ce que Java Visual VM?

Java Visual VM est un outil de profilage Java. L'explication sur le site officiel est la suivante. Il semble que la fonction puisse être étendue par Plugin.

Java VisualVM est une interface utilisateur graphique intuitive qui fournit des informations détaillées sur une application basée sur la technologie Java (application Java) s'exécutant sur une machine virtuelle Java (JVM) spécifiée. est. Java VisualVM aide les développeurs d'applications Java à dépanner les applications et à surveiller et améliorer les performances des applications. Java VisualVM permet aux développeurs de générer et d'analyser les vidages de tas, d'identifier les fuites de mémoire, d'effectuer et de surveiller les garbage collection et d'effectuer un profilage simple de la mémoire et du processeur.

Installer et démarrer (ubuntu)

Pour ubuntu, l'installation est ʻapt-getone shot. Après l'installation, commencez parvisualvm`

$ 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

Écran Java Visual VM

Écran

Écran Threads

CPU Sampler

Memory Sampler

CPU Profiler

Memory Profiler

Sortie de résultat de profil / échantillon

Un ensemble de visualisations est possible sur Visual VM. D'autre part, si vous souhaitez effectuer une analyse plus détaillée ou une autre visualisation, vous souhaitez extraire uniquement ces données. Visual VM fournit également un mécanisme pour cela.

Export Profile Result

Exécutez avec Profiler-> Sortez le résultat de Stop. Il peut être produit dans des formats tels que xml, html et csv. Un exemple de csv est présenté ci-dessous. Une ligne pour chaque méthode est formatée et sortie sous la forme de «Self Time», «Total Time», «Invocations». C'est facile. (Je ne savais pas avant d'écrire cet 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

Vous pouvez prendre un instantané avec le bouton «Snapshot» pendant le profilage et l'échantillonnage. Le résultat peut être affiché au format Profiler Snapshot File (nps), xml, html, csv. Un exemple de csv est présenté ci-dessous. Le blanc de début est exporté sous forme de fichier csv qui représente la profondeur de l'arborescence des appels. Puisqu'il s'agit du temps total, la valeur incluant le temps d'exécution de la méthode du sous-arbre est décrite comme Colonne. De plus, la ligne avec Self time dans l'enfant est l'heure d'exécution (Self time) et le nombre d'appels du parent lui-même. Analyser ce csv depuis le début et l'agréger en tant que «self time», «invocations» du total de chaque méthode, ce qui correspond au résultat du profil d'exportation ci-dessus.

"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"

(Référence) Charge d'échantillonnage / profilage, etc.

Le processus Java utilisé ici est une application Web + DB démarrée par Spring Boot. Par conséquent, la charge peut être augmentée en lançant un grand nombre de requêtes. Ici, l'effet du profilage est indiqué à partir du temps de réponse.

Basic performance

Tout d'abord, des performances sans échantillonnage ni profilage ** 15 500 req / s **

$ 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

Tout d'abord, les performances de débit ** 14 000 req / s ** lorsque seul l'échantillonnage est utilisé sans profilage. Bien qu'une certaine détérioration soit constatée, les performances sont comparables à celles lorsque rien n'est fait.

$ 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

Ensuite, les performances de débit pendant le profilage se détériorent considérablement à ** 368 req / s **. C'est naturel, mais si vous voulez avoir des performances tout en appréhendant les performances en temps réel, la politique est l'échantillonnage de base.

$ 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)

Matériel de référence

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