Санкт-Петербургская группа тестирования JVM

« Электрические Джунгл... | Main | Мониторинг состояния... »

вторник Декабрь 26, 2006

Микротестирование HotSpot

The First Rule of Program Optimization:
Don't do it.
The Second Rule of Program Optimization (for experts only!):
Don't do it yet.
–Michael A. Jackson

Сталкиваясь с результатами очередного микротестирования производительности в Java, часто ли у вас возникает вопрос насколько достоверны полученные результаты? Имеют ли они вообще какое-либо отношение к практике?

В очередной раз наткнувшись на результаты одного из "микроэкспериментов" и проследив дискуссию, меня в очередной раз смутило то, что результаты были восприняты как данность. Я же решил посмотреть на проблему под несколько другим углом и попытаться проанализировать ПОЧЕМУ ЖЕ метод String::length оказался быстрее String::equals? Ввиду специфики данного блога, виртуальная машина забыта не будет.

Все эксперименты проводились с использованием JDK 6.0 release под Linux x86 (Pentium4 3Gh). Некоторые использованные флаги доступны только для debug-версии JDK.

Для наглядности оригинальный пример был немного упрощен:

1   public class Test {

2        public static final long ITERATIONS = 1000000000L;


3   

4        public static void main(String[] args) {

5            long beginL = System.currentTimeMillis();

6            for (long i = 0; i < ITERATIONS; i++)


7                  "".length();

8            long endL = System.currentTimeMillis();

9    

10           long beginEq = System.currentTimeMillis();


11           for (long i = 0; i < ITERATIONS; i++)

12              "".equals("");

13           long endEq = System.currentTimeMillis();

14   


15           System.out.println("length: " + (endL - beginL) + " ms");

16           System.out.println("equals: " + (endEq - beginEq) + " ms");


17       }

18   }

После компиляции теста javac, метод Test.main выглядит следующим образом:

bci instruction


  // Line 5
   0:    invokestatic    #2; //Method java/lang/System.currentTimeMillis:()J
   3:    lstore_1
   


  // Line 6-7 - 1st loop

   4:    lconst_0

   5:    lstore_3

   6:    lload_3


   7:    ldc2_w    #3; //long 1000000000l

  10:    lcmp

  11:    ifge    27


  14:    ldc    #5; //String ""


  16:    invokevirtual    #6; //Method java/lang/String.length:()I

  19:    pop


  20:    lload_3

  21:    lconst_1

  22:    ladd

  23:    lstore_3


  24:    goto    6

  // End of the 1st loop



  // Line 8

  27:    invokestatic    #2; //Method java/lang/System.currentTimeMillis:()J


  30:    lstore_3




  // Line 10 

  31:    invokestatic    #2; //Method java/lang/System.currentTimeMillis:()J


  34:    lstore    5



  // Line 11-12 - the 2nd loop

  36:    lconst_0

  37:    lstore    7


  39:    lload    7

  41:    ldc2_w    #3; //long 1000000000l


  44:    lcmp


  45:    ifge    65

  48:    ldc    #5; //String ""

  50:    ldc    #5; //String ""


  52:    invokevirtual    #7; //Method java/lang/String.equals:(Ljava/lang/Object;)Z


  55:    pop

  56:    lload    7


  58:    lconst_1

  59:    ladd

  60:    lstore    7


  62:    goto    39

  // End of the 2nd loop



  // Line 15-16 - Print performance measurements

  65:    invokestatic    #2; //Method java/lang/System.currentTimeMillis:()J


  68:    lstore    7

  70:    getstatic    #8; //Field java/lang/System.out:Ljava/io/PrintStream;


  73:    new    #9; //class java/lang/StringBuilder


  76:    dup

  77:    invokespecial    #10; //Method java/lang/StringBuilder."<init>":()V

  80:    ldc    #11; //String length:


  82:    invokevirtual    #12;
//Method
java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;


  85:    lload_3

  86:    lload_1


  87:    lsub

  88:    invokevirtual    #13;
