Трассировка стека заметно медленнее в Java 11, чем в Java 8

Я сравнивал производительность JDK 8 и 11, используя jmh 1.21, когда наткнулся на несколько удивительных чисел:

OpenJDK 11 и 12 работают аналогично OracleJDK 11. Для краткости я опустил их номера.

Я понимаю, что микробенчмарки не указывают на поведение производительности реальных приложений. Тем не менее, мне любопытно, откуда эта разница. Есть идеи?

Вот специфичный для Windows скрипт, который я использую. Это должно быть тривиально, чтобы перевести его на другие платформы:

В частности, я использую Microsoft Windows [Version 10.0.17763.195].

Ответы

Ответ 1

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

Как отметил @AlekseyShipilev, замедление между JDK 8 и JDK 9 в основном является результатом изменений StackWalker. Также G1 стал GC по умолчанию с JDK 9. Если мы явно установим -XX:+UseParallelGC (по умолчанию в JDK 8), оценки будут немного лучше.

Но самая интересная часть - это замедление в JDK 11.
Вот что показывает асинхронный профилировщик (кликабельный SVG).

Основное различие между двумя профилями заключается в размере блока java_lang_Throwable::get_stack_trace_elements, в котором преобладает StringTable::intern. Очевидно, StringTable::intern занимает гораздо больше времени в JDK 11.

Позвольте увеличить

Обратите внимание, что StringTable::intern в JDK 11 вызывает do_intern который, в свою очередь, выделяет новый объект java.lang.String. Выглядит подозрительно Ничего подобного не видно в профиле JDK 10. Время смотреть в исходном коде.

stringTable.cpp(JDK 11)

oop StringTable::intern(Handle string_or_null_h, jchar* name, int len, TRAPS) {
  // shared table always uses java_lang_String::hash_code
  unsigned int hash = java_lang_String::hash_code(name, len);
  oop found_string = StringTable::the_table()->lookup_shared(name, len, hash);
  if (found_string != NULL) {
    return found_string;
  }
  if (StringTable::_alt_hash) {
    hash = hash_string(name, len, true);
  }
  return StringTable::the_table()->do_intern(string_or_null_h, name, len,
                                       |     hash, CHECK_NULL);
}                                      |
                       ----------------
                      |
                      v
oop StringTable::do_intern(Handle string_or_null_h, const jchar* name,
                           int len, uintx hash, TRAPS) {
  HandleMark hm(THREAD);  // cleanup strings created
  Handle string_h;

  if (!string_or_null_h.is_null()) {
    string_h = string_or_null_h;
  } else {
    string_h = java_lang_String::create_from_unicode(name, len, CHECK_NULL);
  }

Функция в JDK 11 сначала ищет строку в общей StringTable, не находит ее, затем переходит к do_intern и сразу же создает новый объект String.

В источниках JDK 10 после вызова lookup_shared в основной таблице был выполнен дополнительный поиск, который возвращал существующую строку без создания нового объекта:

  found_string = the_table()->lookup_in_main_table(index, name, len, hashValue);

Этот рефакторинг был результатом JDK-8195097 "Сделать возможным обработку StringTable вне безопасной точки".

TL; DR При интернировании имен методов в JDK 11 HotSpot создает избыточные объекты String. Это произошло после JDK-8195097.

Ответ 2

Я подозреваю, что это связано с несколькими изменениями.

8-> 9 произошла регрессия при переключении на StackWalker для генерации трассировки стека (JDK-8150778). К сожалению, это сделало нативный код виртуальной машины большим количеством строк, и StringTable становится узким местом. Если вы профилируете тест производительности OP, вы увидите профиль, как в JDK-8151751. Этого должно быть достаточно, чтобы perf record -g всю JVM, на которой выполняется тест, а затем просмотреть perf report о тестировании. (Подсказка, подсказка, вы можете сделать это сами в следующий раз!)

И 10-> 11 регресс должен был произойти позже. Я подозреваю, что это связано с подготовкой StringTable к переключению на полностью параллельную хэш-таблицу (JDK-8195100, которая, как указывает Клэйс, не полностью в 11) или чем-то еще (изменения совместного использования данных в классе?).

В любом случае, интернирование по быстрому пути - плохая идея, и патч для JDK-8151751 должен был иметь дело с обеими регрессиями.

Смотри:

8u191:15108 ± 99 нс/операция [пока все хорошо]

-   54.55%     0.37%  java     libjvm.so           [.] JVM_GetStackTraceElement 
   - 54.18% JVM_GetStackTraceElement                          
      - 52.22% java_lang_Throwable::get_stack_trace_element   
         - 48.23% java_lang_StackTraceElement::create         
            - 17.82% StringTable::intern                      
            - 13.92% StringTable::intern                      
            - 4.83% Klass::external_name                      
            + 3.41% Method::line_number_from_bci

"голова": 22382 ± 134 нс/оп [регрессия]

-   69.79%     0.05%  org.sample.MyBe  libjvm.so  [.] JVM_InitStackTraceElement
   - 69.73% JVM_InitStackTraceElementArray                    
      - 69.14% java_lang_Throwable::get_stack_trace_elements  
         - 66.86% java_lang_StackTraceElement::fill_in        
            - 38.48% StringTable::intern                      
            - 21.81% StringTable::intern                      
            - 2.21% Klass::external_name                      
              1.82% Method::line_number_from_bci              
              0.97% AccessInternal::PostRuntimeDispatch<G1BarrierSet::AccessBarrier<573

"head" + патч JDK-8151751: 7511 ± 26 нс/оп [woot, даже лучше, чем 8u]

-   22.53%     0.12%  org.sample.MyBe  libjvm.so  [.] JVM_InitStackTraceElement
   - 22.40% JVM_InitStackTraceElementArray                    
      - 20.25% java_lang_Throwable::get_stack_trace_elements  
         - 12.69% java_lang_StackTraceElement::fill_in        
            + 6.86% Method::line_number_from_bci              
              2.08% AccessInternal::PostRuntimeDispatch<G1BarrierSet::AccessBarrier
           2.24% InstanceKlass::method_with_orig_idnum        
           1.03% Handle::Handle