Path: csiph.com!eternal-september.org!feeder.eternal-september.org!news.eternal-september.org!.POSTED!not-for-mail From: Eric Sosman Newsgroups: comp.lang.java.programmer Subject: Re: One code is aggressively optimised, while another not. Why? Date: Thu, 13 Jul 2017 11:05:42 -0400 Organization: A noiseless patient Spider Lines: 132 Message-ID: References: <87lgnu5b9o.fsf@munus.decebal.nl> <87h8yg6ag8.fsf@munus.decebal.nl> Mime-Version: 1.0 Content-Type: text/plain; charset=utf-8; format=flowed Content-Transfer-Encoding: 7bit Injection-Date: Thu, 13 Jul 2017 15:01:50 -0000 (UTC) Injection-Info: mx02.eternal-september.org; posting-host="d663e4e694f4718b1ad59473425b82f1"; logging-data="7430"; mail-complaints-to="abuse@eternal-september.org"; posting-account="U2FsdGVkX19Vs2QuSjsRi/mRzGXlMSoh" User-Agent: Mozilla/5.0 (Windows NT 10.0; WOW64; rv:52.0) Gecko/20100101 Thunderbird/52.2.1 In-Reply-To: <87h8yg6ag8.fsf@munus.decebal.nl> Content-Language: en-US Cancel-Lock: sha1:msJnh+MPTebHzjJTxZIw77WgOgg= Xref: csiph.com comp.lang.java.programmer:36895 On 7/13/2017 3:51 AM, Cecil Westerhof wrote: > Eric Sosman 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.