//Method java/lang/StringBuilder.append:(J)Ljava/lang/StringBuilder;

  91:    invokevirtual    #14; //Method java/lang/StringBuilder.toString:()Ljava/lang/String;


  94:    invokevirtual    #15; //Method java/io/PrintStream.println:(Ljava/lang/String;)V

  97:    getstatic    #8; //Field java/lang/System.out:Ljava/io/PrintStream;

 100:    new    #9; //class java/lang/StringBuilder


 103:    dup

 104:    invokespecial    #10; //Method java/lang/StringBuilder."<init>":()V

 107:    ldc    #16; //String equals:


 109:    invokevirtual    #12;
//Method
java/lang/StringBuilder.append:(Ljava/lang/String;)Ljava/lang/StringBuilder;

 112:    lload    7

 114:    lload    5


 116:    lsub

 117:    invokevirtual    #13;
//Method java/lang/StringBuilder.append:(J)Ljava/lang/StringBuilder;

 120:    invokevirtual    #14; //Method java/lang/StringBuilder.toString:()Ljava/lang/String;

 123:    invokevirtual    #15; //Method java/io/PrintStream.println:(Ljava/lang/String;)V


 126:    return

ДЛЯ ЗАТРАВКИ

Для интерпретатора (режим -Xint, JIT-компиляторы полностью блокированы) разница в скорости есть, но она не очень значительна: length: 119153 ms equals: 147111 ms

Сколь-нибудь активно используемые методы (а именно их производительность для нас может быть критичной) будут обязательно скомпилированы JIT-компилятором. В Sun HotSpot JVM (или просто HotSpot) присутствует 2 различных JIT-компилятора: C1/client и C2/server, изначально ориентированные на различные типы приложений (как можно догадаться, на "клиентские" и "серверные"). C1 должен генерировать приемлемый по качеству код за минимально возможное время. Для C2 же первостепенна производительность создаваемого кода.

C1 В ДЕТАЛЯХ

Для C1 (режим -client) разница в производительности более чем двукратна:

length: 3208 ms
equals: 8424 ms

Исследование я начал с того, что попытался определить какие же конкретно методы компилируются при исполнении тестового примера. Для этого я воспользовался ключом -XX:+PrintCompilation:

1 java.lang.String::charAt (33 bytes) 2 java.lang.String::hashCode (60 bytes) 3 ! sun.nio.cs.US_ASCII$Encoder::encodeArrayLoop (356 bytes) 4 java.lang.String::indexOf (151 bytes) 1% Test::main @ 6 (137 bytes) 5 java.lang.String::equals (88 bytes)

Каждая строка содержит общую информацию о свойствах произошедшей компиляции для некоторого метода:

[id][flags] [className::methodName] ([size])

[id]—порядковый номер компиляции.
[flags] является строкой из 4х символов, в которой закодирована полезная информация о компиляции и о методе, подвергшемся компиляции.

Первый символ описывает тип произведенной компиляции:

' '—обычная компиляция java-метода
'%'—была создана специальная версия метода, пригодная для использования при OSR'е (OSR = On-Stack Replacement).
'*'—произошла компиляция wrapper'а для native-метода

В Hotspot'е под OSR подразумевается переход от интерпретации метода к исполнению его компилированной версии. Для обратного перехода используется термин "деоптимизация" (deoptimization).

Для каждого исполняемого метода хранится общее число полностью выполненных итераций циклов в рамках данного метода (считаются так называемые обратные переходы/loop back branches). OSR инициируется, когда число таких переходов достигает некоторого фиксированного критического значения.

OSR подразумевает следующую последовательность действий:

исполнение метода останавливается
компилируется специальная версия метода с новой точкой входа
осуществляется замена текущего фрейма на стеке
происходит восстановление значений локальных переменных на момент остановки
исполнение возобновляется

Если метод является синхронизированным, то на второй позиции в строке будет символ 's', иначе—пробел.

В случае, если метод содержит обработчики исключений, на третьей позиции будет '!'. Пробел же будет свидетельствовать об их отсутствии.

Компиляция метода может происходить синхронно с его исполнением или же параллельно.

При синхронной (или блокирующей) компиляции, поток, инициировавший компиляцию метода, приостанавливается до момента её завершения. Соответственно, при возобновлении работы произойдет переход от интерпретации к исполнению компилированной версии. В случае неблокирующей компиляции, во время компиляции исполнение метода будет идти в интерпретаторе, а уже потом при первой возможности будет использована компилированная версия.

В случае блокировки исполнения 4й символ строки будет иметь значение 'b', а ' ' свидетельствует о неблокирующей природе произведенной компиляции.

