It doesn't look like a big deal but if all of Fred was using lazy
evaluation for logging it would make one common use case very
annoying:
Say I'm working on a specific class and need to run that class with
debug logging enabled. This would have the side effect of changing
the compiled LOG.debug( ... ) method globally across the JVM and would
cause every log lazily evaluated parameter for every debug statement
to be instantiated. Production deployments would not be affected but
the developer experience would.
P.S. nice trick with the Double.MIN_VALUE, I'll use that sometime :)
On Fri, Mar 23, 2012 at 11:33 PM, Ximin Luo <infini...@gmx.com> wrote:
> I see.
>
> Actually we didn't even need the side effects thing - I did notice that your
> example stopped doing GC when setting "shouldLog = false" always, so I tried
> to
> introduce your "if (shouldLog) { shouldLog = false; }" into my example, but
> was
> still unable to reproduce GC. Then changing
>
> - System.out.println("don't optimise me out");
> + System.out.println(format + args);
>
> worked to re-introduce GC.
>
> Well, that sucks. I guess the escape analyzer isn't sophisticated enough to
> see
> that ar2.toString() does not cause ar2 to escape - and removing that from your
> log() method does result in no GC.
>
> I still think it's negligible though :p - for my test, I'm seeing only ~8ms
> lost to GC after 20 million calls, and this appears to not change by much even
> if I increase the number of arguments (and objects created) to log_info.
>
> On 24/03/12 03:02, Zlatin Balevsky wrote:
>> Your test has nothing to do with stack allocation because you never
>> use the objects that you pass to the log_info method so JIT removes
>> them. Apply the following patch and see yourself create garbage in
>> both testWith and testWithout.
>>
>> --- Test2.java 2012-03-23 23:01:05.540475497 -0400
>> +++ Test.java 2012-03-23 23:01:47.304477562 -0400
>> @@ -6,8 +6,11 @@
>> final Object existing = new Object();
>> Object tmp = null;
>>
>> + long sideEffect;
>> public void log_info(String format, Object ... args) {
>> if (log_level) {
>> + for (Object o : args)
>> + sideEffect += o.hashCode();
>> System.out.println("don't optimise me out");
>> }
>> }
>> @@ -88,11 +91,8 @@
>> printSummary("with alloc", res[0], "w/o alloc", res[1]);
>> printSummary("with alloc", res[2], "w/o alloc", res[3]);
>> printSummary("with alloc", res[4], "w/o alloc", res[5]);
>> - System.out.println("---- with stack allocation and \"real use case\"");
>> - res = testWithOtherCode(z);
>> - printSummary("log only", res[0], "log+work", res[1]);
>> - printSummary("log only", res[2], "log+work", res[3]);
>> - printSummary("log only", res[4], "log+work", res[5]);
>> +
>> + System.out.println(sideEffect);
>> }
>>
>> public static void main(String[] args) {
>>
>>
>> On Fri, Mar 23, 2012 at 10:48 PM, Ximin Luo <infini...@gmx.com> wrote:
>>> On 24/03/12 02:44, Zlatin Balevsky wrote:
>>>> Wrong. Extracting the log statement into its own method and calling
>>>> that method inside the while loop still creates garbage. Stack frames
>>>> are different.
>>>>
>>>
>>> How do you explain the results obtained from running my test code, then?
>>> Turn
>>> on -verbose:gc. testWithStackAllocation results in no GC,
>>> testWithoutStackAllocation results in lots of GC.
>>>
>>>> Read again exactly how Escape Analysis works. The objects it prevents
>>>> from creating do not appear in heap histograms. Take a "jmap -histo
>>>> <pid>" and you will see a huge number of java.lang.Integer objects in
>>>> the heap, not on the stack.
>>>>
>>>
>>> If you're still talking about your example, this is exactly consistent with
>>> my
>>> explanation, i.e. that escape analysis is NOT occurring, properly anyway.
>>>
>>>> The difference in run times of your example could be due to many
>>>> things. How many iterations did you run? It may be still in
>>>> interpreted mode. Enable -XX:+PrintCompilation and discard any
>>>> results until JIT stops printing.
>>>
>>> Done that, JIT stops printing after the 3rd iteration and results are the
>>> same
>>> thereafter.
>>>
>>> --
>>> GPG: 4096R/5FBBDBCE
>>> https://github.com/infinity0
>>> https://bitbucket.org/infinity0
>>> https://launchpad.net/~infinity0
>>>
>>>
>>> _______________________________________________
>>> Devl mailing list
>>> Devl@freenetproject.org
>>> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
>> _______________________________________________
>> Devl mailing list
>> Devl@freenetproject.org
>> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
>
>
> --
> GPG: 4096R/5FBBDBCE
> https://github.com/infinity0
> https://bitbucket.org/infinity0
> https://launchpad.net/~infinity0
>
>
> _______________________________________________
> Devl mailing list
> Devl@freenetproject.org
> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
_______________________________________________
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
