Profilerstellung mit Java Visual VM ~ Grundlegende Verwendung ~

Über diesen Artikel

Dieser Artikel beschreibt die grundlegende Verwendung von Visual VM, einem Java Profiler.

Was ist Java Visual VM?

Java Visual VM ist ein Java Profiling Tool. Die Erklärung auf der offiziellen Website lautet wie folgt. Es scheint, dass die Funktion durch Plugin erweitert werden kann.

Java VisualVM ist eine intuitive grafische Benutzeroberfläche, die detaillierte Informationen zu einer auf Java-Technologie basierenden Anwendung (Java-Anwendung) bereitstellt, die auf einer bestimmten Java Virtual Machine (JVM) ausgeführt wird. ist. Java VisualVM hilft Java-Anwendungsentwicklern bei der Fehlerbehebung von Anwendungen sowie bei der Überwachung und Verbesserung der Anwendungsleistung. Mit Java VisualVM können Entwickler Heap-Dumps generieren und analysieren, Speicherlecks identifizieren, Garbage Collections durchführen und überwachen sowie einfache Speicher- und CPU-Profile erstellen.

Installieren und booten (Ubuntu)

Für Ubuntu ist die Installation auf einen Schlag "apt-get". Beginnen Sie nach der Installation mit 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 Visual VM-Bildschirm

Bildschirm

Threads-Bildschirm

CPU Sampler

Memory Sampler

CPU Profiler

Memory Profiler

Ausgabe des Profil- / Probenergebnisses

Auf Visual VM ist eine Reihe von Visualisierungen möglich. Wenn Sie andererseits eine detailliertere Analyse oder eine andere Visualisierung durchführen möchten, möchten Sie nur diese Daten extrahieren. Visual VM bietet auch einen Mechanismus dafür.

Export Profile Result

Führen Sie mit Profiler-> Das Ergebnis von Stop aus. Es kann in Formaten wie xml, html und csv ausgegeben werden. Ein Beispiel für CSV ist unten dargestellt. Eine Zeile für jede Methode wird formatiert und in Form von "Self Time", "Total Time" und "Invocations" ausgegeben. Es ist einfach. (Ich wusste es nicht, bis ich diesen Artikel schrieb ...

"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

Sie können während der Profilerstellung und Abtastung einen Schnappschuss mit der Schaltfläche "Schnappschuss" erstellen. Das Ergebnis kann im Profiler-Snapshot-Datei- (nps), XML-, HTML- und CSV-Format ausgegeben werden. Ein Beispiel für CSV ist unten dargestellt. Das führende Leerzeichen wird als CSV-Datei exportiert, die die Tiefe des Aufrufbaums darstellt. Da es sich um die Gesamtzeit handelt, wird der Wert einschließlich der Ausführungszeit der Methode des Unterbaums als Spalte beschrieben. Außerdem ist die Zeile mit "Selbstzeit" im Kind die Ausführungszeit (Selbstzeit) und die Anzahl der Aufrufe des Elternteils selbst. Analysieren Sie diese CSV von Anfang an und aggregieren Sie sie als "Selbstzeit", "Aufrufe" der Summe jeder Methode, was dem obigen Ergebnis des Exportprofils entspricht.

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

(Referenz) Stichproben- / Profillast usw.

Der hier verwendete Java-Prozess ist eine Web + DB-Anwendung, die von Spring Boot gestartet wird. Daher kann die Last durch Auslösen einer großen Anzahl von Anfragen erhöht werden. Hier wird der Effekt der Profilerstellung anhand der Antwortzeit angezeigt.

Basic performance

Zuallererst Leistung ohne Sampling und 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

Erstens die Durchsatzleistung ** 14.000 req / sec **, wenn nur Sampling ohne Profiling verwendet wird. Obwohl eine gewisse Verschlechterung zu beobachten ist, ist die Leistung mit der vergleichbar, wenn nichts unternommen wird.

$ 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

Als nächstes verschlechtert sich die Durchsatzleistung während der Profilerstellung erheblich auf ** 368 req / sec **. Es ist natürlich, aber wenn Sie eine gewisse Leistung erzielen möchten, während Sie die Leistung in Echtzeit erfassen, ist die Richtlinie eine grundlegende Stichprobe.

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

Referenzmaterial

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