Затем следует полное имя метода, подвергшегося компиляции ([className::methodName]), а в скобках указывается размер соответствующего ему байт-кода.

Интерес представляет последняя строка:
1% Test::main @ 6 (127 bytes)
Наличие '%' свидетельствует о том, что компиляция была вызвана OSR'ом, а "@ 6" информирует о том, что OSR произошел во время исполнения первого цикла (строки 6–7), уже после того как началось измерение времени исполнения.

Соответственно, вызванная компиляция и переход от интерпретации к исполнению компилированной версии могли повлиять на конечный результат. Но дополнительный анализ опроверг эту гипотезу. Перейдя к блокирующей компиляции (-XX:-BackgroundCompilation) и замерив время, затраченное на компиляцию, (-XX:+CITimeEach), выяснилось, что лишь несколько миллисекунд были потрачены на компиляцию:
1% b Test::main @ 6 (127 bytes) 1 seconds: 0.004303 bytes/sec : 30676.271484 (bytes 127 + 5 inlined)
Также существует ключ -XX:+CITime, который после завершения работы приложения предоставляет суммарный отчет о ресурсах, затраченных на JIT-компиляцию.

Следующим шагом я хотел получить информацию об инлайнинге (inlining) вызываемых функций в компилированной версии метода.

Под инлайнингом подразумевается замена вызова метода его кодом. Данная оптимизация позволяет избавляться не столько от косвенного вызова (indirect call), сколько от нагрузки, связанной с вызовом виртуальных методов (virtual method dispatch). На текущий момент, в Hotspot'е на основе анализа загруженных классов в момент компиляции (CHA = Class Hierarchy Analysis), метод может быть заинлайнен как мономорфный или биморфный. Естественно, при загрузке новых классов требуется проверять корректность сделанных ранее предположений. Несоответствие повлечет деоптимизацию и, вероятнее всего, последующую перекомпиляцию, т.к. текущий код устарел и не может быть в дальнейшем использован.

Запуск с опциями "-client -XX:+PrintCompilation -XX:+PrintInlining" дал следующий результат:
[...] 1% Test::main @ 6 (127 bytes) @ 0 java.lang.System::currentTimeMillis (0 bytes) @ 16 java.lang.String::length (5 bytes) @ 27 java.lang.System::currentTimeMillis (0 bytes) @ 31 java.lang.System::currentTimeMillis (0 bytes) - @ 52 java.lang.String::equals (88 bytes) callee is too large @ 65 java.lang.System::currentTimeMillis (0 bytes) [...] length: 3293 ms equals: 8322 ms
Особый интерес представляют 2 строки:
@ 16 java.lang.String::length (5 bytes) ... - @ 52 java.lang.String::equals (88 bytes) callee is too large
String.length инлайнится, String.equals—нет. Сообщение информирует о том, что инлайнинг не сработал из-за слишком большого размера метода.

Насколько измениться скорость исполнения, если String.equals будет заинлайнен?

Проверить данную гипотезу можно изменив ограничение на максимальный размер метода (-XX:MaxInlineSize=100):
[...] 1% Test::main @ 6 (127 bytes) @ 0 java.lang.System::currentTimeMillis (0 bytes) @ 16 java.lang.String::length (5 bytes) @ 27 java.lang.System::currentTimeMillis (0 bytes) @ 31 java.lang.System::currentTimeMillis (0 bytes) @ 52 java.lang.String::equals (88 bytes) @ 65 java.lang.System::currentTimeMillis (0 bytes) [...]length: 3220 ms equals: 2871 ms
Парадоксально, теперь String.equals оказался быстрее String.length аж на 30%!

Прояснить ситуацию смог анализ генерируемого кода (-XX:+PrintNMethods) для каждого из циклов.

Первый цикл (String.length):

0xb5e4c744:
jmp   
0xb5e4c760        
;*lstore_3                      

    ; - Test::main@5 (line 6)

0xb5e4c749: nop    

0xb5e4c74a: nop    

0xb5e4c74b: nop    

0xb5e4c74c: movl   $0x9c61b2a0,%ebx   ;   {oop("")}

0xb5e4c751: movl   0x10(%ebx),%ebx    ;*getfield count

; - java.lang.String::length@1 (line 652)

; - Test::main@16 (line 6)

