Первый раз цикл Java запускается МЕДЛЕННО, почему? [Sun HotSpot 1.5, sparc]
При тестировании некоторого Java-кода на блоке Solaris SPARC я заметил, что при первом вызове тестируемой функции она запускается ОЧЕНЬ медленно (разница в 10 раз):
- Первый | 1 | 25295,979 мс
- Второй | 1 | 2256,999 мс
- Третий | 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;
}
}
}
11 ответов
Какой-то уродливый, нереалистичный код (материал микробенчмарок):
while (counter < 10000000) {
// work
for (int j = 0; j < 100; j++)
counter++;
counter -= 99;
}
Так, что это делает и как быстро это должно бежать.
Внутренний цикл увеличивает значение счетчика в 100 раз, затем значение счетчика уменьшается на 99. Таким образом, значение увеличивается на 1. Счетчик примечаний - это переменная-член внешнего класса, поэтому некоторые накладные расходы там. Затем запускается 10 000 000 раз. Таким образом, внутренний цикл выполняется 1 000 000 000 раз.
Цикл, используемый для доступа к методам, называется 25 циклами. 1 000 000 000 раз на 1 ГГц, дает 25 с.
Эй, мы предсказали МЕДЛЕННОЕ время. Медленное время быстро. Быстрое время наступило после того, как тест был каким-то образом нарушен - 2,5 цикла за итерацию? Используйте -server, и вы можете обнаружить, что он становится еще более глупым.
Вероятно, это загрузка классов или динамическое связывание нативных методов. Если вы запустите Java со следующими параметрами JVM (полный список см. Здесь), он напечатает информацию о том, что занимает время:
-verbose:class -verbose:jni -verbose:gc -XX:+PrintCompilation
Чтобы точно определить, где каждая из мер () вызывает начало и конец, добавьте инициализации некоторых новых классов между этими методами в качестве маркеров, чтобы -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 и т. Д., Вот результаты.
Во время первого вызова метода measure() было загружено в общей сложности 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
Во время второго вызова был скомпилирован только один метод:
[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, поэтому ваша система может делать что-то немного иначе. Например, может быть, одна из этих связей динамических методов исключительно медленная в вашей системе. Или тогда загрузка всего класса будет медленнее. Попытайтесь взглянуть на журналы, есть ли необычно длинная пауза, или все эти операции одинаково медленны.
Лучший способ проверить, является ли JIT-компилятор причиной ускорения на более поздних итерациях, - запустить тест с выключенным JIT-компилятором. Для этого укажите системное свойство java.compiler=NONE (слово "нет" должно быть в верхнем регистре).
Время, потраченное на загрузку классов, также может привести к тому, что тестируемый код будет выполняться медленнее в первый раз. Наконец, существует недетерминированная задержка между вызовом Thread.start() и вызываемым методом Thread ().
Возможно, вы захотите подумать о поиске эталонной структуры. Хороший фреймворк "разогреет" код, выполнив несколько итераций, а затем проведет несколько таймингов с разным количеством итераций. См. Теория и практика Java: Анатомия дефектного микробенчмарка.
Добавьте загрузку класса в качестве подозреваемого. Классы загружаются лениво при первом обращении. Поэтому при первом запуске кода вы, вероятно, обращаетесь к некоторым классам в первый раз.
Вы можете заставить ВМ регистрировать информацию о загрузке классов и компиляции, попробуйте следующие аргументы ВМ: -XX:+PrintCompilation -XX:+TraceClassLoading Это может дать некоторые дополнительные подсказки относительно того, что происходит под капотом.
РЕДАКТИРОВАТЬ: Я не уверен, что эти опции работают в Java 1.5 (я использовал их в 1.6). Я попытаюсь проверить... РЕДАКТИРОВАТЬ снова: это работает в Java 1.5 (обратите внимание, что вам нужно +, а не -, или вы отключите опцию...)
Я полагаю, что вы также можете использовать нестандартную опцию для команды java -Xint, чтобы отключить HotSpot и интерпретировать только ваш код. Это может, по крайней мере, вывести HotSpot из уравнения для интерпретации вашего времени.
Я предлагаю вам сделать nThread = Runtime.getRuntime(). AvailableProcessors(). Это даст вам оптимальное количество потоков для использования всех ядер вашей системы.
Вы можете попробовать отключить JIT, чтобы увидеть, какая разница.
Это интересный вопрос. Я подозреваю, что JIT-компилятор, но это мои цифры:
Первый | 1 | 2399,233 мс Второй | 1 | 2322,359 мс Третий | 1 | 2408,342 мс
Возможно, Solaris делает что-то смешное с потоками; ты пробовал с nThreads = 10 или так?
Это, безусловно, компилятор горячей точки. Если вы используете 64-разрядную версию Solaris, по умолчанию используется виртуальная машина сервера, и точка доступа просто начинает оптимизацию при первом запуске. На клиентской виртуальной машине может потребоваться несколько раз выполнить код, прежде чем активируется точка доступа. (Я считаю, что у Solaris есть только сервер vm, но я могу ошибаться)
См. http://java.sun.com/javase/6/docs/technotes/guides/vm/server-class.html чтобы узнать, как программа запуска выбирает виртуальную машину клиента и сервера и что поддерживается на разных процессорах и ОС.
Это компилятор горячей точки на работе. AFAIK, при первом запуске функции запускается "интерпретированный" и анализируется путь выполнения, затем компилятор JIT может оптимизировать последующие вызовы функций.