Подтвердить что ты не робот

Первый цикл Java выполняется SLOW, почему? [Sun HotSpot 1.5, sparc]

При сопоставлении некоторого кода Java в окне Solaris SPARC я заметил, что в первый раз, когда я вызываю контрольную функцию, она работает ЧРЕЗВЫЧАНО медленно (разница 10x):

  • Сначала | 1 | 25295,979 мс
  • Второе | 1 | 2256.990 мс
  • Третий | 1 | 2250.575 мс

Почему это? Я подозреваю JIT-компилятор, есть ли способ проверить это?

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

Решено: Том Хотин правильно указал, что мое "МЕДЛЕННОЕ" время было действительно разумным. Следуя этому наблюдению, я подключил отладчик к процессу Java. Во время первого внутреннего цикла выглядит так:

0xf9037218:     cmp      %l0, 100
0xf903721c:     bge,pn   %icc,0xf90371f4        ! 0xf90371f4
0xf9037220:     nop
0xf9037224:     ld       [%l3 + 92], %l2
0xf9037228:     ld       [%l2 + 8], %l6
0xf903722c:     add      %l6, 1, %l5
0xf9037230:     st       %l5, [%l2 + 8]
0xf9037234:     inc      %l0
0xf9037238:     ld       [%l1], %g0
0xf903723c:     ba,pt    %icc,0xf9037218        ! 0xf9037218

В следующих итерациях цикл выглядит следующим образом:

0xf90377d4:     sub      %l2, %l0, %l3
0xf90377d8:     add      %l3, %l0, %l2
0xf90377dc:     add      %l2, 1, %l4
0xf90377e0:     inc      %l0
0xf90377e4:     cmp      %l0, 100
0xf90377e8:     bl,pn    %icc,0xf90377d8        ! 0xf90377d8

Таким образом, HotSpot удалил доступ к памяти из внутреннего цикла, ускорив его на порядок.

Урок: Сделайте математику! Я должен был сделать сам Том.

Сравнительный код Java:

    private int counter;
    private int nThreads;

    private void measure(String tag) throws Exception {
            MyThread threads[] = new MyThread[nThreads];
            int i;

            counter = 0;

            for (i = 0; i < nThreads; i++)
                    threads[i] = new MyThread();

            long start = System.nanoTime();

            for (i = 0; i < nThreads; i++)
                    threads[i].start();

            for (i = 0; i < nThreads; i++)
                    threads[i].join();

            if (tag != null)
                    System.out.format("%-20s | %-2d | %.3f ms \n", tag, nThreads,
                                     new Double((System.nanoTime() - start) / 1000000.0));
    }
    public MyBench() {
            try {
                    this.nThreads = 1;
                    measure("First");
                    measure("Second");
                    measure("Third");
            } catch (Exception e) {
                    System.out.println("Error: " + e);
            }
    }

    private class MyThread extends Thread {
            public void run() {
                    while (counter < 10000000) {
                            // work
                            for (int j = 0; j < 100; j++)
                                    counter++;
                            counter -= 99;
                    }
            }
    }
4b9b3361

Ответ 1

Какой-то уродливый, нереалистичный код (материал микрообъектов):

                while (counter < 10000000) {
                        // work
                        for (int j = 0; j < 100; j++)
                                counter++;
                        counter -= 99;
                }

Итак, что это такое и как быстро он должен работать.

Внутренний цикл увеличивает счетчик 100 раз, тогда счетчик уменьшается на 99. Таким образом, приращение 1. Note counter является переменной-членом внешнего класса, поэтому некоторые накладные расходы там. Затем это выполняется 10 000 000 раз. Таким образом, внутренний цикл запускается 1 000 000 000 раз.

Цикл, использующий методы доступа, называет его 25 циклами. 1 000 000 000 раз при 1 ГГц, дает 25 с.

Эй, мы предсказали время медленное. Медленное время очень быстрое. Быстрые времена после того, как контрольный показатель был сломан каким-то образом - 2,5 цикла итерации? Используйте -server, и вы можете обнаружить, что он становится еще глупым.

