Path: csiph.com!news.swapon.de!eternal-september.org!feeder.eternal-september.org!news.eternal-september.org!.POSTED!not-for-mail
From: Cecil Westerhof <Cecil@decebal.nl>
Newsgroups: comp.lang.java.programmer
Subject: Different way of printing makes code twice as fast
Date: Sat, 15 Jul 2017 15:55:14 +0200
Organization: Decebal Computing
Lines: 99
Message-ID: <87379x3iv1.fsf@munus.decebal.nl>
Mime-Version: 1.0
Content-Type: text/plain
Injection-Info: mx02.eternal-september.org; posting-host="4986d7c40770117240962b1c7899e1c1"; logging-data="27165"; mail-complaints-to="abuse@eternal-september.org";	posting-account="U2FsdGVkX18iJco1G5ILDDc0Nwg3i9iwERKeiyzH174="
User-Agent: Gnus/5.13 (Gnus v5.13) Emacs/24.5 (gnu/linux)
X-Homepage: http://www.decebal.nl/
Cancel-Lock: sha1:YyzUSAuquJb0K9L5SQc0v7BeY1s= sha1:0c6EXJDwhBqjtbq2T6KLprs3V6I=
Xref: csiph.com comp.lang.java.programmer:36946

I have a very strange problem with the code below. If I run it like it
is, I get:
    15:41:34: Warming up
    15:41:34: took 2.46E+00 seconds.
    15:41:37: took 2.47E+00 seconds.
    15:41:39: took 2.45E+00 seconds.
    15:41:42: Real work
    15:41:42: took 5.26E+00 seconds.
    15:41:47: took 5.22E+00 seconds.
    15:41:52: took 5.28E+00 seconds.
    15:41:58: took 5.25E+00 seconds.
    15:42:03: took 5.28E+00 seconds.

When I change the first:
    System.out.print(getCurrentTime() + ": ");
to:
    System.out.printf("%s: ", getCurrentTime());

I get:
    15:43:52: Warming up
    15:43:52: took 2.47E+00 seconds.
    15:43:54: took 2.49E+00 seconds.
    15:43:57: took 2.50E+00 seconds.
    15:43:59: Real work
    15:43:59: took 2.46E+00 seconds.
    15:44:02: took 2.49E+00 seconds.
    15:44:04: took 2.50E+00 seconds.
    15:44:07: took 2.50E+00 seconds.
    15:44:09: took 2.49E+00 seconds.

What could be happening here?


public class Problem {
    // ################ main
    public static void main(final String[] args) {
        final float DIVIDER          = 1_000_000_000;

        System.out.printf("%s: Warming up\n", getCurrentTime());
        for (int r = 0; r < 3; ++r) {
            long tDuration;
            long tStart;

            System.out.print(getCurrentTime() + ": ");
            // System.out.printf("%s: ", getCurrentTime());
            tStart = System.nanoTime();
            for (int ir = 0; ir < INNER_REPEATS; ++ir) {
                test();
            }
            tDuration = System.nanoTime() - tStart;
            System.out.printf("took %.2E seconds.\n", tDuration / DIVIDER);
        }
        System.out.printf("%s: Real work\n", getCurrentTime());
        for (int r = 0; r < 5; ++r) {
            long tDuration;
            long tStart;

            System.out.print(getCurrentTime() + ": ");
            // System.out.printf("%s: ", getCurrentTime());
            tStart = System.nanoTime();
            for (int ir = 0; ir < INNER_REPEATS; ++ir) {
                test();
            }
            tDuration       = System.nanoTime() - tStart;
            System.out.printf("took %.2E seconds.\n", tDuration / DIVIDER);
        }
    }


    // ################ constructors
    // Do not allow initiation
    private Problem() {
    }


    // ################ private
    private static String getCurrentTime() {
        return String.format("%tT", System.currentTimeMillis());
    }

    private static final int INNER_REPEATS  = 100_000_000;


    // ################ functions to test
    private static final Long test() {
        long sum = 0L;

        for (int i = 0; i < 80; ++i) {
            sum += i;
        }
        return sum;
    }

}

-- 
Cecil Westerhof
Senior Software Engineer
LinkedIn: http://www.linkedin.com/in/cecilwesterhof