Strange method invocation optimization issue

Question

I have been testing problem with too slow DataInputStream.readByte() method working, and found interesting, but incomprehensible issue. I'm using jdk1.7.0_40, Windows 7 64 bit.

Consider we have some huge byte-array and reading data from it. And let's compare 4 methods for reading byte-by-byte from this array:

1. reading via simple loop
2. reading via ByteArrayInputStream -> DataInputStream
3. reading via ByteArrayInputStream -> our own DataInputStream implementation (MyDataInputStream)
4. reading via ByteArrayInputStream and copy of method readByte() from DataInputStream.

I have found following results (after long-time of test-loop iterating):

• Loop took aprox. 312446094 ns
• DataInputStream took apox. 2555898090 ns
• MyDataInputStream took aprox. 2630664298 ns
• Via method readByte() copy took 309265568 ns

In other words, we have strange optimization issue: the same operations via object method invocation take in 10 times longer work, then via "native" implementation.

The question: why?.

For information:

@Test
public void testBytes1() throws IOException {
    byte[] bytes = new byte[1_000_000_000];
    Random r = new Random();
    for (int i = 0; i < bytes.length; i++)
        bytes[i] = (byte) r.nextInt();

    do {
        System.out.println();

        bytes[r.nextInt(1_000_000_000)] = (byte) r.nextInt();

        testLoop(bytes);
        testDis(bytes);
        testMyDis(bytes);
        testViaMethod(bytes);
    } while (true);
}

private void testDis(byte[] bytes) throws IOException {
    long time1 = System.nanoTime();
    long c = 0;
    try (ByteArrayInputStream bais = new ByteArrayInputStream(bytes);
         DataInputStream dis = new DataInputStream(bais)) {
        for (int i = 0; i < bytes.length; i++) {
            c += dis.readByte();
        }
    }
    long time2 = System.nanoTime();
    System.out.println("Dis: \t\t\t\t" + (time2 - time1) + "\t\t\t\t" + c);
}

private void testMyDis(byte[] bytes) throws IOException {
    long time1 = System.nanoTime();
    long c = 0;
    try (ByteArrayInputStream bais = new ByteArrayInputStream(bytes);
         MyDataInputStream dis = new MyDataInputStream(bais)) {
        for (int i = 0; i < bytes.length; i++) {
            c += dis.readByte();
        }
    }
    long time2 = System.nanoTime();
    System.out.println("My Dis: \t\t\t" + (time2 - time1) + "\t\t\t\t" + c);
}

private void testViaMethod(byte[] bytes) throws IOException {
    long time1 = System.nanoTime();
    long c = 0;
    try (ByteArrayInputStream bais = new ByteArrayInputStream(bytes)
    ) {
        for (int i = 0; i < bytes.length; i++) {
            c += readByte(bais);
        }
    }
    long time2 = System.nanoTime();
    System.out.println("Via method: \t\t" + (time2 - time1) + "\t\t\t\t" + c);
}

private void testLoop(byte[] bytes) {
    long time1 = System.nanoTime();
    long c = 0;
    for (int i = 0; i < bytes.length; i++) {
        c += bytes[i];
    }
    long time2 = System.nanoTime();
    System.out.println("Loop: \t\t\t\t" + (time2 - time1) + "\t\t\t\t" + c);
}

public final byte readByte(InputStream in) throws IOException {
    int ch = in.read();
    if (ch < 0)
        throw new EOFException();
    return (byte)(ch);
}

static class MyDataInputStream implements Closeable {

    InputStream in;

    MyDataInputStream(InputStream in) {
        this.in = in;
    }

    public final byte readByte() throws IOException {
        int ch = in.read();
        if (ch < 0)
            throw new EOFException();
        return (byte)(ch);
    }

    @Override
    public void close() throws IOException {
        in.close();
    }
}

