Время, проведенное в Object.<Init> (hprof)
Я профилирую свое приложение - это макросистема, построенная на основе Java. Я использую hprof для профилирования некоторых основных примеров, и вот 20 лучших функций, на которые тратится время:
rank self accum count trace method
1 14.73% 14.73% 453 303755 java.lang.Object.<init>
2 9.75% 24.48% 300 303754 java.lang.Object.<init>
3 7.18% 31.66% 221 303641 java.lang.Object.<init>
4 6.83% 38.49% 210 303621 java.util.ArrayList.<init>
5 6.76% 45.25% 208 303620 java.util.ArrayList.<init>
6 5.95% 51.20% 183 303833 java.lang.Character.toChars
7 4.55% 55.75% 140 303809 java.lang.Object.<init>
8 4.42% 60.18% 136 303791 java.lang.Object.<init>
9 3.77% 63.95% 116 303756 java.lang.Object.<init>
10 3.64% 67.59% 112 300509 java.lang.Object.<init>
11 2.67% 70.25% 82 303789 java.lang.Object.<init>
12 2.54% 72.79% 78 303790 java.lang.Object.<init>
13 1.69% 74.48% 52 303688 java.lang.Object.<init>
14 1.66% 76.14% 51 303644 java.lang.Object.<init>
15 1.46% 77.60% 45 305935 java.lang.Object.<init>
16 1.40% 79.00% 43 303758 java.lang.Object.<init>
17 1.20% 80.20% 37 305324 java.lang.Object.<init>
18 0.98% 81.18% 30 302559 java.lang.Object.<init>
19 0.62% 81.79% 19 300006 java.util.Arrays.copyOf
20 0.52% 82.31% 16 305214 java.lang.Object.<init>
Как видите, большая часть времени уходит на Object.<init>, Это несколько неясно для меня.
Моя интуиция заключается в том, что время заняло распределение памяти. Работа в C оставила у меня сильное чувство, что динамическое распределение памяти (т.е. malloc()) неэффективно. Однако в Java евангелие, похоже, заключается в том, что JVM эффективно работает с недолговечными объектами; и что, следовательно, ничего нельзя получить от таких шаблонов, как пулы объектов.
Я должен добавить, что наиболее требовательной к производительности частью приложения является синтаксический анализатор, который действительно создает множество недолговечных объектов в рамках своей работы.
Как вы думаете, время, проведенное в Object.<init> связано с? Это действительно связано с распределением памяти? Могу ли я извлечь выгоду из использования пула объектов или какого-то другого трюка для уменьшения выделения памяти?
РЕДАКТИРОВАТЬ:
В ответ на ответ Майка Данлавей, вот интерпретация результатов hprof, сделанная JPerfAnal, которая дает инклюзивное время.
Method Times by Caller (times inclusive): 3076 ticks
1: java.lang.Object.<init>: 71,26% (2192 inclusive / 2191 exclusive)
2: com.sun.demo.jvmti.hprof.Tracker.ObjectInit: 0,03% (1 inclusive / 0 exclusive)
3: java.lang.Thread.currentThread: 0,03% (1 inclusive / 1 exclusive)
1: parser.ParseData.<init>: 34,33% (1056 inclusive / 0 exclusive)
2: parser.ParseErrors.<init>: 13,98% (430 inclusive / 1 exclusive)
3: java.lang.Object.<init>: 7,18% (221 inclusive / 221 exclusive)
3: java.util.ArrayList.<init>: 6,76% (208 inclusive / 208 exclusive)
2: java.lang.Object.<init>: 13,52% (416 inclusive / 416 exclusive)
2: java.util.ArrayList.<init>: 6,83% (210 inclusive / 0 exclusive)
3: java.util.ArrayList.<init>: 6,83% (210 inclusive / 210 exclusive)
1: parser.Matcher.parse: 34,33% (1056 inclusive / 0 exclusive)
2: parser.ParseData.<init>: 34,33% (1056 inclusive / 0 exclusive)
3: parser.ParseErrors.<init>: 13,98% (430 inclusive / 1 exclusive)
4: java.lang.Object.<init>: 7,18% (221 inclusive / 221 exclusive)
4: java.util.ArrayList.<init>: 6,76% (208 inclusive / 208 exclusive)
3: java.lang.Object.<init>: 13,52% (416 inclusive / 416 exclusive)
3: java.util.ArrayList.<init>: 6,83% (210 inclusive / 0 exclusive)
4: java.util.ArrayList.<init>: 6,83% (210 inclusive / 210 exclusive)
1: java.util.ArrayList.<init>: 28,38% (873 inclusive / 419 exclusive)
2: java.util.AbstractList.<init>: 14,76% (454 inclusive / 0 exclusive)
3: java.util.AbstractCollection.<init>: 14,76% (454 inclusive / 0 exclusive)
4: java.lang.Object.<init>: 14,76% (454 inclusive / 454 exclusive)
(JPerfAnal также генерирует перевернутое дерево, где дети являются вызывающими для родителей. Я не воспроизводлю его для краткости, но достаточно сказать, что около 40% Object.<init> звонки сделаны из инициализации ArrayList, ParseData а также ParseErrors.)
Теперь, это не меняет того, как я думаю о проблеме или моих вопросах. Я мог бы изменить алгоритм так, чтобы он создавал меньше объектов; но пока я ищу ортогональное решение. Итак: могут ли пулы объектов помочь мне?
2 ответа
Короткий ответ:
Время проведенное в Object.<init> скорее всего, из-за того, что профиль процессора генерируется вместе с профилем кучи; последний инструктирует все распределения памяти, делая медленные выделения и заставляя их выходить на вершину профиля ЦП.
Длинный ответ:
Я подозреваю, что профиль, показанный в вопросе, был сгенерирован путем запроса одновременно профиля CPU и профиля кучи. Другими словами, это было сгенерировано, сделав что-то вроде:
java -agentlib:hprof=heap=sites,cpu=samples,depth=20 MyProg
К сожалению, по крайней мере, когда дело доходит до встроенного в JVM профилировщика hprof, выборка ЦП бесполезна при наличии профилирования кучи. Профилирование кучи обрабатывает все выделения памяти, что делает порядок выполнения программы более медленным. В программе, предназначенной для отслеживания распределения памяти, распределение действительно является узким местом, и именно поэтому Object.<init> выходит на вершину профиля процессора. Однако в реальной программе узкие места могут быть или не быть выделением / сборкой мусора.
Обычно вы хотите создать только один профиль за раз. Сначала создайте профиль процессора, запустив что-то вроде java -agentlib:hprof=cpu=samples,depth=20и проанализировать результаты этого. Если профиль ЦП указывает на распределение памяти / сборку мусора в качестве узкого места, то и только тогда сгенерируйте и проанализируйте профиль кучи, чтобы увидеть, откуда поступает большинство ваших выделений.
Другой ответ делает много важных замечаний об анализе профиля процессора. В частности, гораздо проще увидеть, что происходит с использованием JPerfAnal, чем смотреть на необработанный профиль процессора hperf. Кроме того, чтобы инклюзивные проценты были достаточно точными, вам может потребоваться увеличить глубину выборки из стека в соответствии с вашим приложением.
1) "Я" время почти всегда бесполезно, потому что реальная проблема в вашем коде, который вызывает эти низкоуровневые методы - получить инклюзивное время (self + callees).
2) Колонка "накапливается" еще более бесполезна, потому что все, что она делает - это добавляет время "себя".
Другие колонки также ничего вам не говорят.
hprof берет следы стека. Вам нужно, чтобы они были как можно глубже.
Вам не нужно их большое количество (вопреки распространенным заблуждениям о статистике) - десять, вероятно, более чем достаточно.
Однако вам нужно посмотреть на них и понять их.
Вот некоторая общая информация о профилировании.
РЕДАКТИРОВАТЬ в ответ на ваше изменение, показывающее вывод JPerfAnal:
а) Похоже, глубина стека составляет всего 4. Вы должны видеть глубину стека как можно глубже. Мне все равно, как они представляют результаты. Я в основном просто смотрю на сами образцы стеков. Время не очень важно. Важно то, что происходит и почему.
б) образцы стека на самом деле содержат информацию на уровне строк. Таким образом, они будут указывать на точные линии в ваших процедурах, как parser.ParseData.<init>, parser.Matcher.parse, а также parrser.ParseErrors.<init> где проблемные звонки происходят. Это точно скажет вам, какие ассигнования стоят все время, и тогда вы сможете решить, есть ли лучший способ сделать это.
У меня складывается впечатление, что парсер запускает таблицы структуры данных. Я знаю, что вы не хотите переделывать его, но если вы перепроектируете его, вы получите гораздо лучшую производительность. По сути, если вы можете выразить это как синтаксический анализатор с рекурсивным спуском, и если язык не меняется часто, вы пишете синтаксический анализатор непосредственно в коде - без таблиц - и это будет в 10-100 раз быстрее.