; implicit exception: dispatches to 0xb5e4c950

0xb5e4c754: addl   $0x1,%esi

0xb5e4c757: adcl   $0x0,%edi          ;*goto

; - Test::main@24 (line 6)

0xb5e4c75a: testl  %eax,0xb7fad100    ;*goto

; - Test::main@24 (line 6)

;   {poll} 

0xb5e4c760: movl   %esi,%ebx

0xb5e4c762: movl   %edi,%ecx

0xb5e4c764: movl   $0x3b9aca00,%eax

0xb5e4c769: movl   $0x0,%edx

0xb5e4c76e: subl   %eax,%ebx

0xb5e4c770: sbbl   %edx,%ecx  

0xb5e4c772: jl     0xb5e4c74c         ;*lcmp

; - Test::main@10 (line 6)

Второй цикл (String.equals):

без инлайнинга String.equals c инлайнингом String.equals

0xb5df97ac: jmp 0xb5df97d4 ;*lstore

                               
      ; - Test::main@37 (line 10)

      0xb5df97b1: nop

      0xb5df97b2: nop

      0xb5df97b3: nop 


      0xb5df97b4: movl   $0x9c61b2a0,%ecx   ;   {oop("")}

      0xb5df97b9: movl   %ecx,%edx          ;*invokevirtual equals


                                           

; - Test::main@52 (line 10)

      0xb5df97bb: call   0xb5daee50         ;*invokevirtual equals

                                           
; - Test::main@52 (line 10)

                                           

;   {optimized virtual_call}


      0xb5df97c0: movl   0x44(%esp,1),%edi

      0xb5df97c4: movl   0x40(%esp,1),%esi

      0xb5df97c8: addl   $0x1,%esi


      0xb5df97cb: adcl   $0x0,%edi          ;*goto


                                           
; - Test::main@62 (line 10)

      0xb5df97ce: testl  %eax,0xb7f5a100    ;*goto


                                           
; - Test::main@62 (line 10)

                                           

;   {poll} 

      0xb5df97d4: movl   %esi,%ebx

      0xb5df97d6: movl   %edi,%ecx


      0xb5df97d8: movl   %esi,0x40(%esp,1)


      0xb5df97dc: movl   %edi,0x44(%esp,1)

      0xb5df97e0: movl   $0x3b9aca00,%esi

      0xb5df97e5: movl   $0x0,%edi


      0xb5df97ea: subl   %esi,%ebx


      0xb5df97ec: sbbl   %edi,%ecx 

      0xb5df97ee: jl     0xb5df97b4         ;*lcmp

                                     
; - Test::main@44 (line 10)

0xb5deb79c: jmp 0xb5deb7b0 ;*lstore




                                           
; - Test::main@37 (line 10)

      0xb5deb7a1: nop


      0xb5deb7a2: nop

      0xb5deb7a3: nop

      0xb5deb7a4: addl   $0x1,%esi


      0xb5deb7a7: adcl   $0x0,%edi          ;*goto


                                           
; - Test::main@62 (line 10)

      0xb5deb7aa: testl  %eax,0xb7f45100    ;*goto


                                           
; - Test::main@62 (line 10)

                                           

;   {poll}

      0xb5deb7b0: movl   %esi,%ebx

      0xb5deb7b2: movl   %edi,%ecx


      0xb5deb7b4: movl   $0x3b9aca00,%eax


      0xb5deb7b9: movl   $0x0,%edx

      0xb5deb7be: subl   %eax,%ebx

      0xb5deb7c0: sbbl   %edx,%ecx


      0xb5deb7c2: jl     0xb5deb7a4         ;*lcmp

В первом цикле вызов String.length был заменен на прямое обращение к соответствующему полю объекта. Но во втором цикле заработавший инлайнинг спровоцировал полное удаление кода, связанного c вызовом метода String.equals.

Как оказалось, рассматриваемый тест так и не померял реальное соотношение производительности одного метода относительно другого. Достаточно тривиальный тьюнинг виртуальной машины позволил получить результаты, позволяющие сделать диаметрально противоположные выводы. Reductio ad absurdum.

Какой-либо осмысленный анализ оказался просто невозможен без учета ряда агрессивных оптимизаций, применяемых в современном "виртуальном машиностроении". Но даже подобный учет не позволил бы абстрагироваться от имплементации JDK и её конкретной версии.

