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

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

One code is aggressively optimised, while another not. Why?

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

Contents

  One code is aggressively optimised, while another not. Why? Cecil Westerhof <Cecil@decebal.nl> - 2017-07-12 10:07 +0200
    Re: One code is aggressively optimised, while another not. Why? Eric Sosman <esosman@comcast-dot-net.invalid> - 2017-07-12 09:38 -0400
      Re: One code is aggressively optimised, while another not. Why? Cecil Westerhof <Cecil@decebal.nl> - 2017-07-13 09:51 +0200
        Re: One code is aggressively optimised, while another not. Why? Eric Sosman <esosman@comcast-dot-net.invalid> - 2017-07-13 11:05 -0400
          Re: One code is aggressively optimised, while another not. Why? Cecil Westerhof <Cecil@decebal.nl> - 2017-07-13 18:52 +0200
            Re: One code is aggressively optimised, while another not. Why? Cecil Westerhof <Cecil@decebal.nl> - 2017-07-13 19:51 +0200
    Re: One code is aggressively optimised, while another not. Why? Joshua Cranmer 🐧 <Pidgeot18@verizon.invalid> - 2017-07-12 09:19 -0500
      Re: One code is aggressively optimised, while another not. Why? Martin Gregorie <martin@address-in-sig.invalid> - 2017-07-12 17:04 +0000
    Re: One code is aggressively optimised, while another not. Why? Arne Vajhøj <arne@vajhoej.dk> - 2017-07-12 21:02 -0400

#36861 — One code is aggressively optimised, while another not. Why?

I am looking into some performance metrics. I have the following code:
    long sum = 0L;

    for (long i = start; i < end; ++i) {
        sum += i;
    }

And this code:
    long sum = 0L;

    for (int i = start; i < end; ++i) {
        sum += i;
    }

Start and end are defined like:
    private static int end   = Integer.MAX_VALUE;
    private static int start = Integer.MIN_VALUE;


The second code takes about 50% more time to execute. No surprise
there. But the first code is aggressively optimised when run several
times (the fifth run is about 2½ million times faster as the first
run), while the second code is not optimised:
    09:41:10: Timing long int
    09:41:10: took 2.08E+00 seconds.
    09:41:13: took 1.29E-03 seconds.
    09:41:13: took 1.25E-04 seconds.
    09:41:13: took 1.36E-06 seconds.
    09:41:13: took 7.97E-07 seconds.

    09:41:13: Timing long long
    09:41:13: took 3.09E+00 seconds.
    09:41:16: took 3.11E+00 seconds.
    09:41:19: took 4.03E+00 seconds.
    09:41:23: took 3.94E+00 seconds.
    09:41:27: took 3.87E+00 seconds.

Why the difference?

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

[toc] | [next] | [standalone]

#36862

On 7/12/2017 4:07 AM, Cecil Westerhof wrote:
> I am looking into some performance metrics. I have the following code:
> [... incomplete code fragments deleted; see up-thread ...]
> 
> The second code takes about 50% more time to execute. No surprise
> there. But the first code is aggressively optimised [...]
> 
> Why the difference?

     Perhaps someone could suggest an answer were the complete
program made available for inspection.  Hint, hint.

-- 
esosman@comcast-dot-net.invalid
Twelve hundred eighty-eight days to go.

[toc] | [prev] | [next] | [standalone]

#36874

Eric Sosman <esosman@comcast-dot-net.invalid> writes:

> On 7/12/2017 4:07 AM, Cecil Westerhof wrote:
>> I am looking into some performance metrics. I have the following code:
>> [... incomplete code fragments deleted; see up-thread ...]
>>
>> The second code takes about 50% more time to execute. No surprise
>> there. But the first code is aggressively optimised [...]
>>
>> Why the difference?
>
>     Perhaps someone could suggest an answer were the complete
> program made available for inspection.  Hint, hint.

I uploaded the current program to:
    https://github.com/CecilWesterhof/JavaExamples/blob/master/BoxedTest.java

Originally it was to show the risks of using autoboxing, but when
using an integer instead of a long I got this surprising result.

Only with long int I see an improvement in the performance. And quit a
big one.