P.S. Update for thoose, who is in doubt about my results, this is printout, using -XX:+PrintCompilation -verbose:gc -XX:CICompilerCount=1

     37    1             java.lang.String::hashCode (55 bytes)
     41    2             java.lang.String::charAt (29 bytes)
     43    3             java.lang.String::indexOf (70 bytes)
     49    4             java.lang.AbstractStringBuilder::ensureCapacityInternal (16 bytes)
     52    5             java.lang.AbstractStringBuilder::append (29 bytes)
    237    6             java.util.Random::nextInt (7 bytes)
    237    9     n       sun.misc.Unsafe::compareAndSwapLong (native)   
    238    7             java.util.concurrent.atomic.AtomicLong::get (5 bytes)
    238    8             java.util.concurrent.atomic.AtomicLong::compareAndSet (13 bytes)
    239   10             java.util.Random::next (47 bytes)
    239   11 %           fias.TestArrays::testBytes1 @ 15 (77 bytes)
   9645   11 %           fias.TestArrays::testBytes1 @ -2 (77 bytes)   made not entrant

   9646   12 %           fias.TestArrays::testLoop @ 10 (77 bytes)
   9964   12 %           fias.TestArrays::testLoop @ -2 (77 bytes)   made not entrant
Loop:               318726397               -500090432
   9965   13             java.io.DataInputStream::readByte (23 bytes)
   9966   14  s          java.io.ByteArrayInputStream::read (36 bytes)
   9967   15 % !         fias.TestArrays::testDis @ 37 (279 bytes)
Dis:                2684374258              -500090432
  12651   16             fias.TestArrays$MyDataInputStream::readByte (23 bytes)
  12652   17 % !         fias.TestArrays::testMyDis @ 37 (279 bytes)
My Dis:             2675570541              -500090432
  15327   18             fias.TestArrays::readByte (20 bytes)
  15328   19 % !         fias.TestArrays::testViaMethod @ 23 (179 bytes)
Via method:         2367507141              -500090432

  17694   20             fias.TestArrays::testLoop (77 bytes)
  17699   21 %           fias.TestArrays::testLoop @ 10 (77 bytes)
Loop:               374525891               -500090567
  18069   22   !         fias.TestArrays::testDis (279 bytes)
Dis:                2674626125              -500090567
  20745   23   !         fias.TestArrays::testMyDis (279 bytes)
My Dis:             2671418683              -500090567
  23417   24   !         fias.TestArrays::testViaMethod (179 bytes)
Via method:         2359181776              -500090567

Loop:               315081855               -500090663
Dis:                2558738649              -500090663
My Dis:             2627056034              -500090663
Via method:         311692727               -500090663

Loop:               317813286               -500090778
Dis:                2565161726              -500090778
My Dis:             2630665760              -500090778
Via method:         314594434               -500090778

Loop:               313695660               -500090797
Dis:                2568251556              -500090797
My Dis:             2635236578              -500090797
Via method:         311882312               -500090797

Loop:               316781686               -500090929
Dis:                2563535623              -500090929
My Dis:             2638487613              -500090929
Via method:         313170789               -500090929

UPD-2: Here is benchmark and results kindly given by @maaartinus.

Answer 1

Surprisingly, reason is try-with-resources statement on MyDataInputStream/DataInputStream

if we move initialization inside try block performance will be like loop/method invocation

private void testMyDis(byte[] bytes) throws IOException {
    final long time1 = System.nanoTime();
    long c = 0;
    try (ByteArrayInputStream bais = new ByteArrayInputStream(bytes)) {
        final MyDataInputStream dis = new MyDataInputStream(bais);
        for (int i = 0; i < bytes.length; i++) {
            c += dis.readByte();
        }
    }
    final long time2 = System.nanoTime();
    System.out.println("My Dis: \t\t\t" + (time2 - time1) + "\t\t\t\t" + c);
}

I think that with that unnecessary resource JIT cannot use Range Check Elimination