If I remember right then the main issue with debug logging wasn't GC but that
generating some of the log string arguments in freenet was simply very resource
intensive in itself. So if Java isn't somehow intelligent enough to detect that
argument x isn't needed since it won't be used in the end anyway and thus
doesn't evaluate it before passing the value, then removing the current logic
will cause higher ressource usage once again.
In 'log.info("Random message: %s", obj.toString())' evaluating 'obj.toString()'
was what caused issues, not recycling it, or so I believe to remember.
The main things causing GC issues which I remember were not reusing threads and
spawning a few new objects per received and send packet, not the log stuff,
that probably just tipped things over the edge when GC was already done heavily
because of the former.
Speeking out of memory as a non Java-dev here, so ignore if applicable. :P
________________________________
Von: Ximin Luo <infinity0 at gmx.com>
An: devl at freenetproject.org
Gesendet: 4:33 Samstag, 24.M?rz 2012
Betreff: Re: [freenet-dev] Logging in Fred
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 <infinity0 at 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 at freenetproject.org
>> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
> _______________________________________________
> Devl mailing list
> Devl at 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 at freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
-------------- next part --------------
An HTML attachment was scrubbed...
URL:
<https://emu.freenetproject.org/pipermail/devl/attachments/20120328/00a21308/attachment.html>
