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

Java 8u40 Math.round() очень медленный

У меня есть довольно простой проект хобби, написанный на Java 8, который широко использует повторяющиеся вызовы Math.round() в одном из своих режимов работы. Например, один такой режим порождает 4 потока и ставит в очередь 48 запущенных задач с помощью ExecutorService, каждый из которых выполняет что-то похожее на следующий блок кода 2 ^ 31 раз:

int3 = Math.round(float1 + float2);
int3 = Math.round(float1 * float2);
int3 = Math.round(float1 / float2);

Это не совсем так, как это (есть задействованные массивы и вложенные циклы), но вы получаете эту идею. Во всяком случае, до Java 8u40 код, похожий на приведенный выше, может завершить полный запуск ~ 103 миллиардов блоков команд примерно за 13 секунд на AMD A10-7700k. С Java 8u40 требуется около 260 секунд, чтобы сделать то же самое. Никаких изменений в коде, ничего нет, просто обновление Java.

Кто-нибудь еще заметил, что Math.round() становится намного медленнее, особенно когда он используется повторно? Это почти так, как если бы JVM делала какую-то оптимизацию, прежде чем это больше не делает. Может быть, он использовал SIMD до 8u40, и теперь это не так?

edit: Я выполнил вторую попытку в MVCE. Вы можете загрузить первую попытку здесь:

https://www.dropbox.com/s/rm2ftcv8y6ye1bi/MathRoundMVCE.zip?dl=0

Вторая попытка приведена ниже. Моя первая попытка была удалена из этого сообщения, поскольку она считалась слишком длинной, и она подвержена оптимизации удаления удаленных кодов JVM (что, по-видимому, происходит меньше в 8u40).

import java.util.concurrent.ExecutorService;
import java.util.concurrent.Executors;

public class MathRoundMVCE
{           
    static long grandtotal = 0;
    static long sumtotal = 0;

    static float[] float4 = new float[128];
    static float[] float5 = new float[128];
    static int[] int6 = new int[128];
    static int[] int7 = new int[128];
    static int[] int8 = new int[128];
    static long[] longarray = new long[480];

    final static int mil = 1000000;

    public static void main(String[] args)
    {       
        initmainarrays();
        OmniCode omni = new OmniCode();
        grandtotal = omni.runloops() / mil;
        System.out.println("Total sum of operations is " + sumtotal);
        System.out.println("Total execution time is " + grandtotal + " milliseconds");
    }   

    public static long siftarray(long[] larray)
    {
        long topnum = 0;
        long tempnum = 0;
        for (short i = 0; i < larray.length; i++)
        {
            tempnum = larray[i];
            if (tempnum > 0)
            {
                topnum += tempnum;
            }
        }
        topnum = topnum / Runtime.getRuntime().availableProcessors();
        return topnum;
    }

    public static void initmainarrays()
    {
        int k = 0;

        do
        {           
            float4[k] = (float)(Math.random() * 12) + 1f;
            float5[k] = (float)(Math.random() * 12) + 1f;
            int6[k] = 0;

            k++;
        }
        while (k < 128);        
    }       
}

class OmniCode extends Thread
{           
    volatile long totaltime = 0;
    final int standard = 16777216;
    final int warmup = 200000;

    byte threads = 0;

    public long runloops()
    {
        this.setPriority(MIN_PRIORITY);

        threads = (byte)Runtime.getRuntime().availableProcessors();
        ExecutorService executor = Executors.newFixedThreadPool(threads);

        for (short j = 0; j < 48; j++)
        {           
            executor.execute(new RoundFloatToIntAlternate(warmup, (byte)j));
        }

        executor.shutdown();

        while (!executor.isTerminated())
        {
            try
            {
                Thread.sleep(100);
            } 
            catch (InterruptedException e)
            {
                //Do nothing                
            }
        }

        executor = Executors.newFixedThreadPool(threads);

        for (short j = 0; j < 48; j++)
        {           
            executor.execute(new RoundFloatToIntAlternate(standard, (byte)j));          
        }

        executor.shutdown();

        while (!executor.isTerminated())
        {
            try
            {
                Thread.sleep(100);
            } 
            catch (InterruptedException e)
            {
                //Do nothing                
            }
        }

        totaltime = MathRoundMVCE.siftarray(MathRoundMVCE.longarray);   

        executor = null;
        Runtime.getRuntime().gc();
        return totaltime;
    }
}

