Path: csiph.com!weretis.net!feeder4.news.weretis.net!news.albasani.net!.POSTED!not-for-mail
From: j4n bur53 <janburse@fastmail.fm>
Newsgroups: comp.lang.java.programmer
Subject: Re: Different way of printing makes code twice as fast
Date: Sun, 16 Jul 2017 02:35:36 +0200
Organization: albasani.net
Lines: 122
Message-ID: <okecco$dor$1@news.albasani.net>
References: <87379x3iv1.fsf@munus.decebal.nl>
Mime-Version: 1.0
Content-Type: text/plain; charset=ISO-8859-1; format=flowed
Content-Transfer-Encoding: 7bit
X-Trace: news.albasani.net 7JDUySyzZ/1wpK5mhFCvx0R8SabZaZSPUKR0EVujOUhed3CzlKSIUlPHua+iZIgaTIg5fUGiny62SHEcYF3mKw==
NNTP-Posting-Date: Sun, 16 Jul 2017 00:35:36 +0000 (UTC)
Injection-Info: news.albasani.net; logging-data="BjPrvJ7UwrX/1pzANnME6S5epuYg1/qtTWpJ8ZaXe8AXe1eGqCWcjZn5Xo8aH5L5Dr8CXjYWy/a59frD7GLOlRqo3eI2Z4Y+zTIG6z30sUJSfKuRpFQoYRvJdmLvOz9y"; mail-complaints-to="abuse@albasani.net"
User-Agent: Mozilla/5.0 (Macintosh; Intel Mac OS X 10.12; rv:49.0) Gecko/20100101 Firefox/49.0 SeaMonkey/2.46
In-Reply-To: <87379x3iv1.fsf@munus.decebal.nl>
Cancel-Lock: sha1:nFighJwlWWdakZz3nU6ck5ObMpY=
Xref: csiph.com comp.lang.java.programmer:36955

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;
>     }
>
> }
>