Ответ 2

Вероятно, это загрузка классов или динамическое связывание собственных методов. Если вы запустите Java со следующими параметрами JVM (см. здесь для полного списка), он распечатает информацию о том, что занимает время:

-verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation

Чтобы узнать, где именно начинается и заканчивается каждый из вызовов measure(), добавьте инициализации некоторых новых классов между этими методами в качестве маркеров, чтобы -verbose:class покажет, в какой момент в журналах загружен класс маркера. См. этот ответ для аналогичного измерения.

Чтобы узнать, что именно делает ваш код, я изменил его следующим образом:

public MyBench() {
    try {
        this.nThreads = 1;
        new Mark1();
        measure("First");
        new Mark2();
        measure("Second");
        new Mark3();
        measure("Third");
        new Mark4();
    } catch (Exception e) {
        System.out.println("Error: " + e);
    }
}

private static class Mark1 {
}
private static class Mark2 {
}
private static class Mark3 {
}
private static class Mark4 {
}

Затем, посмотрев, когда JVM загрузил эти классы Mark1 и т.д., вот результаты.

Во время первого вызова для измерения() было загружено в общей сложности 85 классов, 11 динамических связей были связаны между собой, а 5 методов были скомпилированы JIT:

[Loaded MyBench$Mark1 from file:/D:/DEVEL/Test/classes/]
[Loaded java.net.InetSocketAddress from shared objects file]
[Loaded java.net.InetAddress from shared objects file]
[Loaded MyBench$MyThread from file:/D:/DEVEL/Test/classes/]
[Loaded sun.security.action.GetBooleanAction from shared objects file]
[Dynamic-linking native method java.net.InetAddress.init ... JNI]
[Loaded java.net.InetAddress$Cache from shared objects file]
[Loaded java.lang.Enum from shared objects file]
[Loaded java.net.InetAddress$Cache$Type from shared objects file]
[Loaded java.net.InetAddressImplFactory from shared objects file]
[Dynamic-linking native method java.net.InetAddressImplFactory.isIPv6Supported ... JNI]
 22       MyBench::access$508 (12 bytes)
[Loaded java.net.InetAddressImpl from shared objects file]
[Loaded java.net.Inet4AddressImpl from shared objects file  1%      MyBench$MyThread::run @ 14 (48 bytes)
]
[Loaded sun.net.spi.nameservice.NameService from shared objects file]
[Loaded java.net.InetAddress$1 from shared objects file]
[Loaded java.net.Inet4Address from shared objects file]
[Dynamic-linking native method java.net.Inet4Address.init ... JNI]
[Dynamic-linking native method java.net.PlainSocketImpl.socketCreate ... JNI]
[Dynamic-linking native method java.net.PlainSocketImpl.socketBind ... JNI]
[Dynamic-linking native method java.net.PlainSocketImpl.socketListen ... JNI]
[Loaded java.net.Socket from shared objects file]
[Dynamic-linking native method java.net.PlainSocketImpl.socketAccept ... JNI]
[Loaded java.lang.Integer$IntegerCache from shared objects file]
[Loaded java.util.Formatter from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.regex.Pattern$6 from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.text.DecimalFormatSymbols from shared objects file]
[Loaded java.util.spi.LocaleServiceProvider from shared objects file]
[Loaded java.text.spi.DecimalFormatSymbolsProvider from shared objects file]
[Loaded sun.util.LocaleServiceProviderPool from shared objects file]
[Loaded java.util.LinkedHashSet from shared objects file]
[Loaded sun.util.LocaleServiceProviderPool$1 from shared objects file]
[Loaded java.util.ServiceLoader from shared objects file]
[Loaded java.util.ServiceLoader$LazyIterator from shared objects file]
[Loaded java.util.ServiceLoader$1 from shared objects file]
[Loaded java.util.HashMap$EntrySet from shared objects file]
[Loaded java.util.LinkedHashMap$LinkedHashIterator from shared objects file]
[Loaded java.util.LinkedHashMap$EntryIterator from shared objects file]
[Loaded sun.misc.Launcher$1 from shared objects file]
 23  !    java.io.BufferedReader::readLine (304 bytes)
