Почему первый раз цикл Java выполняется МЕДЛЕННО?[Sun HotSpot 1.5, SPARC]
https://stackoverflow.com/questions/860231
-
21-08-2019 - |
italiano
english
français
española
中国
日本の
العربية
Deutsch
한국어
Português
RussianВопрос
При тестировании некоторого Java-кода на компьютере Solaris SPARC я заметил, что при первом вызове тестируемой функции она выполняется ОЧЕНЬ медленно (разница в 10 раз):
- Первый | 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;
}
}
}
Решение
Какой-то уродливый, нереалистичный код (что-то вроде микробенчмарков):
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
Чтобы точно узнать, где начинается и заканчивается каждый из вызовов метода 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 и т. д.занятия, вот результаты.
Во время первого вызова метода Measure() было загружено в общей сложности 85 классов, было динамически скомпоновано 11 собственных методов и JIT-компилировано 5 методов:
[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, поэтому ваша система может работать немного по-другому.Например, возможно, одно из этих связываний динамических методов в вашей системе работает исключительно медленно.Или тогда загрузка всех классов будет медленнее.Попробуйте посмотреть логи, нет ли необычно длинной паузы или все ли эти операции выполняются одинаково медленно.
Добавьте загрузку классов в качестве подозреваемого.Классы загружаются лениво при первом обращении.Таким образом, при первом запуске кода вы, вероятно, впервые ссылаетесь на некоторые классы.
Лучший способ проверить, является ли JIT-компилятор причиной ускорения в последующих итерациях, — запустить тест с выключенным JIT-компилятором.Для этого укажите системное свойство java.compiler=NONE (слово «нет» должно быть в верхнем регистре).
Время, потраченное на загрузку классов, также может привести к замедлению работы тестируемого кода в первый раз.Наконец, существует недетерминированная задержка между вызовом Thread.start() и вызовом метода run() потока.
Возможно, вы захотите найти эталонную структуру.Хороший фреймворк «разогревает» код, выполняя несколько итераций, а затем выполняет несколько таймингов с разным количеством итераций.Видеть Теория и практика Java:Анатомия ошибочного микробенчмарка.
Это интересный вопрос.Я бы подозревал JIT-компилятор, но вот мои цифры:
First | 1 | 2399.233 ms Second | 1 | 2322.359 ms Third | 1 | 2408.342 ms
Возможно, Solaris делает что-то странное с потоками;ты пробовал с nThreads = 10 или так?
Я предлагаю вам сделать nThread = Runtime.getRuntime().availableProcessors(). Это даст вам оптимальное количество потоков для использования всех ядер вашей системы.
Вы можете попробовать отключить JIT, чтобы увидеть, какая разница.
Вы можете заставить виртуальную машину регистрировать информацию о загрузке классов и компиляции, попробуйте следующие аргументы виртуальной машины:-Xx:+printcompilation -xx:+Traceclassloading Это может дать некоторые дополнительные подсказки относительно того, что происходит под капюшоном.
РЕДАКТИРОВАТЬ:Я не уверен, что эти параметры работают в Java 1.5 (я использовал их в 1.6).попробую проверить...РЕДАКТИРОВАТЬ еще раз:Он работает в Java 1.5 (обратите внимание, что вам нужен +, а не -, или вы отключите эту опцию...)
Я считаю, что вы также можете использовать нестандартную опцию для Java-команды -Xint, чтобы отключить HotSpot и интерпретировать только свой код.Это, по крайней мере, может исключить HotSpot из уравнения для интерпретации вашего времени.
Это компилятор горячих точек в действии.AFAIK, при первом запуске функции выполняется «интерпретация» и анализируется путь выполнения, после чего JIT-компилятор может оптимизировать последующие вызовы функций.
Это наверняка компилятор точки доступа.Если вы используете 64-битную версию Solaris, по умолчанию используется виртуальная машина сервера и точка доступа, просто начните оптимизацию при первом запуске.На клиентской виртуальной машине код может потребоваться выполнить несколько раз, прежде чем сработает точка доступа.(я думаю только Солярис имеет сервер ВМ, но я могу ошибаться)
Видеть http://java.sun.com/javase/6/docs/technotes/guides/vm/server-class.html о том, как программа запуска выбирает между клиентской и серверной виртуальной машиной и что поддерживается различными процессорами и операционными системами.
