JPoint 2016 - Etudes of DYI Java profiler

Slide 1

Slide 1 text

Как сделать профилировщик из палок... и других подручных средств @antonarhipov JPoint 2016, Москва

Slide 2

Slide 2 text

No content

Slide 3

Slide 3 text

No content

Slide 4

Slide 4 text

Batch / ETL Исходные данные : ~10k записей Результат: ~20M записей j.u.Date / j.u.Calendar Java 1.4 HP-UX Первый запуск: 25 ч :-( После оптимизаций: 10 ч После изменения дизайна: 30 мин :-) 2005 История одного проекта

Slide 5

Slide 5 text

Тот самый случай когда выглядишь умным, но чувствуешь себя полным ДУРАКОМ

Slide 6

Slide 6 text

https://twitter.com/shipilev/status/578193813946134529

Slide 7

Slide 7 text

Как и когда вы используете профилировщик?

Slide 8

Slide 8 text

QA Staging Production Тормозит! Тесты показывают падение производительности Всё плохо!

Slide 9

Slide 9 text

No content

Slide 10

Slide 10 text

> Chrome DevTools > FireBug > YSlow > … > XRebel “Проактивные” инструменты

Slide 11

Slide 11 text

> Пользовательский интерфейс > Профилирование приложения > Трассировка внешних вызовов > Трассировка потоков > Распределённые приложения Этюды профайлероводства

Slide 12

Slide 12 text

UI & UX

Slide 13

Slide 13 text

No content

Slide 14

Slide 14 text

Slide 15

Slide 15 text

package org.apache.catalina.connector; public class Response implements HttpServletResponse { public ServletOutputStream getOutputStream() throws IOException { if (this.usingWriter) { throw new IllegalStateException(…)); } this.usingOutputStream = true; if (this.outputStream == null) { this.outputStream = new CoyoteOutputStream(this.outputBuffer); } return this.outputStream; } ctClass.getDeclaredMethod("getOutputStream").insertAfter(  "if (" + _interceptor + " != null) {" +  " $_ = (ServletOutputStream)" + _interceptor + ".getOutputStream($_);" +  "}"); Javassist

Slide 16

Slide 16 text

package org.apache.catalina.connector; public class Response implements HttpServletResponse { public ServletOutputStream getOutputStream() throws IOException { if (this.usingWriter) { throw new IllegalStateException(…)); } this.usingOutputStream = true; if (this.outputStream == null) { this.outputStream = new CoyoteOutputStream(this.outputBuffer); } if (_interceptor != null) { this.outputStream = (ServletOutputStream)_interceptor .getOutputStream(this.outputStream); } return this.outputStream; }

Slide 17

Slide 17 text

Куда уходит время?

Slide 18

Slide 18 text

Windows: Ctrl+Break *nix: kill -3 PID "http-nio-8080-exec-1" #40 daemon prio=5 os_prio=31 tid=0x00007fd7057ed800 nid=0x7313 runnable java.lang.Thread.State: RUNNABLE at o.s.s.p.w.OwnerController.processFindForm(OwnerController.java:89) at s.r.NativeMethodAccessorImpl.invoke0(Native Method) at s.r.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62) at s.r.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) at j.l.r.Method.invoke(Method.java:497) Сэмплирование

Slide 19

Slide 19 text

Интервал : 20 мс Кол-во сэмплов: 4

Slide 20

Slide 20 text

Интервал : 1 мс Кол-во сэмплов: 100+

Slide 21

Slide 21 text

main() foo() bar() baz()

Slide 22

Slide 22 text

Safepoints main() foo() bar() baz()

Slide 23

Slide 23 text

Safepoints main() foo() bar() baz()

Slide 24

Slide 24 text

Java Mission Control Java 7u40 Honest Profiler https://github.com/RichardWarburton/honest-profiler AsyncGetCallTrace JVMTI Как обуздать safepoint bias?

Slide 25

Slide 25 text

main() foo() bar() baz() Инструментирующий профилировщик Высокие накладные расходы для быстрых методов

Slide 26

Slide 26 text

public void businessMethod() {  long start = System.currentTimeMillis();  work();  Profiler.log(System.currentTimeMillis()-‐start); }

Slide 27

Slide 27 text

public void businessMethod() {  long start = System.nanoTime();  work();  Profiler.log(System.nanoTime()-‐start);  }

Slide 28

Slide 28 text

public void businessMethod() {  Profiler.start("businessMethod"); try {  work();  } finally {  Profiler.log("businessMethod");  }  }

Slide 29

Slide 29 text

System.nanoTime Параллельный поток для замеров времени sleep-wakup-update yield-wakup-update busy-loop-update

Slide 30

Slide 30 text

