Measuring Logging performance

I am trying to measure logging performance in combination with in unit test. What I noticed is, the first block that gets executed gets some overhead get added. The code below is one case with StringEscapeUtils.escapeJava but I have also come across this behaviour in other tests. Has anyone come across this and know the reason?

import org.junit.jupiter.api.Test;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

class MyTests {
    private static final Logger LOGGER = LoggerFactory.getLogger(MyTests.class);

    protected String getSaltString(final int length) {
        String SALTCHARS = "ABCDEFGHIJKLMNOPQRSTUVWXY\nZ1234567890";
        StringBuilder salt = new StringBuilder();
        Random rnd = new Random();
        while (salt.length() < length) { // length of the random string.
            int index = (int) (rnd.nextFloat() * SALTCHARS.length());
            salt.append(SALTCHARS.charAt(index));
        }
        String saltStr = salt.toString();
        return saltStr;

    }

    private void dummy(final String str) {

    }

    @Test
    public void testNewlineInString() {
        long start = 0, end = 0;
        final int Times = 1000;

        LOGGER.info("starting..");

        String [] strings = new String[Times];
        for (int i = 0; i < Times; ++i) {
            strings[i] = getSaltString(100);
        }

        LOGGER.info("Generated strings..");

        start = Instant.now().toEpochMilli();
        for (int i = 0; i < Times; ++i) {
            LOGGER.info("Case 1: String Number: {} Name: {}", i + 1, strings[i]);
//          dummy(strings[i]);
        }
        end = Instant.now().toEpochMilli();
        final long durationNo_escapeJava = end - start;

        start = Instant.now().toEpochMilli();
        for (int i = 0; i < Times; ++i) {
            LOGGER.info("Case 2: String Number: {} Name: {}", i + 1, StringEscapeUtils.escapeJava(strings[i]));
//          dummy(StringEscapeUtils.escapeJava(strings[i]));
        }
        end = Instant.now().toEpochMilli();
        final long duration_escapeJava = end - start;

        start = Instant.now().toEpochMilli();
        for (int i = 0; i < Times; ++i) {
            LOGGER.info("Case 3: String Number: {} Name: {}", i + 1, strings[i]);
//          dummy(strings[i]);
        }
        end = Instant.now().toEpochMilli();
        final long durationNo_escapeJavaAgain = end - start;


        LOGGER.info("durationNo_escapeJava: {} duration_escapeJava: {} durationNo_escapeJavaAgain: {}",
                durationNo_escapeJava, duration_escapeJava, durationNo_escapeJavaAgain);

    }
}

The result consistently shows that the first block takes much more than 3rd block which is essentially same.

for example:

durationNo_escapeJava: 265 duration_escapeJava: 107 durationNo_escapeJavaAgain: 28

I have tried using a function call, function dummy in the example above but it does not have this problem.

What you're observing has to do with the JVM warm-up and the nature of a JIT compiler that optimizes code at runtime.

There's a whole article about that topic on Baeldung.com

I'd suggest you use the "JMH - Java Microbenchmark Harness" framework mentioned in the article for benchmarking your program.