Почему первый запуск всегда намного медленнее?

Я написал макрос, который сообщает время, необходимое для выполнения данной операции. Он запускает его несколько раз и выводит время для каждого запуска в наносекундах. Первый запуск всегда занимает значительно больше времени, чем последующие. Почему это так?

Вот результаты 10 x 10 прогонов, время Thread.yield():

> (dotimes [x 10] (prn (times 10 (Thread/yield))))

[55395 1659 622 561 591 702 795 719 742 624]
[3255 772 884 677 787 634 605 664 629 657]
[3431 789 965 671 774 767 627 627 521 717]
[2653 780 619 632 616 614 606 602 629 667]
[2373 759 700 676 557 639 659 654 659 676]
[2884 929 627 604 689 614 614 666 588 596]
[2796 749 672 769 667 852 629 589 627 802]
[1308 514 395 321 352 345 411 339 436 315]
[1390 363 328 337 330 321 324 347 333 342]
[1461 416 410 320 414 381 380 388 388 396]

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

Код макроса times:

(defmacro time
  [expr]
  `(let [t1# (System/nanoTime)]
     ~expr 
     (- (System/nanoTime) t1#)))

(defmacro times
  [reps expr]
  `(loop [reps# ~reps times# []]
     (if (zero? reps#) 
       times#
       (recur (dec reps#) (conj times# (time ~expr))))))

Декомпиляция приводит к следующему результату, поэтому System.nanoTime(), кажется, вызывается непосредственно перед и после Thread.yield(), как и предполагалось:

> (decompile (dotimes [x 10] (prn (times 10 (Thread/yield)))))

...

public Object invoke() {
    long reps__1952__auto__2355 = 10L;
    Object times__1953__auto__2356 = PersistentVector.EMPTY;
    while (reps__1952__auto__2355 != 0L) {
        final long dec = Numbers.dec(reps__1952__auto__2355);
        final IFn fn = (IFn)const__3.getRawRoot();
        final Object o = times__1953__auto__2356;
        times__1953__auto__2356 = null;
        final long t1__1946__auto__2354 = System.nanoTime();
        Thread.yield();
        times__1953__auto__2356 = fn.invoke(o, Numbers.num(Numbers.minus(System.nanoTime(), t1__1946__auto__2354)));
        reps__1952__auto__2355 = dec;
    }
    final Object o2 = times__1953__auto__2356;
    times__1953__auto__2356 = null;
    return o2;
}

person Evgeniy Berezovsky    schedule 12.02.2018    source источник
comment
Связанные вопросы и ответы включают объяснения различных причин такого поведения в тесте Java.   -  person Stephen C    schedule 12.02.2018
comment
ХОРОШО. Так что он, должно быть, сделал это за несколько секунд между тем, как я добавил свой дубликат, и он удалил свой. Я так и не увидел его ссылку. Но факт остается фактом: удаления первого тайминга не обязательно достаточно, и дублирование объясняет, почему.   -  person Stephen C    schedule 12.02.2018
comment
@StephenC Обращаясь к тому, что вы пометили это как дубликат: я не спрашиваю о том, как написать хороший микротест, меня особенно интересует, почему каждый первый запуск каждой партии медленнее, чем остальные. Насколько я знаю, это может быть даже результатом того, как работает clojure, и не имеет прямого отношения к java.   -  person Evgeniy Berezovsky    schedule 12.02.2018
comment
Как я уже сказал, связанные ответы и связанные статьи объясняют различные факторы, которые приводят к замедлению. Насколько я знаю, здесь нет особых проблем с закрытием. Или проблемы, связанные с Java. Все эффекты находятся на уровне JVM: загрузка байт-кода, начальная интерпретация, JIT-компиляция, изменение размера кучи и стабилизация.   -  person Stephen C    schedule 12.02.2018
comment
И, как вы можете видеть из декомпилированного кода, все это преобразуется в байт-коды, которые можно декомпилировать в обычный код Java. JVM обрабатывает его, как и любые другие байт-коды...   -  person Stephen C    schedule 12.02.2018
comment
@StephenC голосует за повторное открытие, так как для меня это не проблема эталона, этот код не запускается столько раз или меньше, это что-то другое   -  person Eugene    schedule 12.02.2018
comment
Это не относится ни к JVM, ни к Clojure, а скорее к системному таймеру и планировщику ОС. Я не могу воспроизвести проблему в Windows, но отчетливо вижу эффект в Linux и macOS, даже с программой на чистом C: ">gist.github.com/apangin/9b298993d750c2e18ea7e34eb915e244 Чем больше работы выполняется вне цикла - тем длиннее следующий yield.   -  person apangin    schedule 12.02.2018
comment
@apangin Ваша интересная суть кажется уместной здесь и заслуживает отдельного ответа, на который я мог бы, например, комментарий с моими собственными результатами, которые отличаются от ваших.   -  person Evgeniy Berezovsky    schedule 13.02.2018
comment
@EugeneBeresovsky Не стесняйтесь комментировать это прямо здесь. Это еще не ответ, но я уверен, что сам ввод-вывод (например, System.out.println) не имеет значения. Важен объем работы процессора, выполняемой до yield. Планировщик ОС учитывает это, пытаясь справедливо разделить процессорное время между процессами.   -  person apangin    schedule 13.02.2018


Ответы (2)


Первый запуск всегда занимает значительно больше времени, чем последующие. Почему это так?

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

(for [_ (range 10)]
  (times 10 (Thread/yield)))
=>
([32674 1539 1068 1063 1027 1026 1025 1031 1034 1035]
 [1335 1048 1030 1036 1043 1037 1036 1031 1034 1047]
 [1088 1043 1029 1035 1045 1035 1036 1035 1045 1047]
 [1051 1037 1032 1031 1048 1045 1039 1045 1042 1037]
 [1054 1048 1032 1036 1046 1029 1038 1038 1039 1051]
 [1050 1051 1039 1037 1038 1035 1030 1030 1045 1031]
 [1054 1045 1034 1034 1045 1037 1037 1035 1046 1044]
 [1051 1041 1032 1050 1061 1039 1045 1041 1057 1034]
 [1052 1042 1034 1032 1035 1045 1043 1038 1052 1052]
 [1053 1053 1041 1043 1053 1044 1039 1042 1051 1038])

Если вы используете System.out.println в своем тесте вместо prn, вы должны увидеть такое же замедление, но гораздо менее преувеличенное:

(dotimes [x 10]
  (.println System/out (times 10 (Thread/yield))))
=> nil
[33521 1733 1232 1161 1150 1135 1151 1138 1143 1144]
[1724 1205 1149 1152 1141 1149 1149 1150 1139 1145]
[1368 1156 1141 1139 1147 1149 1141 1147 1141 1149]
[1306 1159 1150 1141 1150 1148 1147 1142 1144 1149]
[1329 1161 1155 1144 1140 1155 1151 1149 1149 1140]
[1319 1154 1140 1143 1147 1154 1156 1149 1148 1145]
[1291 1166 1164 1149 1140 1150 1140 1152 1141 1139]
[4482 1194 1148 1150 1137 1165 1163 1154 1149 1152]
[1333 1184 1162 1163 1138 1149 1150 1151 1137 1145]
[1318 1150 1144 1150 1151 1147 1138 1147 1143 1149]
person Taylor Wood    schedule 12.02.2018
comment
Интересный. Я пробую это сейчас на другой коробке, и здесь замедление - как для prn, так и для .println - также менее выражено. Так что кажется, что первыеThread/yield или System/nanoTime и prn (из предыдущей партии) как-то взаимодействуют... Конечно, мы говорим о сотнях наносекунд, так что это полностью микротест, но все же интересно и ответит на мой вопрос. - person Evgeniy Berezovsky; 13.02.2018

Вы можете увидеть этот эффект даже с гораздо менее дорогой и менее связанной с вводом-выводом операцией, чем (Thread/yield), такой как константное выражение 5:

user=> (doall (for [_ (range 10)] (times 10 5)))
[[390 132 134 132 109 86 94 109 115 112]
 [115 117 114 112 112 89 112 112 115 89]
 [117 106 109 109 109 86 109 109 111 109]
 [121 106 103 103 109 86 106 106 129 109]
 [117 109 106 109 112 95 111 112 109 89]
 [112 112 111 111 114 92 109 112 109 114]
 [118 111 112 111 115 88 112 109 115 92]
 [112 108 108 111 109 92 109 109 118 89]
 [115 106 112 115 112 89 112 109 114 89]
 [117 109 112 112 114 89 114 112 111 91]]

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

Мое лучшее предположение — это просто таинственная сила HotSpot. Даже в этом очень коротком фрагменте вызывается несколько методов динамической отправки. Вы вызываете conj как IFn, и, возможно, HotSpot создает некоторую уверенность в том, что большинство ваших вызовов IFn будет conj, и поэтому он пытается ускорить этот вариант использования; но в конце каждой итерации 10 вызываются некоторые другие функции, которые добавляются к большему списку результатов, и поэтому HotSpot отказывается от своих оптимизаций, ожидая, что вы начнете делать что-то еще.

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

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

person amalloy    schedule 13.02.2018