Breizhcamp : Guide de survie du développeur dans une application (Java) qui rame

Guide de survie du dveloppeur dans une

application (Java) qui rame

BreizhCamp 2016 #BzhCmp@blep

Les ordres de grandeur importent

Salaire: 1000 --> 1300

Page speed: 30s --> 20s Seuls les changements d'ordre de grandeur

( >300%) changent la perception de la performance de l'application


About me

Brice LEPORINI

Dveloppeur Java / Scala


http://the-babel-tower.github.io/ @blep

Lenteurs ou performance ?


Scott Oaks - Java Performance The definitive guide

There is no magical -XX:+RunReallyFast option


Lenteurs avec 1 utilisateur?

Ouvrir un shell sur la plateforme dexcution


Collecter des donnes sur l'environnement

concern!




CPU bound? GC?


Les problmes lis la mmoire

Terminal avec jstat -gcutil


Young Generation

Heap

Eden

From Space To Space

Old Generation

Survivor

1: new

2: minor 1

3: n minors

4: promotion


GC: la master classhttp://www.infoq.com/presentations/Understanding-Java-Garbage-Collection


Les GC Stop The World

Serial GC: 1 thread

Throughput Collector ou Parallel Collector:

multi threads young et old


Les GC concurrents: CMS Concurrent Mark Sweep

Multi thread sur la young et les phases concurrentes, mono thread sur les Full GC

STW sur les minor GC

6 Phases:

1. Initial mark (STW)

2. Concurrent Mark

3. Pre clean

4. Remark (STW)

5. Sweep

6. Reset

Ne compacte pas de faon concurrenteBreizhCamp 2016 #BzhCmp@blep

Les GC concurrents : G1 G1 pour Garbage first

Multi thread sur la young et les phases concurrentes, mono thread sur les Full GC

STW sur les minor GC

Gre la heap en zones discrtes

Phases:

1. Initial Mark (STW)

2. Root Region Scanning

3. Concurrent Marking

4. Remark (STW)

5. Cleanup / Copying

Eden Survivor

Old

Old

EdenEden

Old

Survivor

OldEden Eden


Le log du GC90,652: [ GC (Allocation Failure) [ PSYoungGen: 130768K->1088K(152576K) ] 381293K->253237K(502272K), 0,0044329 secs ] [Times: user=0,02 sys=0,00, real=0,01 secs]

101,003: [ Full GC (Ergonomics) [ PSYoungGen: 3687K->0K(150528K) ] [ ParOldGen: 344000K->132146K(349696K) ] 347687K->132146K(500224K), [ Metaspace: 76887K->76887K(1118208K) ], 0,1998650 secs ] [Times: user=1,03 sys=0,01, real=0,20 secs]

Type de collecte-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -Xloggc:gc.log -XX:+UseGCLogFileRotation -XX:NumberOfGClogFiles=10 -XX:GCLogFileSize=1000K


GCViewer

https://github.com/chewiebug/GCViewerBreizhCamp 2016 #BzhCmp@blep

Maintenant qu'on en sait un peu plus sur les GC,

lequel choisir?


Profils applicatifs

Transactionnels

Batches


Choix du GC Batch:

Throughtput collector

Application transactionnelle:

GC concurrent

CMS heap < 4GB

G1 heap >= 4GB




CPU bound? GC?

Prlever un heap dump


Heap dump

$ jmap -dump:file=heap.hprof,format=b,live 4695 Dumping heap to heap.hprof ... Heap dump file created $ du -sh heap.hprof 462M heap.hprof

$ java -XX:+HeapDumpOnOutOfMemoryError \ -XX:HeapDumpPath=myApp.hprof ...


Retained size et dominateur

User

age: 42 8o

name: 4/8o

StringB i l lvalue:

4/8o

Groupname:

4/8oa d m i n

group: 4/8o

User

age: 42 8o

group: 4/8o

name: 4/8o

StringJ o h nvalue:

4/8o

Shallow sizeRetained size deep size


Memory Analyzer Tool (MAT)

http://www.eclipse.org/mat/

1

2

3


Tester



CPU bound? GC?


Fuite ou utilisation

abusive?

Analyser le dump et identifier les dominateurs

Augmenter la mmoire

Optimisation du code


Et le tuning mmoire et GC?

Dfinition des ratios pour tailler les zones Eden, Survivor et Old

Dfinition dobjectifs de latence

Nombre de threads allous au GC

Java Ergonomics depuis 1.5 -XX:+UseAdaptiveSizePolicy

$ java -XX:+PrintFlagsFinal -version |wc -l java version "1.8.0_66" Java(TM) SE Runtime Environment (build 1.8.0_66-b17) Java HotSpot(TM) 64-Bit Server VM (build 25.66-b17, mixed mode) 718


Tester



CPU bound? GC?



abusive?


Augmenter la mmoire

Prlever un ou plusieurs thread dumps

OU Analyser lactivit des

threads avec un profiler



Thread dump$ jstack 4695