The output I get on my system is:
    09:02:30: Timing long int    
    09:02:30: took 2.06E+00 seconds.
    09:02:32: took 1.21E-03 seconds.
    09:02:32: took 1.01E-04 seconds.
    09:02:32: took 7.38E-07 seconds.
    09:02:32: took 7.13E-07 seconds.

    09:02:32: Timing long long   
    09:02:32: took 3.06E+00 seconds.
    09:02:35: took 3.05E+00 seconds.
    09:02:38: took 3.79E+00 seconds.
    09:02:42: took 3.84E+00 seconds.
    09:02:46: took 3.81E+00 seconds.

    09:02:50: Timing Long int    
    09:02:50: took 3.46E+01 seconds.
    09:03:24: took 3.75E+01 seconds.
    09:04:02: took 3.62E+01 seconds.
    09:04:38: took 3.62E+01 seconds.
    09:05:14: took 3.97E+01 seconds.

    09:05:54: Timing Long long   
    09:05:54: took 3.61E+01 seconds.
    09:06:30: took 3.69E+01 seconds.
    09:07:07: took 3.65E+01 seconds.
    09:07:43: took 3.66E+01 seconds.
    09:08:20: took 3.75E+01 seconds.

    09:08:57: Timing long Integer
    09:08:57: took 2.63E+01 seconds.
    09:09:24: took 2.49E+01 seconds.
    09:09:49: took 2.57E+01 seconds.
    09:10:14: took 2.52E+01 seconds.
    09:10:40: took 2.49E+01 seconds.

    09:11:05: Timing long Long   
    09:11:05: took 3.63E+01 seconds.
    09:11:41: took 3.67E+01 seconds.
    09:12:18: took 3.41E+01 seconds.
    09:12:52: took 3.39E+01 seconds.
    09:13:26: took 3.41E+01 seconds.

    09:14:00: Timing Long Integer
    09:14:00: took 5.49E+01 seconds.
    09:14:55: took 5.47E+01 seconds.
    09:15:49: took 5.77E+01 seconds.
    09:16:47: took 5.68E+01 seconds.
    09:17:44: took 5.71E+01 seconds.

    09:18:41: Timing Long Long   
    09:18:41: took 6.68E+01 seconds.
    09:19:48: took 6.68E+01 seconds.
    09:20:54: took 6.64E+01 seconds.
    09:22:01: took 6.63E+01 seconds.
    09:23:07: took 7.30E+01 seconds.

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

[toc] | [prev] | [next] | [standalone]

#36895

On 7/13/2017 3:51 AM, Cecil Westerhof wrote:
> Eric Sosman <esosman@comcast-dot-net.invalid> writes:
> 
>> On 7/12/2017 4:07 AM, Cecil Westerhof wrote:
>>> I am looking into some performance metrics. I have the following code:
>>> [... incomplete code fragments deleted; see up-thread ...]
>>> Why the difference?
>>
>>      Perhaps someone could suggest an answer were the complete
>> program made available for inspection.  Hint, hint.
> 
> I uploaded the current program to:
>      https://github.com/CecilWesterhof/JavaExamples/blob/master/BoxedTest.java

     Thank you.  I'm now in a position to offer a few remarks,
although I can give only a partial explanation ("rationale"
might be better) for your results.

     Remark: What's the point of all those Threads?  The code
never starts even one of them, never uses any of them for
anything at all.

     Remark: The "%tT" format conversion can save you a little
effort.

> Originally it was to show the risks of using autoboxing, but when
> using an integer instead of a long I got this surprising result.
> 
> Only with long int I see an improvement in the performance. And quit a
> big one.

     Explanation/Rationale: Each test runs a loop to compute a sum,
but the sum is never subsequently used for anything at all: It is
not printed, it is not tested, it participates in no further
computation of any kind.  The JVM may well notice this and decide
not to bother computing the sum since it isn't needed.  A loop
that starts out as

	long sum = 0;
	for (int i = start; i < end; ++i) {
	    sum += i;
	}

... may then be transformed to

	for (int i = start; i < end; ++i) {
	}

