imul, который никогда не исполняется

На этой неделе я получил один комментарий на ревью. Я написал total = count * 2, а комментарий просил вместо этого count << 1, потому что сдвиг дешевле умножения. Я не спорил. Мне было нечем. Я пишу на Java каждый рабочий день и ни разу не открывал class-файл, чтобы посмотреть, что javac из него делает.

Так я его открыл. Всё, что ниже, снято на OpenJDK 7 b147, сборке IcedTea 2.0, попавшей в дистрибутивы в октябре. Прогон прибит к одному ядру гостя kvm. В седьмой версии многоуровневая компиляция выключена, поэтому всю работу делает серверный компилятор с порогом CompileThreshold в 10000.

Что javac сохраняет

Два метода, через строку:

static int byMul(int x)   { return x * 2; }
static int byShift(int x) { return x << 1; }

И javap -c по class-файлу:

  static int byMul(int);        static int byShift(int);
       0: iload_0                    0: iload_0
       1: iconst_2                   1: iconst_1
       2: imul                       2: ishl
       3: ireturn                    3: ireturn

По четыре байткода. Отличаются два из четырёх: одна инструкция кладёт на стек константу, вторая её забирает. На этом слое комментарий с ревью верен.

javac кое-что переписывает, просто не это. return 2 * 3 компилируется в bipush 6. Прочитанный из другого класса static final int приезжает как iconst_4, а не как чтение поля. javac делает те переписывания, которые предписывает язык, а арифметику оставляет тому, кто будет исполнять байткод.

javac разницу сохраняет. Ниже её уже не измерить: интерпретатор двух вариантов не различает, а серверный компилятор пишет для обоих одну инструкцию.

Что видит интерпретатор

Если разница живёт ниже javac, она должна жить в интерпретаторе, который идёт по байткоду по одной инструкции. Я прогнал оба цикла под -Xint, десять миллионов вызовов на раунд, пятнадцать раундов, раунды mul и shift чередуются внутри одной jvm, чтобы дрейф задевал оба. Медианы в микросекундах:

mul   median 241716 us
shift median 240751 us

Shift выходит быстрее на 0.4 процента. Скрипт повторяет тот же замер три раза: mul быстрее на 4.7 процента, потом на 8.4, потом shift быстрее на 2.6. Раунды внутри одного прогона разошлись от 199267 до 301291, так что ни один из этих зазоров ничего не значит.

Причина в диспетчеризации. Каждый шаблон байткода кончается на movzbl 0x1(%r13),%ebx и jmp *(%r10,%rbx,8), то есть на обращении к таблице и косвенном переходе в следующий шаблон. Я вывалил оба шаблона через -XX:+PrintInterpreter, ожидая близнецов. Арифметика в каждом одна инструкция, но шаблон сдвига на одну пересылку длиннее, потому что счётчик сдвига обязан пройти через %cl. Что сдвиг экономит в ALU, он отдаёт обратно в начале собственного шаблона.

Компилятор приходит посреди цикла

Те же циклы без -Xint, по сто миллионов вызовов на раунд. Эти раунды не чередуются, все девять раундов mul идут первыми:

mul   median 34629 us
shift median 34635 us

Это 0.35 наносекунды на итерацию против 24.2 в интерпретаторе, отношение 70. По четырём прогонам оно легло между 66 и 71, причём почти всё движение приходит со стороны интерпретатора: его медиана сдвинулась на шесть процентов, скомпилированная меньше чем на один.

Переход видно, если печатать каждый раунд вместо медианы. Двенадцать раундов по миллиону вызовов, в микросекундах:

10012  386  370  381  370  381  342  356  342  342  354  342

Нулевой раунд дороже плато примерно в тридцать раз. И он тоже не полностью интерпретирован. Миллион интерпретируемых вызовов стоит около 24200 микросекунд, а этот стоил 10012, то есть компилятор догнал цикл прямо на ходу. -XX:+PrintCompilation на той же команде показывает, как именно:

37    1             Doubling::byMul (4 bytes)
39    1 %           Doubling::roundMul @ 9 (47 bytes)
45    2             Doubling::roundMul (47 bytes)

Знак % означает on-stack replacement. Кадр уже стоял на стеке, когда рантайм подменил код на скомпилированный со входом по байткоду 9, а это голова цикла. Я считал, что метод сначала компилируется, а следующий вызов получает быструю версию. У длинного цикла следующего вызова нет, поэтому jvm его и не ждёт.

Что получает машина