Создание репрезентативного микротеста на производительность—задача, если и разрешимая, то только с большим количеством допущений и оговорок. Да и насколько вообще полезно микротестирование на практике - вопрос открытый.

"Bottlenecks occur in surprising places, ..."
Rob Pike

Владимир Иванов

опубликовал vmrobot ( дек 26 2006, 09:31:25 PM MSK ) Permalink Комментарии [5]

Trackback URL: http://blogs.sun.com/vmrobot/entry/microbenchmarking_hotspot

Комментарии:

Нда. Заставляет задуматься %) Видимо, результаты fine tuning-а своих методов можно оценить только на большом синтетическом тесте, близком к реальной задаче.

опубликовал 9000 Декабрь 26, 2006 at 11:28 PM MSK #

Подскажите пожалуйста, как можно включить debug mode JVM? Чему равно по умолчанию значение MaxInlineSize для серверного компилятора? Есть ли другие интересные параметры, влияющие на то, какой код генерирует компилятор?

опубликовал denis Декабрь 29, 2006 at 01:15 PM MSK #

По порядку: 1) Debug-версия Hotspot входит в debug JDK, скачать который можно, например, отсюда: http://download.java.net/jdk6/binaries/ 2) Дефолтное значение параметра MaxInlineSize равно 35 как для C1, так и для C2. 3) Ряд полезных флагов описан тут: http://java.sun.com/javase/technologies/hotspot/vmoptions.jsp Хотя лучше исходников на текущий момент ничего нету... =(

опубликовал Vladimir Ivanov Январь 09, 2007 at 04:10 PM MSK #

типа нужно было dependency добавить от вычисляемого значения так, что бы оптимизитрующий компилятор не смел его удалять. Без этого многие микробенчмарки превращаются в nop, nop, nop. Строчку для сравнения стоит получать из статически непредсказуемого источника (с консоли например). Тогда .length должен победить с существенным отрывом. :-)

опубликовал Anatoly Zhmur Март 01, 2007 at 05:17 PM MSK #

Толя, ты уверен? ;-) Быть тебе значит битым контр.примером!

public class Test {
public static final long ITERATIONS = 1000000000L;

public static void main(String[] args) {
System.out.print("Insert a string:");
String str = System.console().readLine().intern();
long total = 0;

System.out.println("Measuring equals...");

long beginEq = System.currentTimeMillis();
for (long i = 0; i < ITERATIONS; i++) {
if (!str.equals("")) {
total++;
}
}
long endEq = System.currentTimeMillis();

System.out.println("Measuring length...");
long beginL = System.currentTimeMillis();
for (long i = 0; i < ITERATIONS; i++) {
if (str.length() > 0) {
total++;
}
}

long endL = System.currentTimeMillis();

System.out.println("length: " + (endL - beginL) + " ms");
System.out.println("equals: " + (endEq - beginEq) + " ms");
System.out.println("total = " + total);

}
}

$ javac Test.java && /set/vmsqe/jdk-builds/6/latest/linux-i586/bin/java -XX:MaxInlineSize=100 -server -showversion Test
java version "1.6.0"
Java(TM) SE Runtime Environment (build 1.6.0-b105)
Java HotSpot(TM) Server VM (build 1.6.0-b105, mixed mode)

Insert a string:
Measuring equals...
Measuring length...
length: 4042 ms
equals: 3711 ms
total = 0

PS: без пары хитростей конечно же не обошлось ;-)

опубликовал Vladimir Ivanov Март 06, 2007 at 05:59 AM MSK #

Опубликовать комментарий:

Имя
E-Mail:
URL:
	Известить меня по email о новых комментариях
	Запомнить информацию?

Ваш комментарий:
HTML Syntax: Отключен

Хиты страниц за сегодня: 106

Санкт-Петербургская группа тестирования JVM

ДЛЯ ЗАТРАВКИ

C1 В ДЕТАЛЯХ

Calendar

RSS Feeds

Links

Navigation

Пн	Вт	Ср	Чт	Пт	Сб	Вс
« Декабрь 2009
	1	2	3	4	5	6
7	8	9	10	11	12	13
14	15	16	17	18	19	20
21	22	23	24	25	26	27
28	29	30	31

Сегодня