Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > comp.lang.java.programmer > #36946 > unrolled thread

Different way of printing makes code twice as fast

Started byCecil Westerhof <Cecil@decebal.nl>
First post2017-07-15 15:55 +0200
Last post2017-07-16 02:35 +0200
Articles 2 — 2 participants

Back to article view | Back to comp.lang.java.programmer

Contents

  Different way of printing makes code twice as fast Cecil Westerhof <Cecil@decebal.nl> - 2017-07-15 15:55 +0200
    Re: Different way of printing makes code twice as fast j4n bur53 <janburse@fastmail.fm> - 2017-07-16 02:35 +0200

#36946 — Different way of printing makes code twice as fast

FromCecil Westerhof <Cecil@decebal.nl>
Date2017-07-15 15:55 +0200
SubjectDifferent way of printing makes code twice as fast
Message-ID<87379x3iv1.fsf@munus.decebal.nl>
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

[toc] | [next] | [standalone]

#36955

Fromj4n bur53 <janburse@fastmail.fm>
Date2017-07-16 02:35 +0200
Message-ID<okecco$dor$1@news.albasani.net>
In reply to#36946
You use two different call-sites, of what you are testing.

Mostlikely test() is inlined, and what gets optimized is this loop:

for (int ir = 0; ir < INNER_REPEATS; ++ir) {
       test();
}

Now its not unlikely that with the second variant of the code
main() gets too long maybe the second loop doesn't get enough optimized.

Try a single call-site that you measure, like for example:

for (int r = 0; r < 10; ++r) {
      if (r==0) {
         /* warming up */
      } else if (r==4) {
         /* real work */
      } else {
         /* call-site */
      }
}

But this might also not do what you expect it to do.

Cecil Westerhof schrieb:
> 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;
>     }
>
> }
>

[toc] | [prev] | [standalone]

Back to top | Article view | comp.lang.java.programmer

csiph-web