class RoundFloatToIntAlternate extends Thread
{       
    int i = 0;
    int j = 0;
    int int3 = 0;
    int iterations = 0;
    byte thread = 0;

    public RoundFloatToIntAlternate(int cycles, byte threadnumber)
    {
        iterations = cycles;
        thread = threadnumber;
    }

    public void run()
    {
        this.setPriority(9);
        MathRoundMVCE.longarray[this.thread] = 0;
        mainloop();
        blankloop();    

    }

    public void blankloop()
    {
        j = 0;
        long timer = 0;
        long totaltimer = 0;

        do
        {   
            timer = System.nanoTime();
            i = 0;

            do
            {
                i++;
            }
            while (i < 128);
            totaltimer += System.nanoTime() - timer;            

            j++;
        }
        while (j < iterations);         

        MathRoundMVCE.longarray[this.thread] -= totaltimer;
    }

    public void mainloop()
    {
        j = 0;
        long timer = 0; 
        long totaltimer = 0;
        long localsum = 0;

        int[] int6 = new int[128];
        int[] int7 = new int[128];
        int[] int8 = new int[128];

        do
        {   
            timer = System.nanoTime();
            i = 0;

            do
            {
                int6[i] = Math.round(MathRoundMVCE.float4[i] + MathRoundMVCE.float5[i]);
                int7[i] = Math.round(MathRoundMVCE.float4[i] * MathRoundMVCE.float5[i]);
                int8[i] = Math.round(MathRoundMVCE.float4[i] / MathRoundMVCE.float5[i]);

                i++;
            }
            while (i < 128);
            totaltimer += System.nanoTime() - timer;

            for(short z = 0; z < 128; z++)
            {
                localsum += int6[z] + int7[z] + int8[z];
            }       

            j++;
        }
        while (j < iterations);         

        MathRoundMVCE.longarray[this.thread] += totaltimer;
        MathRoundMVCE.sumtotal = localsum;
    }
}

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

Under 8u25: Общее время выполнения составляет 261545 миллисекунд

До 8u40: Общее время выполнения составляет 266890 миллисекунд

Условия испытаний были такими же, как и раньше. Таким образом, казалось бы, что 8u25 и 8u31 делали удаление мертвого кода, которое остановилось 8u40, в результате чего код "замедлялся" в 8u40. Это не объясняет каждую странную мелочь, которая возникла, но это, по-видимому, основная масса. В качестве дополнительного бонуса предложения и ответы, представленные здесь, вдохновили меня на улучшение других частей моего проекта по хобби, за что я очень благодарен. Спасибо вам всем за это!

4b9b3361

Ответ 1

MVCE на основе OP

  • может быть упрощен далее
  • изменил int3 = заявления на int3 +=, чтобы уменьшить вероятность удаления мертвого кода. int3 = разница от 8u31 до 8u40 является фактором 3x медленнее. Использование разницы int3 += только на 15% медленнее.
  • распечатать результат, чтобы еще больше уменьшить вероятность оптимизации удаления мертвого кода.

код

public class MathTime {
    static float[][] float1 = new float[8][16];
    static float[][] float2 = new float[8][16];

    public static void main(String[] args) {
        for (int j = 0; j < 8; j++) {
            for (int k = 0; k < 16; k++) {
                float1[j][k] = (float) (j + k);
                float2[j][k] = (float) (j + k);
            }
        }
        new Test().run();
    }

    private static class Test {
        int int3;

