RFR: 8076161: LogEvents filter is now applied earlier to avoid unnecessary string construction.

[David Holmes]

Hi Max,

Seems perfectly reasonable. Reviewed.

Thanks,
David



On 9/06/2015 8:13 AM, Max Ockner wrote:
> Hello,
> Please review this fix.
>
> Bug: https://bugs.openjdk.java.net/browse/JDK-8076161
> Webrev: http://cr.openjdk.java.net/~mockner/8076161/
>
> Summary:  The body of Events::log_exception() is filtered by the
> LogEvents flag. This is supposed to prevent the function from wasting
> time when LogEvents is turned off. Before this fix, a possibly large
> format string was passed into the function and is constructed before the
> LogEvents filter is applied. Since the entire body of
> Events::log_exception is conditioned on LogEvents, there is another
> LogEvents filter around Events::log_exception(). The only call to
> log_exceptions that this change applies to is the one in
> Exceptions::_throw because most of the calls come from there, and I do
> not want to suggest that this is the best permanent fix. However, I do
> believe this is the best fix that doesn't change or add a lot of code,
> and I have shown that it does improve performance. Below are some
> benchmark results (the benchmark is the same one that appeared in the
> comments on the bug page).
>
> Benchmarks:
>
> 1) Clean repo with LogEvents OFF
> Baseline-off                       (bias)  (count)  Mode  Cnt Score
> Error  Units
> ImplicitNullChecks.testExplicit     0.0     1000  avgt   50 3.161 ±
> 0.006  us/op
> ImplicitNullChecks.testExplicit     0.5     1000  avgt   50 5991.922 ±
> 83.419  us/op
> ImplicitNullChecks.testExplicit     1.0     1000  avgt   50 12047.777 ±
> 78.517  us/op
> ImplicitNullChecks.testImplicit     0.0     1000  avgt   50 3.168 ±
> 0.007  us/op
> ImplicitNullChecks.testImplicit     0.5     1000  avgt   50 20751.388 ±
> 325.065  us/op
> ImplicitNullChecks.testImplicit     1.0     1000  avgt   50 41402.197 ±
> 407.636  us/op
>
> 2) Fixed repo with LogEvents OFF
> Modified-off                       (bias)  (count)  Mode  Cnt Score
> Error  Units
> ImplicitNullChecks.testExplicit     0.0     1000  avgt   50 3.163 ±
> 0.007  us/op
> ImplicitNullChecks.testExplicit     0.5     1000  avgt   50 5733.610 ±
> 86.945  us/op
> ImplicitNullChecks.testExplicit     1.0     1000  avgt   50 11362.151 ±
> 71.750  us/op
> ImplicitNullChecks.testImplicit     0.0     1000  avgt   50 3.163 ±
> 0.007  us/op
> ImplicitNullChecks.testImplicit     0.5     1000  avgt   50 17721.661 ±
> 362.937  us/op
> ImplicitNullChecks.testImplicit     1.0     1000  avgt   50 35007.120 ±
> 309.886  us/op
>
> 3) Clean repo with LogEvents ON
> Baseline-on                       (bias)  (count)  Mode  Cnt Score
> Error  Units
> ImplicitNullChecks.testExplicit     0.0     1000  avgt   50 3.161 ±
> 0.007  us/op
> ImplicitNullChecks.testExplicit     0.5     1000  avgt   50 6086.867 ±
> 100.584  us/op
> ImplicitNullChecks.testExplicit     1.0     1000  avgt   50 12130.285 ±
> 87.830  us/op
> ImplicitNullChecks.testImplicit     0.0     1000  avgt   50 3.159 ±
> 0.007  us/op
> ImplicitNullChecks.testImplicit     0.5     1000  avgt   50 25559.707 ±
> 324.303  us/op
> ImplicitNullChecks.testImplicit     1.0     1000  avgt   50 50383.913 ±
> 377.618  us/op
>
> 4) Fixed repo with LogEvents ON
> Modified-on                      (bias)  (count)  Mode  Cnt Score Error
> Units
> ImplicitNullChecks.testExplicit     0.0     1000  avgt   50 3.163 ±
> 0.007  us/op
> ImplicitNullChecks.testExplicit     0.5     1000  avgt   50 5690.737 ±
> 97.704  us/op
> ImplicitNullChecks.testExplicit     1.0     1000  avgt   50 11376.765 ±
> 67.243  us/op
> ImplicitNullChecks.testImplicit     0.0     1000  avgt   50 3.161 ±
> 0.009  us/op
> ImplicitNullChecks.testImplicit     0.5     1000  avgt   50 24464.360 ±
> 393.227  us/op
> ImplicitNullChecks.testImplicit     1.0     1000  avgt   50 48913.627 ±
> 449.750  us/op
>
> Looks like up to 10-15% speedup on this particular benchmark for runs
> with -XX:-LogEvents.
>
> Tested with jtreg runtime tests.
>
> Thanks,
> Max