2016-03-06 09:47:03 Full thread dump Java HotSpot(TM) 64-Bit Server VM (25.66-b17 mixed mode):

"http-bio-8081-exec-74" #305 daemon prio=5 os_prio=31 tid=0x00007fa2de53b000 nid=0xf11f runnable [0x00000001202e7000] java.lang.Thread.State: RUNNABLE at java.net.SocketInputStream.socketRead0(Native Method) at java.net.SocketInputStream.socketRead(SocketInputStream.java:116) at java.net.SocketInputStream.read(SocketInputStream.java:170) at java.net.SocketInputStream.read(SocketInputStream.java:141) at java.io.BufferedInputStream.fill(BufferedInputStream.java:246) at java.io.BufferedInputStream.read(BufferedInputStream.java:265) - locked (a java.io.BufferedInputStream) at java.io.DataInputStream.readByte(DataInputStream.java:265) at org.hsqldb.result.Result.newResult(Unknown Source) at org.hsqldb.ClientConnection.read(Unknown Source) at org.hsqldb.ClientConnection.execute(Unknown Source) - locked (a org.hsqldb.ClientConnection) at org.hsqldb.ClientConnection.getAttribute(Unknown Source) - locked (a org.hsqldb.ClientConnection) at org.hsqldb.ClientConnection.isAutoCommit(Unknown Source) - locked (a org.hsqldb.ClientConnection) at org.hsqldb.jdbc.JDBCConnection.getAutoCommit(Unknown Source) - locked (a org.hsqldb.jdbc.JDBCConnection) at org.apache.commons.dbcp.DelegatingConnection.getAutoCommit(DelegatingConnection.java:337) []

"http-bio-8081-exec-79" #310 daemon prio=5 os_prio=31 tid=0x00007fa2e00e7800 nid=0xe30b waiting for monitor entry [0x0000000123aa0000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:216) - waiting to lock (a java.lang.Object)


Les tats du thread


java.lang.Thread.State#BLOCKED

Un thread bloqu est dans lattente de lacquisition dun moniteur pour entrer dans un bloc synchronis

La synchronisation dun bloc permet de garantir que les instructions ne sont excutes exclusivement que par un et un seul thread

@Test public void lockMe() throws InterruptedException { final Thread thread1 = new Thread(this::intenseLockingComputation); final Thread thread2 = new Thread(this::intenseLockingComputation); thread1.start(); thread2.start();

thread2.join();

}

private final Object monitor = new Object();

private String intenseLockingComputation() { synchronized (monitor) { return { ... } } }

Thread1 verrouille monitor

Thread2 attend monitorThread2 verrouille monitor


Lire le thread dump

"Thread-2" #21 prio=5 os_prio=31 tid=0x00007fed9c8b3800 nid=0x6803 waiting for monitor entry [0x000000012d3b1000] java.lang.Thread.State: BLOCKED (on object monitor) at blep.LockTest.intenseLockingComputation(LockTest.java:36) - waiting to lock (a java.lang.Object) at blep.LockTest$$Lambda$9/204349222.run(Unknown Source) at java.lang.Thread.run(Thread.java:745)

"Thread-1" #20 prio=5 os_prio=31 tid=0x00007fed9bb03000 nid=0x6603 runnable [0x000000012d2ae000] java.lang.Thread.State: RUNNABLE at sun.nio.cs.UTF_8$Decoder.decode(UTF_8.java:456) at java.lang.StringCoding$StringDecoder.decode(StringCoding.java:153) at java.lang.StringCoding.decode(StringCoding.java:193) at java.lang.StringCoding.decode(StringCoding.java:254) at java.lang.String.(String.java:534) at java.lang.String.(String.java:554) at blep.LockTest.intenseLockingComputation(LockTest.java:39) - locked (a java.lang.Object) at blep.LockTest$$Lambda$8/1100439041.run(Unknown Source) at java.lang.Thread.run(Thread.java:745)

Thread-2 est bloqu l en attente du moniteur de la classe

Thread-1 excute la ligne et a verrouill le moniteur l


Un cas concret de verrouillage"http-bio-8081-exec-172" #454 daemon prio=5 os_prio=31 tid=0x00007fa2e00f2000 nid=0xe12f waiting for monitor entry [0x0000000122acc000] java.lang.Thread.State: BLOCKED (on object monitor) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:216) - waiting to lock (a java.lang.Object) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:108) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64) at ch.qos.logback.classic.Logger.appendLoopOnAppenders(Logger.java:285) at ch.qos.logback.classic.Logger.callAppenders(Logger.java:272) at ch.qos.logback.classic.Logger.buildLoggingEventAndAppend(Logger.java:473) at ch.qos.logback.classic.Logger.filterAndLog_0_Or3Plus(Logger.java:427) at ch.qos.logback.classic.Logger.debug(Logger.java:534)