        public void run() {
            for (String test : new String[] { "warmup", "real" }) {

                long t0 = System.nanoTime();

                for (int count = 0; count < 1e7; count++) {
                    int i = count % 8;
                    int3 += Math.round(float1[i][0] + float2[i][0]);
                    int3 += Math.round(float1[i][1] + float2[i][1]);
                    int3 += Math.round(float1[i][2] + float2[i][2]);
                    int3 += Math.round(float1[i][3] + float2[i][3]);
                    int3 += Math.round(float1[i][4] + float2[i][4]);
                    int3 += Math.round(float1[i][5] + float2[i][5]);
                    int3 += Math.round(float1[i][6] + float2[i][6]);
                    int3 += Math.round(float1[i][7] + float2[i][7]);
                    int3 += Math.round(float1[i][8] + float2[i][8]);
                    int3 += Math.round(float1[i][9] + float2[i][9]);
                    int3 += Math.round(float1[i][10] + float2[i][10]);
                    int3 += Math.round(float1[i][11] + float2[i][11]);
                    int3 += Math.round(float1[i][12] + float2[i][12]);
                    int3 += Math.round(float1[i][13] + float2[i][13]);
                    int3 += Math.round(float1[i][14] + float2[i][14]);
                    int3 += Math.round(float1[i][15] + float2[i][15]);

                    int3 += Math.round(float1[i][0] * float2[i][0]);
                    int3 += Math.round(float1[i][1] * float2[i][1]);
                    int3 += Math.round(float1[i][2] * float2[i][2]);
                    int3 += Math.round(float1[i][3] * float2[i][3]);
                    int3 += Math.round(float1[i][4] * float2[i][4]);
                    int3 += Math.round(float1[i][5] * float2[i][5]);
                    int3 += Math.round(float1[i][6] * float2[i][6]);
                    int3 += Math.round(float1[i][7] * float2[i][7]);
                    int3 += Math.round(float1[i][8] * float2[i][8]);
                    int3 += Math.round(float1[i][9] * float2[i][9]);
                    int3 += Math.round(float1[i][10] * float2[i][10]);
                    int3 += Math.round(float1[i][11] * float2[i][11]);
                    int3 += Math.round(float1[i][12] * float2[i][12]);
                    int3 += Math.round(float1[i][13] * float2[i][13]);
                    int3 += Math.round(float1[i][14] * float2[i][14]);
                    int3 += Math.round(float1[i][15] * float2[i][15]);

                    int3 += Math.round(float1[i][0] / float2[i][0]);
                    int3 += Math.round(float1[i][1] / float2[i][1]);
                    int3 += Math.round(float1[i][2] / float2[i][2]);
                    int3 += Math.round(float1[i][3] / float2[i][3]);
                    int3 += Math.round(float1[i][4] / float2[i][4]);
                    int3 += Math.round(float1[i][5] / float2[i][5]);
                    int3 += Math.round(float1[i][6] / float2[i][6]);
                    int3 += Math.round(float1[i][7] / float2[i][7]);
                    int3 += Math.round(float1[i][8] / float2[i][8]);
                    int3 += Math.round(float1[i][9] / float2[i][9]);
                    int3 += Math.round(float1[i][10] / float2[i][10]);
                    int3 += Math.round(float1[i][11] / float2[i][11]);
                    int3 += Math.round(float1[i][12] / float2[i][12]);
                    int3 += Math.round(float1[i][13] / float2[i][13]);
                    int3 += Math.round(float1[i][14] / float2[i][14]);
                    int3 += Math.round(float1[i][15] / float2[i][15]);

                }
                long t1 = System.nanoTime();
                System.out.println(int3);
                System.out.println(String.format("%s, Math.round(float), %s, %.1f ms", System.getProperty("java.version"), test, (t1 - t0) / 1e6));
            }
        }
    }
}

Результаты

[email protected]:~$ ./jdk1.8.0_40/bin/javac MathTime.java;./jdk1.8.0_40/bin/java -cp . MathTime 
1.8.0_40, Math.round(float), warmup, 6846.4 ms
1.8.0_40, Math.round(float), real, 6058.6 ms
[email protected]:~$ ./jdk1.8.0_31/bin/javac MathTime.java;./jdk1.8.0_31/bin/java -cp . MathTime 
1.8.0_31, Math.round(float), warmup, 5717.9 ms
1.8.0_31, Math.round(float), real, 5282.7 ms
[email protected]:~$ ./jdk1.8.0_25/bin/javac MathTime.java;./jdk1.8.0_25/bin/java -cp . MathTime 
1.8.0_25, Math.round(float), warmup, 5702.4 ms
1.8.0_25, Math.round(float), real, 5262.2 ms

Наблюдения

  • Для тривиального использования Math.round(float) я не вижу разницы в производительности на моей платформе (Linux x86_64). В тестах есть только разница, мои предыдущие наивные и неправильные тесты только выявили различия в поведении в оптимизации, так как ответ Ивана и комментарии Marco13 указывают.
  • 8u40 менее агрессивен в устранении мертвого кода, чем предыдущие версии, что означает, что больше кода выполняется в некоторых угловых случаях и, следовательно, медленнее.
  • 8u40 занимает немного больше времени, чтобы разогреться, но как только "там", быстрее.

Анализ источников

Удивительно Math.round(float) - это чистая реализация Java, а не native, код для 8u31 и 8u40 идентичен.