... which (since the loop has no effect on anything except `i',
which is itself not used outside the loop) may be further
optimized to

	{
	}

... which casts just a wee bit of suspicion on the timings ;).
For example,

> The output I get on my system is:
>      09:02:30: Timing long int
> [...]
>      09:02:32: took 7.13E-07 seconds.

     Four billion additions in 713 nanoseconds?  Do you really
have a 570,000,000 GHz CPU chip?  How do you shield yourself
from the X-rays emitted at that frequency?  ;)  As Joshua
Cranmer suggests, some transformation of a "structural" nature
must have occurred -- possibly the transformation I illustrate,
or possibly something a bit different, but whatever's going on
it's clear that the loop is not being executed as written.

>      09:02:32: Timing long long
> [...]
>      09:02:46: took 3.81E+00 seconds.

     Okay, so why didn't the JVM perform the same transformation
on this loop?  I don't know.  At a guess, the JVM's pattern
matchers and other code analyzers are less aggressive with `long'
than with `int'.  This might reflect the implementors' opinion
that `long' will be used only when the coder Really Means It,
whereas `int' is used all over the place and thus presents more
opportunities to benefit from optimization.  In any event, the
reported time in this case is "sane" in that it comes to about
one nanosecond per loop execution -- four instructions, maybe?
I'm on shaky ground, but not actually sinking into quicksand.

>      09:02:50: Timing Long int
> [...]
>      09:05:14: took 3.97E+01 seconds.

     I'm on even shakier ground, but I suspect the JVM now sees
that the loop has an observable side-effect: It calls Long::valueOf
four billion times.  This probably means it constructs four billion
Long objects (and garbage-collects most of them), and the JVM may
be reluctant to delete four billion uses of a constructor as
"unnecessary."  Still, it's not too bad: You're creating Long
objects at a rate of 100 MHz, which is maybe forty or fifty
instructions apiece (including GC).

> [...]
>      09:14:00: Timing Long Integer
 > [...]
>      09:17:44: took 5.71E+01 seconds.

     This one creates four billion Longs and almost four billion
Integers (Integer::valueOf caches and re-uses a few of them).
The time doesn't quite double, presumably because an Integer
is smaller than a Long (16 vs. 24 bytes on my machine, YMMV)
so the garbage collector runs less often.

>      09:18:41: Timing Long Long
> [...]
>      09:23:07: took 7.30E+01 seconds.

     This is the only case that really baffles me, because it's
faster than I would have expected.  This one creates *two*
Longs per iteration, eight billion in all, so I would have
thought it'd take twice the time of the "Long plus long" test.
In fact, it only took 1.8 times as long, and any hand-waving I
could come up with to explain away the 20% would be ... well,
purest hand-waving.

     I took the liberty of rewriting your test to eliminate the
Threads, to print the calculated sums (restraining the JVM's
eagerness to optimize), and to run a warm-up phase before the
"in earnest" loops.  I'd be happy to mail you the code if you'd
like; maybe you can find as many "improvements" to mine as I did
to yours.

-- 
esosman@comcast-dot-net.invalid
Twelve hundred eighty-seven days to go.

[toc] | [prev] | [next] | [standalone]

#36901

Eric Sosman <esosman@comcast-dot-net.invalid> writes:

>     Remark: What's the point of all those Threads?  The code
> never starts even one of them, never uses any of them for
> anything at all.

I use the Threads as parameter to the test function.


>     Explanation/Rationale: Each test runs a loop to compute a sum,
> but the sum is never subsequently used for anything at all: It is
> not printed, it is not tested, it participates in no further
> computation of any kind.  The JVM may well notice this and decide
> not to bother computing the sum since it isn't needed.  A loop
> that starts out as
>
> 	long sum = 0;
> 	for (int i = start; i < end; ++i) {
> 	    sum += i;
> 	}
>
> ... may then be transformed to
>
> 	for (int i = start; i < end; ++i) {
> 	}
>
> ... which (since the loop has no effect on anything except `i',
> which is itself not used outside the loop) may be further
> optimized to
>
> 	{
> 	}
>
> ... which casts just a wee bit of suspicion on the timings ;).

OK, I change the code to return the sum.