"http-bio-8081-exec-173" #457 daemon prio=5 os_prio=31 tid=0x00007fa2e275e800 nid=0xf61b runnable [0x0000000122de8000] java.lang.Thread.State: RUNNABLE at java.io.FileOutputStream.writeBytes(Native Method) at java.io.FileOutputStream.write(FileOutputStream.java:326) at java.io.BufferedOutputStream.write(BufferedOutputStream.java:122) - locked (a java.io.BufferedOutputStream) at java.io.PrintStream.write(PrintStream.java:480) - locked (a java.io.PrintStream) at java.io.FilterOutputStream.write(FilterOutputStream.java:97) at org.apache.tomcat.util.log.SystemLogHandler.write(SystemLogHandler.java:169) at ch.qos.logback.core.joran.spi.ConsoleTarget$1.write(ConsoleTarget.java:36) at ch.qos.logback.core.encoder.LayoutWrappingEncoder.doEncode(LayoutWrappingEncoder.java:103) at ch.qos.logback.core.OutputStreamAppender.writeOut(OutputStreamAppender.java:193) at ch.qos.logback.core.OutputStreamAppender.subAppend(OutputStreamAppender.java:217) - locked (a java.lang.Object) at ch.qos.logback.core.OutputStreamAppender.append(OutputStreamAppender.java:108) at ch.qos.logback.core.UnsynchronizedAppenderBase.doAppend(UnsynchronizedAppenderBase.java:88) at ch.qos.logback.core.spi.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:64)


Mon Thread Dump Analyzerhttp://the-babel-tower.github.io/tda.html

Analyse des moniteurs soumis concurrence

Stats

Recherche dans les piles dappels

Lien vers GrepCode (enfin quand a marche)

Regroupements par tat


Thread history


Ca dpend !

Dimensionner un pool de threads


Sync vs Async

RUN RUNWAIT

Traitement

2 x Traitement @ 1 thread :

RUN11 RUN12WAIT1 RUN21 RUN22WAIT2Sync

Async RUN11 RUN12WAIT1

RUN21 RUN22

WAIT2

Conception squentielle et bloquante

Conception non bloquante base sur la composition de callbacks


Dimensionner un pool de threads

Conception asynchrone: autant que de threads physiques (@see /proc/cpuinfo)

Conception synchrone: a dpend!

Batch: autant que de threads physiques

Transactionnel : plus ( voire avec la charge et la proportion dattente)


Tester



CPU bound? GC?



abusive?


Augmenter la mmoire




Identifier les segments de code applicatifs concerns


Locks?

Identifier les moniteurs soumis concurrence


Identifier les consommateurs avec un profiler

Sampling ou profiling?


Profiler gratuit ou payant? Profilers gratuits:

Gratuit!

Pas de choix

Peu performant

Tlmtrie

Lger

Profilers payants:

Cot dcent (500/600)

Peu de choix

Performants

Prcis

Sondes de haut niveau

Intgrs lIDEBreizhCamp 2016 #BzhCmp@blep

Tester



CPU bound? GC?



abusive?


Augmenter la mmoire






Locks?


IO bound?

Analyser lactivit I/O


Monitorer les I/O


Identifier les contentions I/O


Tester



CPU bound? GC?



abusive?


Augmenter la mmoire






Locks?


IO bound?


Optimiser les IO (cache?)


Tester



CPU bound? GC?



abusive?


Augmenter la mmoire






Locks?


IO bound?




pour identifier les threads en wait


Exemple du pool sous dimensionn


Dimensionner un pool JDBC

x connexions pour y utilisateurs?

42?

Autant que de requtes HTTP?

initial = max = maxIdle !

Exprimenter pour rduire le temps dacquisition et obtenir la meilleure cadence


Tester

Pool sous dimensionn?

Redimensionner



CPU bound? GC?



abusive?


Augmenter la mmoire






Locks?


IO bound?






Tester


Redimensionner

Analyser lactivit/lutilisation des systmes externes



CPU bound? GC?



abusive?


Augmenter la mmoire






Locks?


IO bound?






Always blame the database! Analyse des plans dexcution / query trace

Ajout dindexes

Fracheur des statistiques

Purge de donnes / partitionnement / sharding (NoSQL)

Rationalisation des changes (batches, round trips, fetch size)

Dnormalisation


Optimisation IO

Utiliser les Buffered(In|Out)putStreams

Utilisation de cache:

Applicatif

cache FS du kernel


Tester


Redimensionner


Optimiser les IO (batches / buffers / ?)



CPU bound? GC?



abusive?


Augmenter la mmoire






Locks?


IO bound?






Et la virtualisation? Rservation de ressources!


https://www.youtube.com/watch?v=XK2sG7AiEY8



Tester


Redimensionner


Optimiser les IO (batches / buffers / ?)



CPU bound? GC?



abusive?


Augmenter la mmoire






Locks?


CPU bound?

Placer des marqueurs de mesure dans les log

OU Analyser lactivit avec un

profiler

IO bound?



Tester




Faites confiance aux frameworks matures!


Technology

Breizhcamp : Guide de survie du développeur dans une application (Java) qui rame