diff  jdk1.8.0_31/src/java/lang/Math.java jdk1.8.0_40/src/java/lang/Math.java
-no differences-

public static int round(float a) {
    int intBits = Float.floatToRawIntBits(a);
    int biasedExp = (intBits & FloatConsts.EXP_BIT_MASK)
            >> (FloatConsts.SIGNIFICAND_WIDTH - 1);
    int shift = (FloatConsts.SIGNIFICAND_WIDTH - 2
            + FloatConsts.EXP_BIAS) - biasedExp;
    if ((shift & -32) == 0) { // shift >= 0 && shift < 32
        // a is a finite number such that pow(2,-32) <= ulp(a) < 1
        int r = ((intBits & FloatConsts.SIGNIF_BIT_MASK)
                | (FloatConsts.SIGNIF_BIT_MASK + 1));
        if (intBits < 0) {
            r = -r;
        }
        // In the comments below each Java expression evaluates to the value
        // the corresponding mathematical expression:
        // (r) evaluates to a / ulp(a)
        // (r >> shift) evaluates to floor(a * 2)
        // ((r >> shift) + 1) evaluates to floor((a + 1/2) * 2)
        // (((r >> shift) + 1) >> 1) evaluates to floor(a + 1/2)
        return ((r >> shift) + 1) >> 1;
    } else {
        // a is either
        // - a finite number with abs(a) < exp(2,FloatConsts.SIGNIFICAND_WIDTH-32) < 1/2
        // - a finite number with ulp(a) >= 1 and hence a is a mathematical integer
        // - an infinity or NaN
        return (int) a;
    }
}

Ответ 2

Случайный бенчмаркинг: вы сравниваете A, но на самом деле измеряете B, и что вы измерили C.

Современные JVM слишком сложны и делают все виды оптимизации. Если вы попытаетесь измерить небольшой фрагмент кода, очень сложно сделать это правильно, без очень подробного знания того, что делает JVM. Преступником многих эталонных тестов является устранение мертвого кода: компиляторы достаточно умны, чтобы выводить некоторые вычисления, являются избыточными и полностью устраняют их. Пожалуйста, прочитайте следующие слайды http://shipilev.net/talks/jvmls-July2014-benchmarking.pdf. Чтобы "исправить" микробиблиотеку Адама (я все еще не могу понять, что он измеряет, и это "исправление" не учитывает разминки, проблемы с OSR и многие другие проблемы с микрообъективом), мы должны распечатать результат вычисления в системе выход:

    int result = 0;
    long t0 = System.currentTimeMillis();
    for (int i = 0; i < 1e9; i++) {
        result += Math.round((float) i / (float) (i + 1));
    }
    long t1 = System.currentTimeMillis();
    System.out.println("result = " + result);
    System.out.println(String.format("%s, Math.round(float), %.1f ms", System.getProperty("java.version"), (t1 - t0)/1f));

В результате:

result = 999999999
1.8.0_25, Math.round(float), 5251.0 ms

result = 999999999
1.8.0_40, Math.round(float), 3903.0 ms

То же самое "исправление" для исходного примера MVCE

It took 401772 milliseconds to complete edu.jvm.runtime.RoundFloatToInt. <==== 1.8.0_40

It took 410767 milliseconds to complete edu.jvm.runtime.RoundFloatToInt. <==== 1.8.0_25

Если вы хотите измерить реальную стоимость Math # round, вы должны написать что-то вроде этого (на основе jmh)

package org.openjdk.jmh.samples;

import org.openjdk.jmh.annotations.*;
import org.openjdk.jmh.runner.Runner;
import org.openjdk.jmh.runner.RunnerException;
import org.openjdk.jmh.runner.options.Options;
import org.openjdk.jmh.runner.options.OptionsBuilder;
import org.openjdk.jmh.runner.options.VerboseMode;

import java.util.Random;
import java.util.concurrent.TimeUnit;

@State(Scope.Benchmark)
@BenchmarkMode(Mode.AverageTime)
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 3, time = 5, timeUnit = TimeUnit.SECONDS)
@Measurement(iterations = 3, time = 5, timeUnit = TimeUnit.SECONDS)
public class RoundBench {

    float[] floats;
    int i;

    @Setup
    public void initI() {
        Random random = new Random(0xDEAD_BEEF);
        floats = new float[8096];
        for (int i = 0; i < floats.length; i++) {
            floats[i] = random.nextFloat();
        }
    }

