Режим Sampling
дает самые меньшие искажения и почти незаметен для профилируемого сервиса, по нему можно понять, что какая-то строка кода выполняется, например, 60% времени
По данным семплирования удобно строить Flame диаграммы, как на скриншоте
И данная строка может быть горячей по разным причинам:
🤩медленная операция которая потребляет CPU
🤩выделяет память
🤩походы на диск
🤩походы по сети
🤩и может быть это супер быстрый код, но который вызывают 1 000 000 раз в цикле
Вот в этом последнем варианте причина медленной работы в том методе который вызывает данный метод 1 000 000 раз
Это довольно частый случай. А технически задача становится такой:
🤩собрать статистику по количеству выполнений методов
🤩наложить статистику с количеством на данные семплирования
Сбор статистики по количеству выполнений бывает двух видов
🤩без номеров строк и вышестоящих запросов (Call Counting) — быстрый
🤩с номерами строк (Tracing) — медленный
В Call Counting попадают абсолютно все вызовы данного метода, и если метод — это некий популярный интерфейс, как
EntityIteratorBase.hasNext, то по нему будут миллионы вызовов в статистике, даже если в профилируемой операции он вызывался 10 000 раз только. Обычно такие методы в начале или середине стека. Они есть при каждом HTTP-запросе и каждой операции и Call Counting покажет для них очень высокие значения. Но вот для уникальных строк в конце стек-трейса, таких как
Delegator.checkPage (вершина Flame graph), Call Counting будет работать очень точно. Он покажет точные значения. Потому что чаще всего это узкое место уникально для этого запроса. А еще будут точные значения про метод который вызывал этот метод. И может быть про предыдущийКак понять, что числа в Call Counting более менее настоящие
Например, смотрим на метрики сверху вниз
🤩DataIterator.checkPage — 27 000 000 вызовов
🤩PatriciaTreeBase.getDataIterator — 5 000 000 вызовов (такое может быть, этот метод вызывает checkPage примерно по 5-6 раз)
🤩PatriciaTreeBase.getLoggable — 5 000 000 вызовов (такое может быть, он вызывает getDataIterator только один раз)
🤩PatriciaTreeBase.loadNode — 5 000 000 (ok)
🤩ChildReference.getNode - 1 600 000 (этот вызывает loadNode 3 раза)
🤩PatriciaTraverser.moveDown — 80 000 000
Тут я выдумал число 80 000 000 для сокращения, но если вдруг количество по вышестоящему методу резко выроcло, а не упало — то это означает, что дальше метрикам Call Counting верить нельзя. Они свое отработали, показали для методов нижнего уровня сколько вызовов приходится на следующий:
🤩x5, x1, x1, x1, x3, x???
Дальше можно продолжать разматывать стек, но уже держа в голове, что это замусоренные данные.
И в какой-то момент придется переключиться на данные трассировки. Это самые неточные данные. Трассировка хоть и самая детальная, но вносит столько изменений и замедлений в код, что часто выполнение кода становится уже неполным (завершается по таймауту) или искаженным. Она покажет неполные данные — например скачок в
x218208 на данных трассировки в реальности может быть и скачком в x1000000, но код просто не дожил то итерации в 1 000 000 и прервался на 218208. Но это лучшая оценкаВсе такие множители удобно записывать в виде комментариев к строкам стек-трейса — просто через //
И когда разработчики будут смотреть на такой аннотированный трейс, то будут говорить спасибо. А чтобы его получить надо будет сделать три разных профилирования одной и той же операции