[Loaded sun.misc.Launcher$2 from shared objects file]
[Loaded sun.misc.URLClassPath$2 from shared objects file]
[Loaded java.lang.ClassLoader$2 from shared objects file]
[Loaded sun.misc.URLClassPath$1 from shared objects file]
[Loaded java.net.URLClassLoader$3 from shared objects file]
[Loaded sun.misc.CompoundEnumeration from shared objects file]
 24       sun.nio.cs.UTF_8$Decoder::decodeArrayLoop (553 bytes)
[Loaded java.io.FileNotFoundException from shared objects file]
[Loaded java.net.URLClassLoader$3$1 from shared objects file]
[Dynamic-linking native method java.security.AccessController.doPrivileged ... JNI]
[Loaded sun.util.resources.LocaleData from shared objects file]
[Loaded sun.util.resources.LocaleData$1 from shared objects file]
[Loaded java.util.ResourceBundle$Control from shared objects file]
[Loaded sun.util.resources.LocaleData$LocaleDataResourceBundleControl from shared objects file]
[Loaded java.util.Arrays$ArrayList from shared objects file]
[Loaded java.util.Collections$UnmodifiableCollection from shared objects file]
 25       java.lang.String::startsWith (78 bytes)
[Loaded java.util.Collections$UnmodifiableList from shared objects file]
[Loaded java.util.Collections$UnmodifiableRandomAccessList from shared objects file]
[Loaded java.util.ResourceBundle from shared objects file]
[Loaded java.util.ResourceBundle$1 from shared objects file]
[Dynamic-linking native method java.util.ResourceBundle.getClassContext ... JNI]
[Loaded java.util.ResourceBundle$RBClassLoader from shared objects file]
[Loaded java.util.ResourceBundle$RBClassLoader$1 from shared objects file]
[Loaded java.util.ResourceBundle$CacheKey from shared objects file]
[Loaded java.util.ResourceBundle$CacheKeyReference from shared objects file]
[Loaded java.util.ResourceBundle$LoaderReference from shared objects file]
[Loaded java.util.ResourceBundle$SingleFormatControl from shared objects file]
[Loaded sun.util.LocaleDataMetaInfo from shared objects file]
[Loaded java.util.AbstractList$Itr from shared objects file]
[Loaded java.util.ListResourceBundle from shared objects file]
[Loaded sun.text.resources.FormatData from shared objects file]
[Dynamic-linking native method java.lang.Class.isAssignableFrom ... JNI]
[Loaded java.util.ResourceBundle$BundleReference from shared objects file]
[Loaded sun.text.resources.FormatData_fi from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.text.resources.FormatData_fi_FI from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Currency from shared objects file]
[Loaded java.util.Currency$1 from shared objects file]
[Loaded java.util.CurrencyData from shared objects file]
[Loaded sun.reflect.UnsafeFieldAccessorFactory from shared objects file]
[Loaded sun.reflect.UnsafeQualifiedStaticFieldAccessorImpl from shared objects file]
[Loaded sun.reflect.UnsafeQualifiedStaticObjectFieldAccessorImpl from shared objects file]
[Loaded java.util.spi.CurrencyNameProvider from shared objects file]
[Loaded sun.util.resources.OpenListResourceBundle from shared objects file]
[Loaded sun.util.resources.LocaleNamesBundle from shared objects file]
[Loaded sun.util.resources.CurrencyNames from shared objects file]
[Loaded sun.util.resources.CurrencyNames_fi_FI from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.regex.MatchResult from shared objects file]
[Loaded java.util.regex.Matcher from shared objects file]
[Loaded java.util.regex.ASCII from shared objects file]
[Loaded java.util.Formatter$FormatString from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$FormatSpecifier from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$Flags from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$Conversion from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formatter$FixedString from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded java.util.Formattable from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Dynamic-linking native method java.io.FileOutputStream.writeBytes ... JNI]
First                | 1  | [Loaded sun.misc.FormattedFloatingDecimal from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.misc.FormattedFloatingDecimal$1 from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.misc.FormattedFloatingDecimal$Form from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
[Loaded sun.misc.FormattedFloatingDecimal$2 from C:\Program Files\Java\jdk1.6.0_11\jre\lib\rt.jar]
2072,825 ms 

Во время второго вызова только один метод был скомпилирован JIT:

[Loaded MyBench$Mark2 from file:/D:/DEVEL/Test/classes/]
 26       MyBench$MyThread::run (48 bytes)
Second               | 1  | 2058,669 ms 

Во время третьего вызова не было никакой дополнительной работы:

[Loaded MyBench$Mark3 from file:/D:/DEVEL/Test/classes/]
Third                | 1  | 2093,659 ms 

Это было выполнено в Windows с помощью jdk1.6.0_11, поэтому ваша система могла бы сделать что-то по-другому. Например, возможно, одна из этих связей динамических методов исключительно медленна в вашей системе. Или тогда все загрузки классов медленнее. Попробуйте взглянуть на журналы, есть ли необычно длинная пауза или все эти операции одинаково медленны.

Ответ 3

Добавить загрузку класса в качестве подозреваемого. Классы загружаются лениво при первой ссылке. Поэтому при первом запуске кода вы, вероятно, ссылаетесь на некоторые классы в первый раз.

Ответ 4

Лучший способ проверить, является ли компилятор JIT причиной ускорения в последующих итерациях, - это запустить тест с выключенным компилятором JIT. Для этого укажите системное свойство java.compiler=NONE (слово "none" должно быть в верхнем регистре).

Время, затрачиваемое на загрузку классов, также может привести к медленному запуску эталонного кода в первый раз. Наконец, существует неопределенная задержка между вызовом метода Thread.start() и вызываемого метода Thread().

Возможно, вам захочется найти базовую платформу. Хорошая структура "разогревает" код, запуская несколько итераций, а затем выполняет несколько таймингов с различным количеством итераций. См. Теория и практика Java: анатомия ошибочного микрообъекта.

Ответ 5

Это интересный вопрос. Я подозреваю JIT-компилятор, но это мои номера:

First                | 1  | 2399.233 ms 
Second               | 1  | 2322.359 ms 
Third                | 1  | 2408.342 ms 

Возможно, Solaris делает что-то смешное с потоками; вы пробовали с помощью nThreads = 10 или так?

Ответ 6

Я предлагаю вам сделать nThread = Runtime.getRuntime(). availableProcessors() Это даст вам оптимальное количество потоков для использования всех ядер в вашей системе.

Вы можете попробовать отключить JIT, чтобы узнать, какая разница.

Ответ 7

Вы можете заставить виртуальную машину регистрировать информацию о загрузке и компиляции классов, попробуйте следующие аргументы VM: -XX: + PrintCompilation -XX: + TraceClassLoading Это может дать некоторые дополнительные сведения о том, что происходит под капотом.

EDIT: Я не уверен, что эти параметры работают в java 1.5 (я использовал их в версии 1.6). Я постараюсь проверить... EDIT еще раз: он работает в java 1.5 (обратите внимание, что вам нужно +, а не -, или вы отключите опцию...)

Ответ 8

Я считаю, что вы также можете использовать нестандартную опцию для java-команды -Xint для отключения HotSpot и только для вашего кода. Это могло бы по крайней мере вывести HotSpot из уравнения для интерпретации вашего времени.

Ответ 9

Это компилятор hotspot на работе. AFAIK, при первом запуске функции, запускает "интерпретируемый" и анализируется путь выполнения, тогда компилятор JIT может оптимизировать последующие вызовы функций.

Ответ 10

Это, безусловно, компилятор hotspot. Если вы работаете на 64-битном Solaris, то по умолчанию сервер VM и точка доступа просто начинают оптимизацию при первом выполнении. На клиентской виртуальной машине код может понадобиться запустить несколько раз до того, как точка hotspot начнет работать. (Я считаю, что у Solaris только сервер vm, но я могу ошибаться)