class Profiler {   Loop loop;    public static void start(String method) {  long now = loop.getTime(); …  }

Slide 31

Slide 31 text

public class Loop implements Runnable {  private volatile long time;  public void run() {  while (running) {  time = System.nanoTime();  sleep();  }  } public final long getTime() {  return time;  } Busy Loop

Slide 32

Slide 32 text

Наносекунды в приближении Чтение памяти имеет цену Занимает циклы процессора = ns Каждый слой ПО добавляет к цене. JVM, JNI, OS, HW http://shipilev.net/blog/2014/nanotrusting-nanotime/ Nanotrusting the NanoTime

Slide 33

Slide 33 text

Наносекунды в приближении http://shipilev.net/blog/2014/nanotrusting-nanotime/ Nanotrusting the NanoTime granularity_nanotime: 26.300 +- 0.205 ns latency_nanotime: 25.542 +- 0.024 ns granularity_nanotime: 29.322 +- 1.293 ns latency_nanotime: 29.910 +- 1.626 ns granularity_nanotime: 371,419 +- 1,541 ns latency_nanotime: 14,415 +- 0,389 ns Linux Solaris Windows

Slide 34

Slide 34 text

Thread.sleep Win8: 1.7 мс (JNI + socket poll: 1.0 ms ) Linux: 0.1 мс OS X: 0.05 мс Всё таки загружает ядро процессора на 25-50% Thread.yield Планировшик в Windows может проигнорировать наш поток в случае высокой загрузки процессора

Slide 35

Slide 35 text

public class Loop implements Runnable {  private volatile long time;  public void run() {  while (running) {  time = System.nanoTime();  sleep();  }  } private void sleep() {  if (!MiscUtil.isWindows()) {  Thread.yield();  }  } Busy Loop

Slide 36

Slide 36 text

Busy Loop public class Loop implements Runnable {  private volatile long time;  public void run() {  while (running) {  time = System.nanoTime();  sleep();  }  } private void sleep() {  if (!MiscUtil.isWindows()) {  Thread.yield();  }  }

Slide 37

Slide 37 text

Slide 38

Slide 38 text

main() foo() bar() baz() 2 3 4

Slide 39

Slide 39 text

main() foo() bar() baz() 2 3 5 boo() Дисбаланс ошибки для веток с разной глубиной

Slide 40

Slide 40 text

No content

Slide 41

Slide 41 text

No content

Slide 42

Slide 42 text

Оптимизации LeafMethodAnalyser(AbstractMethodBodyAnalyser mv) {  super(mv, not(eq(VISIT_METHOD_INSN)),  not(eq(VISIT_INVOKE_DYNAMIC_INSN)),  not(eq(VISIT_JUMP_INSN)));  }

Slide 43

Slide 43 text

Оптимизации public int calculateMargin(Order order){  return order.grossPrice() / order.salesPrice() * 100;  } public int grossPrice() {  return gross;  } public int grossPrice(); Code: 0: aload_0 1: getfield #2 // Field gross:I 4: ireturn Не вызывает других методов Нет циклов Можно игнорировать

Slide 44

Slide 44 text

44 Потоки

Slide 45

Slide 45 text

val r = new Runnable(){} val t = new Thread(r) t.start() t.join() public void run() { doSomething(); }

Slide 46

Slide 46 text

Runnable r = new Runnable(){  public void run() { doSomething();  }  };

Slide 47

Slide 47 text

Runnable r = new Runnable(){  private WeakReference ctx; public void run() { Context sink = ctx.getChildContext();  sink = Sinks.startAsync(sink);    try {  doSomething();  } finally {  Sinks.stopAsync(sink);  }  }  };

Slide 48

Slide 48 text

No content

Slide 49

Slide 49 text

Внешние вызовы

Slide 50

Slide 50 text

JDBC > Вариант 1. Proxy > Вариант 2. Список известных нам классов. Что знаем, то и инструментируем. > Вариант 3. Есть известные интерфейсы - сканируем иерархию классов Привет, ClassCastException Замедление старта приложения Привет, DB2

Slide 51

Slide 51 text

No content

Slide 52

Slide 52 text

No content

Slide 53

Slide 53 text

Распределённые приложения

Slide 54

Slide 54 text

No content

Slide 55

Slide 55 text

No content

Slide 56

Slide 56 text

Что уже есть? > Разные $$$ APM-продукты: Dynatrace, AppDynamics > Dapper > ZipKin http://research.google.com/pubs/pub36356.html http://zipkin.io NB! Требуется серверная часть

Slide 57

Slide 57 text

No content

Slide 58

Slide 58 text

Request headers GET /supplements/ HTTP/1.1 X-XRebel-Event-Id: 6a61eb15-23f1-40ea-a30d-2f62d616a196 X-XRebel-Version: 3.0.2 Cache-Control: no-cache Pragma: no-cache User-Agent: Java/1.8.0_51 Host: localhost:8080 Response headers HTTP/1.1 200 OK Server: Apache-Coyote/1.1 X-XRebel-Event-Id: c5603281-a745-416e-8f27-92ba47c76b26 X-XRebel-Version: 3.0.2 X-xr-bookmark: 3197589b-bc9f-44ab-a2aa-12557a39b090 Content-Type: application/json;charset=ISO-8859-1

Slide 59

Slide 59 text

No content

Slide 60

Slide 60 text

This slide is intentionally left blank

Slide 61

Slide 61 text

No content

Slide 62

Slide 62 text

@antonarhipov anton@zeroturnaround.com https://speakerdeck.com/antonarhipov https://www.slideshare.net/arhan