>     I took the liberty of rewriting your test to eliminate the
> Threads, to print the calculated sums (restraining the JVM's
> eagerness to optimize), and to run a warm-up phase before the
> "in earnest" loops.  I'd be happy to mail you the code if you'd
> like; maybe you can find as many "improvements" to mine as I did
> to yours.

I would appreciate it when you could email the code: I can only learn
from it.

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

[toc] | [prev] | [next] | [standalone]

#36906

Cecil Westerhof <Cecil@decebal.nl> writes:

> Eric Sosman <esosman@comcast-dot-net.invalid> writes:
>>     Explanation/Rationale: Each test runs a loop to compute a sum,
>> but the sum is never subsequently used for anything at all: It is
>> not printed, it is not tested, it participates in no further
>> computation of any kind.  The JVM may well notice this and decide
>> not to bother computing the sum since it isn't needed.  A loop
>> that starts out as
>>
>> 	long sum = 0;
>> 	for (int i = start; i < end; ++i) {
>> 	    sum += i;
>> 	}
>>
>> ... may then be transformed to
>>
>> 	for (int i = start; i < end; ++i) {
>> 	}
>>
>> ... which (since the loop has no effect on anything except `i',
>> which is itself not used outside the loop) may be further
>> optimized to
>>
>> 	{
>> 	}
>>
>> ... which casts just a wee bit of suspicion on the timings ;).
>
> OK, I change the code to return the sum.

I rewrote the code and use Supplier<Long> now. That gives more sane
values. (Next time I should think twice before posting.)

I now get:
    19:10:13: Timing long int    
    19:10:13: took 2.95E+00 seconds.
    19:10:16: took 3.05E+00 seconds.
    19:10:19: took 3.05E+00 seconds.
    19:10:22: took 3.05E+00 seconds.
    19:10:25: took 3.04E+00 seconds.

    19:10:28: Timing long long   
    19:10:28: took 8.71E+00 seconds.
    19:10:37: took 8.79E+00 seconds.
    19:10:46: took 8.67E+00 seconds.
    19:10:54: took 8.68E+00 seconds.
    19:11:03: took 8.70E+00 seconds.

    19:11:12: Timing Long int    
    19:11:12: took 7.24E+01 seconds.
    19:12:24: took 7.08E+01 seconds.
    19:13:35: took 7.17E+01 seconds.
    19:14:46: took 7.01E+01 seconds.
    19:15:57: took 6.96E+01 seconds.

    19:17:06: Timing Long long   
    19:17:06: took 7.75E+01 seconds.
    19:18:24: took 7.82E+01 seconds.
    19:19:42: took 7.68E+01 seconds.
    19:20:59: took 7.68E+01 seconds.
    19:22:15: took 7.80E+01 seconds.

    19:23:33: Timing long Integer
    19:23:33: took 2.75E+01 seconds.
    19:24:01: took 2.75E+01 seconds.
    19:24:28: took 2.77E+01 seconds.
    19:24:56: took 2.76E+01 seconds.
    19:25:24: took 2.77E+01 seconds.

    19:25:51: Timing long Long   
    19:25:51: took 3.89E+01 seconds.
    19:26:30: took 3.89E+01 seconds.
    19:27:09: took 3.89E+01 seconds.
    19:27:48: took 3.90E+01 seconds.
    19:28:27: took 3.90E+01 seconds.

    19:29:06: Timing Long Integer
    19:29:06: took 7.99E+01 seconds.
    19:30:26: took 7.96E+01 seconds.
    19:31:46: took 7.95E+01 seconds.
    19:33:05: took 8.03E+01 seconds.
    19:34:26: took 7.72E+01 seconds.

    19:35:43: Timing Long Long   
    19:35:43: took 9.17E+01 seconds.
    19:37:15: took 9.15E+01 seconds.
    19:38:46: took 9.18E+01 seconds.
    19:40:18: took 9.19E+01 seconds.
    19:41:50: took 9.47E+01 seconds.

So long/integer is about three times as fast as long/long.
And long/long is about eight times as fast as Long/long.
Also long/long is about ten times as fast as Long/Long.

So I think it is save to say that when you could use an integer, you
should not use a long.
And that when you need to do a lot of calculations you should wait as
long as possible before converting to Long.

Or am I still overlooking something?

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

[toc] | [prev] | [next] | [standalone]

#36863

On 7/12/17 3:07 AM, Cecil Westerhof wrote:
> The second code takes about 50% more time to execute. No surprise
> there. But the first code is aggressively optimised when run several
> times (the fifth run is about 2½ million times faster as the first
> run), while the second code is not optimised:

Fundamentally speaking, you need to execute about 2^32 additions, if you 
do the loop. That means you need to take a billion clock cycles, or 
something on that magnitude, to do the loop, and anything less than that 
is indicative of the loop not being done.

I don't know your quality of microbenchmark suite, but a result that 
takes around a thousand clock cycles or so strongly suggests that the 
optimizer did loop idiom detection to replace the loop with sum = 
f(start, end). That the second loop didn't suggests either that the loop 
didn't tickle the loop idiom detector or that it bailed on computing the 
result do to an overflow. Since my development computer is currently 
nonfunctional, I can't do any more detailed analysis.

-- 
Beware of bugs in the above code; I have only proved it correct, not 
tried it. -- Donald E. Knuth

[toc] | [prev] | [next] | [standalone]

#36867

On Wed, 12 Jul 2017 09:19:36 -0500, Joshua Cranmer 🐧 wrote:

> I don't know your quality of microbenchmark suite, but a result that
> takes around a thousand clock cycles or so strongly suggests that the
> optimizer did loop idiom detection to replace the loop with sum =
> f(start, end). That the second loop didn't suggests either that the loop
> didn't tickle the loop idiom detector or that it bailed on computing the
> result do to an overflow. Since my development computer is currently
> nonfunctional, I can't do any more detailed analysis.
>
Or possibly the optimiser knows a fast way to add long to long but not to 
add int to long. 

Alternatively, the compiler may do mixed length integer addition by 
extending the shorter representation and then adding two integers of the 
same length and possibly the optimiser can't do a lot to speed that up.


-- 
martin@   | Martin Gregorie
gregorie. | Essex, UK
org       |

[toc] | [prev] | [next] | [standalone]

#36873

On 7/12/2017 4:07 AM, Cecil Westerhof wrote:
> I am looking into some performance metrics. I have the following code:
>      long sum = 0L;
> 
>      for (long i = start; i < end; ++i) {
>          sum += i;
>      }
> 
> And this code:
>      long sum = 0L;
> 
>      for (int i = start; i < end; ++i) {
>          sum += i;
>      }
> 
> Start and end are defined like:
>      private static int end   = Integer.MAX_VALUE;
>      private static int start = Integer.MIN_VALUE;
> 
> 
> The second code takes about 50% more time to execute. No surprise
> there. But the first code is aggressively optimised when run several
> times (the fifth run is about 2½ million times faster as the first
> run), while the second code is not optimised:
>      09:41:10: Timing long int
>      09:41:10: took 2.08E+00 seconds.
>      09:41:13: took 1.29E-03 seconds.
>      09:41:13: took 1.25E-04 seconds.
>      09:41:13: took 1.36E-06 seconds.
>      09:41:13: took 7.97E-07 seconds.
> 
>      09:41:13: Timing long long
>      09:41:13: took 3.09E+00 seconds.
>      09:41:16: took 3.11E+00 seconds.
>      09:41:19: took 4.03E+00 seconds.
>      09:41:23: took 3.94E+00 seconds.
>      09:41:27: took 3.87E+00 seconds.
> 
> Why the difference?

Other have already commented on the specifics.

But let me add a few general comments.

Optimizers are pretty smart these days, but they are not human. They
recognize certain patterns and do certain optimizations on them.

For a real world application consisting of thousands or tens
of thousands of constructs, then the optimizer get a large part
of them right and the result is an overall good performance.

But if you focus on just a single construct, then it becomes
almost random if the optimizer get it right or not.

And that conclusion is not constant over time. Any time
you switch Java version, then the optimizer can work
the same or do a better job or do a worse job.

Testing an extremely unrealistic small program for
something that is known that it can change with any
new Java version is in general not very productive.

Unless you happen to do number crunching and you need
to optimize DAXPY, then there are most likely much
better usage of the time.

Arne

[toc] | [prev] | [standalone]

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

csiph-web