Java VisualVM дает причудливые результаты для профилирования CPU. Кто-нибудь еще сталкивается с этим?

Я написал этот небольшой (и жестоко неэффективный) класс и хотел его профилировать с помощью Java VisualVM.

public class Test {

    public static void main(String[] args) throws IOException {
        BufferedReader br = new BufferedReader(new InputStreamReader(System.in));
        br.readLine();
        int n = Integer.parseInt(args[0]);
        int fib = fib(n);
        System.out.println(fib);
    }

    private static int fib(int n) {
        if (n < 2) {
            return n;
        }
        return fib(n-1)+fib(n-2);
    }
}

Результаты выглядят странно. В результатах полностью доминируют вызовы ConnectionHandler.run().

(98.2%) sun.rmi.transport.tcp.TCPTransport $ConnectionHandler.run()
(1,7%) java.lang.Thread.join(long)
(0%) java.lang.String.equals(Object)
и т.д...

Есть, вероятно, около ста методов профилированных, и ни один из них не является fib (int)!

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

Что я делаю неправильно?

Отредактировано для ясности:. Если вы передадите 45 для n, это приложение будет работать в течение 20 хорошо профилированных секунд. Первоначально программа, которую я профилировал (а не фибоначчивый калькулятор), привязывала все четыре ядра к моему процессору на 100%, и я делал профайлинговые прогоны продолжительностью до 5 минут. Эти же результаты и методы из моего приложения не отображались высоко в списке методов горячей точки.

Он варьируется от run to run, но ConnectionHandler.run() всегда находится наверху и обычно составляет ~ 99% от времени профиля.

Second Edit: Я попытался использовать сэмплер, и теперь я получаю результаты, которые согласуются с тем, что производит JProfiler. Недостатком этого является то, что я не получаю информацию о трассировке стека, которая поставляется с профилированием. Но для моих непосредственных потребностей это превосходно.

Что-то, что я обнаружил во время игры, - это то, что VisualVM учитывает настенные часы для вызовов методов при их профилировании.

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

Это означает, что метод блокировки, по-видимому, будет занимать почти все время на профилировщике, несмотря на то, что это не тот метод, который ест мой процессор.

Я бы ожидал, что то же самое относится к методу sun.rmi.transport.tcp.TCPTransport $ConnectionHandler.run(), который выполняет свою работу красиво - но когда он завершается, он становится одним из самых длинных запущенных методов в моем приложении - повторно.

Ответ 1

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

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

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

это не очевидно, когда нужно оптимизировать усилия по оптимизации; и
в полезной нагрузке есть какая-то значительная работа.

Если вы действительно хотите протестировать этот код, вам, вероятно, нужно поднять его эффект (например), заменив:

int fib = fib(n);

с:

for (int i = 0; i < 100000; i++) {
    int fib = fib(n);
)

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

Таким образом, я имею в виду, что бинарный поиск является хорошим кандидатом, поскольку он удаляет половину оставшегося пространства поиска с каждым уровнем рекурсии (так что пространство поиска из миллиарда элементов составляет всего 30 уровней).

С другой стороны, использование рекурсии для последовательности Фибоначчи на количестве 1,000,000,000 заняло бы около миллиарда уровней, и большинство стеков было бы трудно содержать это.

Оптимизация рекурсии хвоста может избежать этой проблемы, но вам нужно быть осторожным, если оптимизация не будет выполнена.

Ответ 2

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

Переместите свой метод fib в другой класс и повторите попытку профилирования. Вы можете добавить опцию jvm "-verbose: class", чтобы дважды проверить, что класс не загружен, прежде чем вы включите профилирование cpu в jvisualvm.

Изменить: Спасибо JB за комментарий. Забудьте мою загрузочную фигню. Моя интуиция заключается в том, что метод fib слишком тесно связан с основным методом, поэтому он эффективно выполняет байт-код в настоящее время.

Ответ 3

На основе ответа Рона удалось улучшить результат, остановив JVM сразу после запуска, затем активировав профайлер и, наконец, после этого продолжим выделение (нажав enter). Это грубо.

class Foobar {
    /* First line in Class */
      static {
        try {
            System.in.read();
        } catch (IOException e) {
            throw new RuntimeException(e);
        }
    }
    /* .. */
    public static void main(..) {
        doMagic()
    }
}

Ответ 4

Моя догадка заключается в том, что вы пропускаете слишком мало значения для фик, и программа просто не работает достаточно долго, чтобы зарегистрироваться. Чтобы получить значимые данные практически для любого, когда вы выполняете профилирование (или сканирование), вам обычно требуется истекшее время, по крайней мере, несколько секунд.