3

I initially wrote this code to check the fastest way to put a string in a buffer, but quickly discovered a performance anomaly.

The test now contains three relevant methods: 'slow', 'alpha' and 'beta'. The code for 'alpha' and 'beta' is exactly the same. I then measure the time it takes to do N iterations with each method and it turns out that the loop with 'beta' takes about 2x more time than the loop with 'alpha'. It seems that the 3rd loop is always 2x slower than the second, even when I swap the methods.

import java.lang.reflect.Field;
import java.nio.ByteBuffer;

public class Main {
    private static final int N = 1_000_000;
    private static Field stringBytes;
    private static String testString;

    static {
        // setup test string:
        StringBuilder builder = new StringBuilder(1024);
        for (int i = 0; i < 100; i++) {
            builder.append("Hello, world!");
        }
        testString = builder.toString();
        // setup String byte array field:
        try {
            Field stringValue = String.class.getDeclaredField("value");
            stringValue.setAccessible(true);
            stringBytes = stringValue;
        } catch (NoSuchFieldException e) {
            e.printStackTrace();
        }
    }

    public static void main(String[] args) throws IllegalAccessException {
        ByteBuffer expectedBuffer = ByteBuffer.allocate(2000)
            .put(testString.getBytes());
        ByteBuffer testBuffer = ByteBuffer.allocate(2000);
        //
        for (int i = 0; i < 10; i++) {
            runTests(testBuffer, expectedBuffer);
        }
    }

    private static void runTests(ByteBuffer testBuffer, ByteBuffer expectedBuffer) throws
        IllegalAccessException {
        long startTime = System.nanoTime();
        for (int i = 0; i < N; i++) {
            testBuffer.clear();
            slow(testBuffer);
            checkResult(testBuffer, expectedBuffer);
        }
        long endTime = System.nanoTime();
        System.out.println("Slow: \t" + (endTime - startTime));
        //
        startTime = System.nanoTime();
        for (int i = 0; i < N; i++) {
            testBuffer.clear();
            alpha(testBuffer);
            checkResult(testBuffer, expectedBuffer);
        }
        endTime = System.nanoTime();
        System.out.println("Alpha: \t" + (endTime - startTime));
        //
        startTime = System.nanoTime();
        for (int i = 0; i < N; i++) {
            testBuffer.clear();
            beta(testBuffer);
            checkResult(testBuffer, expectedBuffer);
        }
        endTime = System.nanoTime();
        System.out.println("Beta: \t" + (endTime - startTime));
    }

    // make sure the JIT doesn't discard computations
    private static void checkResult(ByteBuffer got, ByteBuffer expected) {
        if (!got.equals(expected)) {
            throw new RuntimeException(
                String.format("expected: %s, got %s", expected, got)
            );
        }
    }

    private static void slow(ByteBuffer source) {
        source.put(testString.getBytes());
    }

    private static void alpha(ByteBuffer source) throws IllegalAccessException {
        source.put((byte[]) stringBytes.get(testString));
    }

    private static void beta(ByteBuffer source) throws IllegalAccessException {
        source.put((byte[]) stringBytes.get(testString));
    }
}

What can cause such a drastic performance difference and how can I avoid it in my code?

Here is my output when running the program (except illegal access warnings):

Slow:   4271284211
Alpha:  1089785263
Beta:   1067286082
Slow:   3772404211
Alpha:  1100012164
Beta:   1869625263
Slow:   3779312281
Alpha:  1261239766
Beta:   1949156491
Slow:   3778842573
Alpha:  1067640702
Beta:   1914821988
Slow:   3860709240
Alpha:  1084109473
Beta:   1878945497
Slow:   3662584328
Alpha:  1058276492
Beta:   1819476024
Slow:   3665676725
Alpha:  1061351111
Beta:   1855920467
Slow:   3725946199
Alpha:  1070417778
Beta:   1843628538
Slow:   3666171696
Alpha:  1062847251
Beta:   1829787135
Slow:   3663726784
Alpha:  1055333802
Beta:   1821107836

Setup: x64 win10 java9

PhilipRoman
  • 1,136
  • 10
  • 20
  • Have you tried using a profiler? Or writing a benchmark using a benchmark framework? – Yassin Hajaj Apr 21 '18 at 13:43
  • Each method is run 10_000_000 times, surely the JIT has enough time. Also, what profiler should I use in this case? The JDK built in profilers are only useful for memory, unless i'm missing something. – PhilipRoman Apr 21 '18 at 13:47
  • As we know, We don't know when the GC take the recycling. I guess the 3rd loop trigger the GC recycling which may slow down the jvm. ps: It's just my own guess – Jswq Apr 21 '18 at 13:55
  • Just confirmed: no allocations are being done from 'alpha' or 'beta'. GC happens only in the 'slow' method. – PhilipRoman Apr 21 '18 at 14:00
  • 1
    I just test the demo in my machine which shows the times are very close between 'alpha' and 'beta' – Jswq Apr 21 '18 at 14:17
  • 1
    A similar problem: [Java loop gets slower after some runs / JIT's fault?](https://stackoverflow.com/questions/24882946/java-loop-gets-slower-after-some-runs-jits-fault). And [the answer](https://stackoverflow.com/a/24889503/3448419) applies to your case as well. – apangin Apr 21 '18 at 23:02
  • Yeah, that seems to be exactly what I am seeing here. Thank you for solving this! – PhilipRoman Apr 22 '18 at 05:46

0 Answers0