    @Benchmark
    public float baseline() {
        i++;
        i = i & 0xFFFFFF00;
        return floats[i];
    }

    @Benchmark
    public int round() {
        i++;
        i = i & 0xFFFFFF00;
        return Math.round(floats[i]);
    }

    public static void main(String[] args) throws RunnerException {
        Options options = new OptionsBuilder()
                .include(RoundBench.class.getName())
                .build();
        new Runner(options).run();
    }
}

Мои результаты:

1.8.0_25
Benchmark            Mode  Cnt  Score   Error  Units
RoundBench.baseline  avgt    6  2.565 ± 0.028  ns/op
RoundBench.round     avgt    6  4.459 ± 0.065  ns/op

1.8.0_40 
Benchmark            Mode  Cnt  Score   Error  Units
RoundBench.baseline  avgt    6  2.589 ± 0.045  ns/op
RoundBench.round     avgt    6  4.588 ± 0.182  ns/op

Чтобы найти основную причину проблемы, вы можете использовать https://github.com/AdoptOpenJDK/jitwatch/. Чтобы сэкономить время, могу сказать, что размер JIT-кода для Math # round был увеличен в 8.0_40. Это почти незаметно для небольших методов, но в случае огромных методов слишком длинный лист машинного кода загрязняет кеш команд.

Ответ 3

Не определенный ответ, но, возможно, еще один небольшой вклад.

Изначально я прошел целую цепочку в виде Адама в его ответе (см. историю для подробностей), отслеживания и сравнения байт-кода, реализации времени выполнения - хотя, как отмечалось в комментариях, во время моих тестов (на Win7/8) и с "обычными примерами лучших микрофэнкчмарков" разница в производительности была не такой яркой, как предполагалось в исходном вопросе и в первых версиях первых ответов.

Однако была разница, поэтому я создал еще один небольшой тест:

public class MathRoundPerformance {

    static final int size = 16;
    static float[] data = new float[size];

    public static void main(String[] args) {
        for (int i = 0; i < size; i++) {
            data[i] = i;
        }

        for (int n=1000000; n<=100000000; n+=5000000)
        {
            long t0 = System.nanoTime();
            int result = runTest(n);
            long t1 = System.nanoTime();
            System.out.printf(
                "%s, Math.round(float), %s, %s, %.1f ms\n",
                System.getProperty("java.version"),
                n, result, (t1 - t0) / 1e6);
        }
    }

    public static int runTest(int n) {
        int result = 0;
        for (int i = 0; i < n; i++) {
            int i0 = (i+0) % size;
            int i1 = (i+1) % size;
            result += Math.round(data[i0] + data[i1]);
            result += Math.round(data[i0] * data[i1]);
            result += Math.round(data[i0] / data[i1]);
        }
        return result;
    }
}

Результаты синхронизации (опуская некоторые детали) были

...
1.8.0_31, Math.round(float), 96000000, -351934592, 504,8 ms

....
1.8.0_40, Math.round(float), 96000000, -351934592, 544,0 ms

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

java -server -XX:+UnlockDiagnosticVMOptions -XX:+TraceClassLoading
     -XX:+LogCompilation -XX:+PrintInlining -XX:+PrintAssembly
     MathRoundPerformance

Важно то, что оптимизация завершена, когда программа заканчивается (или, по крайней мере, кажется, что она завершена). Это означает, что результаты последних вызовов метода runTest печатаются без любой дополнительной оптимизации JIT между вызовами.

Я попытался выяснить различия, посмотрев на сгенерированный машинный код. Большая часть сгенерированного кода была одинаковой для обеих версий. Но поскольку указал Иван, количество инструкций увеличилось на 8u40. Я сравнил исходный код версий h20 и u40. Я думал, что могут быть тонкие различия в intrinsics для floatToRawIntBits, но эти файлы не изменились. Я считал, что проверки AVX или SSE4.2, которые были добавлены в последнее время, могут повлиять на генерацию машинного кода неудачным способом, но... мои знания ассемблера не так хороши, как хотелось бы, и поэтому я не могу сделать здесь определенное утверждение. В целом, сгенерированный машинный код выглядит так, как будто он был в основном переупорядочен (т.е. В основном изменен структурно), но сравнение свалок вручную - это боль в... глазе (адреса все разные, даже если инструкции в основном одинаковы).

(Я хотел сбросить результаты машинного кода, который был создан для метода runTest здесь, но есть некоторый нечетный предел 30k для одного ответа)

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