-XX:+UnlockDiagnosticVMOptions -XX:CompileCommand=print печатает готовый код, если собрать плагин hsdis против binutils. Сборка заняла у меня больше времени, чем сам замер. Оба метода:

byMul:   mov %esi,%eax        shl $1,%eax   ;*imul
byShift: mov %esi,%eax        shl $1,%eax   ;*ishl

Та же арифметика, один mov и один shl, внутри тел по 32 байта каждое. В колонке комментария стоит байткод, из которого инструкция получилась. В первой строке там написан imul рядом со сдвигом.

Циклы получились интереснее. Я вырезал из обоих листингов адреса и сравнил, по 103 инструкции с каждой стороны. diff выдаёт две строки. Обе различаются только комментарием:

55c55
< add    $0x10,%esi         ;*imul
---
> add    $0x10,%esi         ;*ishl
64c64
< mov    %r11d,%ebx         ;*imul
---
> mov    %r11d,%ebx         ;*ishl

Горячий цикл это 32 инструкции и 90 байт. За один проход он делает шестнадцать итераций исходника. Умножения в нём нет, вызова byMul тоже нет. Умножение стало бегущим значением, которое растёт на 32 за проход и живёт сразу в трёх регистрах со сдвигом по фазе. В аккумулятор попадают шестнадцать его копий, пятнадцать сложением и одна пересылкой, которая аккумулятор затирает, а старое содержимое возвращается следующей строкой. Константу 240, поправляющую сумму, приносит add $0xf0. Сумма 2 * i по шестнадцати подряд идущим i равна 32 первых значения плюс 240. Это ровно то, что компилятор записал.

Настоящая инструкция умножения во всём скомпилированном методе ровно одна. Она стоит между movabs $0x20c49ba5e353f7cf и sar $0x7, то есть это деление на 1000, посчитанное умножением на магическую константу. Это моя же строка замера, переводящая наносекунды в микросекунды. Умножение из моего исходника не исполняется никогда. То, которое исполняется, пришло из кода замера.

Шестнадцать умножений превратились в шестнадцать копий одного бегущего значения и константу. Оставшееся умножение принадлежит коду замера.

Бенчмарк, который я выбросил

Первая версия ничего не суммировала. Она вызывала byMul(i) и выбрасывала результат:

discarded   4934   8684      0      0      0      0

Ноль микросекунд начиная со второго раунда. Я поднял цикл до двух миллиардов итераций, а он всё равно печатал нули. Ненужный вызов без побочного эффекта мёртв. Цикл вокруг него уходит вместе с ним. В дизассемблере этого main остался один цикл и ни одного упоминания byMul. На нули у меня ушло полчаса, прежде чем я сообразил, что замеряю пустой цикл.

Где виден порог

Мне хотелось увидеть, как срабатывает счётчик на 10000. Тысяча вызовов на раунд доходит до него примерно к десятому раунду, поэтому я прогнал двести таких раундов и стал искать ступеньку. Она случилась на раунде 76. Я запустил ту же команду ещё раз и получил 101, потом 66, потом 69, потом 91.

Двигается не счётчик. -Xbatch заставляет вызывающий поток дождаться компилятора вместо очереди. Под этим флагом ступенька в каждом прогоне приходится на раунд 11. И она переезжает ровно туда, куда велит счётчик: CompileThreshold=20000 ставит её на раунд 21, 5000 на раунд 6, а пятьсот вызовов на раунд возвращают её на 21.

round 8   41 us
     51    1    b        Doubling::byMul (4 bytes)
round 9   2181 us
     53    2    b        Doubling::roundMul (47 bytes)
round 10   28 us
round 11   0 us

Раунд 9 несёт 2181 микросекунду, потому что byMul компилируется внутри замеряемого цикла. roundMul компилируется на входе в раунд 10, до старта таймера, поэтому его собственные две миллисекунды нигде не видны. Раунд 10 всё ещё интерпретируется: счётчик сработал на входе, а уже запущенный кадр досиживает в интерпретаторе до конца. Раунд 11 первый скомпилированный. Его тысяча итераций стоит меньше микросекунды, что целочисленное деление печатает как ноль. Без флага код приезжает тогда, когда до него доберётся поток компилятора, здесь это на пятьдесят-девяносто раундов позже.

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

Чего я не проверял

Я мерил только * 2. Умножение на константу, которая не степень двойки, это отдельный вопрос. Умножение на переменную это ещё один. Ни того, ни другого я не открывал. Я собирался сравнить клиентский компилятор и обнаружил, что в этой 64-битной сборке -client нет вовсе. Это означало бы 32-битный jdk. Туда я не пошёл.

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