Wrong. Extracting the log statement into its own method and calling
that method inside the while loop still creates garbage. Stack frames
are different.
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.
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.
On Fri, Mar 23, 2012 at 10:28 PM, Ximin Luo <infinity0 at gmx.com> wrote:
> On 24/03/12 01:56, Zlatin Balevsky wrote:
>> Not really. ?Here, I'll change my call to allocate everything on one level:
>>
>> ? while (true) {
>> ? ? ? ? ? ? ? log(" list size is {1} ",
>> ? ? ? ? ? ? ? ? new Integer(listToLog.size()));
>> ? ? ? ? ? }
>>
>> I don't see how using this you can log primitive values without garbage.
>>
>
> This still allocates many "new Integer()" on the stack without giving them an
> opportunity to be destroyed, because this occurs all on the same stack frame.
> Eventually there is no more space for stack allocation, leading to heap
> allocation and GC. This is an uncommon situation to pop up in real code
> however, because in most cases you don't have an extremely long loop.
>
> Have a look at the difference between testWithStackAllocation and
> testWithoutStackAllocation in the example I posted, and the huge difference in
> their run times; maybe it will be clearer then.
>
> Arguably the JVM should be smart enough to destroy things at the end of a code
> block when things go out of scope, including loops, but practically that
> doesn't appear to be the case. (Unless you have another explanation for the
> behaviour encountered when running my test code?)
>
> One reason I'm opposed to the predicate form, is because it encourages things
> like
>
> | if (log_level) {
> | ? // huge complex calculation
> | ? // that takes up many lines
> | ? // and distracts from the rest of the code
> | ? log.level(args);
> | }
>
> We could agree to restrict logging calls to be of the form
>
> | if (log_level) log.level(
> | ? ?args ... );
>
> which would at least force the complex calculations to be factored out into
> another method.
>
>> On Fri, Mar 23, 2012 at 9:33 PM, Ximin Luo <infinity0 at gmx.com> wrote:
>>> That is because in your example you're allocating all those new Object()s in
>>> the same stack frame, so the allocator runs out of space on the stack.
>>>
>>> If you put the call to log(x, new Object()) inside its only function call,
>>> each
>>> Object will be destroyed once that call exits, and no GC occurs.
>>>
>>> Example code here:
>>> https://gist.github.com/2177070
>>>
>>> The "real use case" just adds one simple operation with each logging call
>>> (since you're never logging without doing something else as well) to show
>>> how
>>> little of a difference it makes in real terms (<5%).
>>>
>>> X
>>>
>>> On 24/03/12 01:15, Zlatin Balevsky wrote:
>>>> You're right, the example you gave will put the arguments on the
>>>> stack. ?I wanted to clarify Escape Analysis in its current form works
>>>> only if a new object doesn't exit the stack frame where it's created.
>>>> Because of that, the moment you do something slightly more complicated
>>>> you will create garbage like this:
>>>>
>>>> ? ?private static void logListSize ( final List<?> listToLog ) {
>>>> ? ? ? ? LOG.log(" list size is {1} ",
>>>> ? ? ? ? ? ? ? ? new Object() {
>>>> ? ? ? ? ? ? ? ? ? ? ? ? public String toString() {
>>>> ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? return String.valueOf(listToLog.size());
>>>> ? ? ? ? ? ? ? ? ? ? ? ? }
>>>> ? ? ? ? ? ? ? ? });
>>>> ? ? }
>>>>
>>>> Here is the tricky part - if you can guarantee that everywhere in the
>>>> jvm the LOG.log method is disabled by the logging system, then the
>>>> entire call will compile to noop and no objects will be created.
>>>> However, if even one call site enables logging you will end up
>>>> creating the temp objects even if they don't get logged. ?Below is a
>>>> full example, compile and run passing "-verbosegc -XX:+PrintGC" and
>>>> watch it GC all the time.
>>>>
>>>> ===== ?LazyEvalTest.java ===
>>>> import java.util.*;
>>>>
>>>> public class LazyEvalTest {
>>>>
>>>> ? ? // only if this is is always false does logging produce no garbage.
>>>> ? ? private static boolean shouldLog = true;
>>>>
>>>> ? ? private static void log(String ar1, Object ar2) {
>>>> ? ? ? ? if (shouldLog)
>>>> ? ? ? ? ? ? ?System.out.println(ar1 + ar2.toString());
>>>> ? ? ? ? shouldLog = false;
>>>> ? ? }
>>>>
>>>> ? ? public static void main(String []ar) {
>>>>
>>>> ? ? ? ? final List<Object> listToLog = new ArrayList<Object>(1000);;
>>>>
>>>> ? ? ? ? ? while (true) {
>>>> ? ? ? ? ? ? ? log(" list size is {1} ",
>>>> ? ? ? ? ? ? ? ? new Object() {
>>>> ? ? ? ? ? ? ? ? ? ? ? ? public String toString() {
>>>> ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? return String.valueOf(listToLog.size());
>>>> ? ? ? ? ? ? ? ? ? ? ? ? }
>>>> ? ? ? ? ? ? ? ? });
>>>> ? ? ? ? ? }
>>>> ? ? }
>>>> }
>>>> ======
>>>>
>>>> As far as garbage collection times go, they are a function of the
>>>> count of live objects and on how easy it is to scan them in parallel
>>>> and a whole bunch of other factors. ?Others can answer better what
>>>> values are common for Fred.
>>>>
>>>> Zlatin
>>>>
>>>> On Thu, Mar 22, 2012 at 11:47 PM, Ximin Luo <infinity0 at gmx.com> wrote:
>>>>> LOL, are you kidding me?
>>>>>
>>>>> Please point to the exact lines of code that results in "double-digit
>>>>> millisecond pauses"?
>>>>>
>>>>> Talk is cheap, show us some numbers.
>>>>>
>>>>> BTW, the "example" I gave is not real code, and contains no variable
>>>>> declarations, so your challenge makes no sense. Since you apparently
>>>>> didn't
>>>>> understand my implicit argument, here it is in more detail: a typical
>>>>> method
>>>>> that computes something simply for the purpose of logging it somewhere,
>>>>> usually
>>>>> only allocates local variables that are not stored anywhere in the long
>>>>> term.
>>>>> Escape analysis can turn these into stack allocations, saving GC
>>>>> overhead. (If
>>>>> they do use more long-term variables, they will need to be stored on the
>>>>> heap,
>>>>> but then GC doesn't need to clean these up anyway.)
>>>>>
>>>>> Why are you even looking at blog entries? Escape analysis has been around
>>>>> for
>>>>> years. http://hg.openjdk.java.net/jdk6/jdk6/hotspot/rev/357d4e2eb4dd
>>>>>
>>>>> On 23/03/12 02:06, Zlatin Balevsky wrote:
>>>>>> My claim is based on day-to-day observations of hundreds of JVMs under
>>>>>> various
>>>>>> load scenarios.
>>>>>>
>>>>>> Your claim that modern JVMs "do escape analysis" is worthless as it
>>>>>> shows that
>>>>>> you have merely read some blog posts, and even those you've read only
>>>>>> partially. ?Please point to the exact lines of code in hotspot or any
>>>>>> other
>>>>>> modern jvm that will optimize the specific lazy evaluation example you
>>>>>> presented, together with the opto-assembly that their JITs produce.
>>>>>> ?Failing
>>>>>> that, take your attitude elsewhere.
>>>>>>
>>>>>> On Thu, Mar 22, 2012 at 8:49 PM, Ximin Luo <infinity0 at gmx.com
>>>>>> <mailto:infinity0 at gmx.com>> wrote:
>>>>>>
>>>>>> ? ? The "drastically cleaner syntax" is a red herring. Most of the time
>>>>>> when you
>>>>>> ? ? are doing a complex calculation, you are not going to put it on one
>>>>>> line
>>>>>> ? ? anyway. In such cases, the function you are using to do the
>>>>>> calculation might
>>>>>> ? ? as well be the toString() method of some object.
>>>>>>
>>>>>> ? ? Your claim of "double-digit millisecond" pauses is worthless without
>>>>>> some
>>>>>> ? ? benchmarking and actual numbers. Modern JVMs do escape analysis to
>>>>>> avoid heap
>>>>>> ? ? allocation and this helps especially for transient computations like
>>>>>> in
>>>>>> ? ? logging.
>>>>>>
>>>>>> ? ? On 22/03/12 21:59, Zlatin Balevsky wrote:
>>>>>> ? ? > Double-digit millisecond pauses are not nothing. ?They may be
>>>>>> acceptable
>>>>>> ? ? right
>>>>>> ? ? > now but unless you can offer a drastically cleaner syntax Fred
>>>>>> should stick
>>>>>> ? ? > with predicates as they are handled much better by the hotspot jit.
>>>>>> ? ? >
>>>>>> ? ? > On Mar 22, 2012 5:36 PM, "Ximin Luo" <infinity0 at gmx.com
>>>>>> ? ? <mailto:infinity0 at gmx.com>
>>>>>> ? ? > <mailto:infinity0 at gmx.com <mailto:infinity0 at gmx.com>>> wrote:
>>>>>> ? ? >
>>>>>> ? ? > ? ? Lazy evaluation is trivial.
>>>>>> ? ? >
>>>>>> ? ? > ? ? Log.info("{1} did {2}",
>>>>>> ? ? > ? ? ?new Object(){ public String toString() { return ITEM_1; } },
>>>>>> ? ? > ? ? ?new Object(){ public String toString() { return ITEM_2; } }
>>>>>> ? ? > ? ? );
>>>>>> ? ? >
>>>>>> ? ? > ? ? Garbage collection with short-lived objects costs next to
>>>>>> nothing.
>>>>>> ? ? >
>>>>>> ? ? > ? ? On 22/03/12 21:15, Zlatin Balevsky wrote:
>>>>>> ? ? > ? ? > Constructing the logging strings is half of the problem.
>>>>>> ?The amount of
>>>>>> ? ? > ? ? garbage
>>>>>> ? ? > ? ? > they will generate will result in significantly more time in
>>>>>> garbage
>>>>>> ? ? > ? ? collection
>>>>>> ? ? > ? ? > pauses.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > Unless you figure out a way to mimic lazy evaluation you
>>>>>> have to live
>>>>>> ? ? > ? ? with the
>>>>>> ? ? > ? ? > isLoggable predicates. ?varargs are not an option either
>>>>>> because
>>>>>> ? ? they also
>>>>>> ? ? > ? ? > create garbage.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > On Mar 22, 2012 8:11 AM, "Marco Schulze" <marco.c.schulze at
>>>>>> gmail.com
>>>>>> ? ? <mailto:marco.c.schulze at gmail.com>
>>>>>> ? ? > ? ? <mailto:marco.c.schulze at gmail.com <mailto:marco.c.schulze
>>>>>> at gmail.com>>
>>>>>> ? ? > ? ? > <mailto:marco.c.schulze at gmail.com
>>>>>> ? ? <mailto:marco.c.schulze at gmail.com> <mailto:marco.c.schulze at
>>>>>> gmail.com
>>>>>> ? ? <mailto:marco.c.schulze at gmail.com>>>> wrote:
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? On 22-03-2012 08:50, Matthew Toseland wrote:
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? On Wednesday 21 Mar 2012 21:18:37 Marco Schulze
>>>>>> wrote:
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? There are basically two big concerns regarding
>>>>>> logging
>>>>>> ? ? in fred:
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Readability and code clutter, which was my
>>>>>> original
>>>>>> ? ? > ? ? questioning;
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Raw throughput, as raised by toad.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? Point 1 could mostly be solved by removing any
>>>>>> traces of
>>>>>> ? ? > ? ? logMINOR and
>>>>>> ? ? > ? ? > ? ? ? ? ? ? logDEBUG on all but the few places where
>>>>>> generating
>>>>>> ? ? messages
>>>>>> ? ? > ? ? to be
>>>>>> ? ? > ? ? > ? ? ? ? ? ? logged brings noticeable slowdown. That'd be
>>>>>> enough, but,
>>>>>> ? ? > ? ? personally,
>>>>>> ? ? > ? ? > ? ? ? ? ? ? the mess that the logging backend is does
>>>>>> warrant a
>>>>>> ? ? replacement.
>>>>>> ? ? > ? ? > ? ? ? ? ? ? According to toad, the current system needs
>>>>>> ? ? log{MINOR,DEBUG} to
>>>>>> ? ? > ? ? > ? ? ? ? ? ? function
>>>>>> ? ? > ? ? > ? ? ? ? ? ? in a timely manner. Based on this, I think we
>>>>>> all agree a
>>>>>> ? ? > ? ? > ? ? ? ? ? ? replacement is
>>>>>> ? ? > ? ? > ? ? ? ? ? ? desirable.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? Logging has a few additional requirements:
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Log rotation (possibly live);
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Reentrant;
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Per-class filtering;
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Specific information in log (class-name, for
>>>>>> example).
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? Now, _any_ library which fits would make me
>>>>>> happy, as
>>>>>> ? ? long as
>>>>>> ? ? > ? ? they
>>>>>> ? ? > ? ? > ? ? ? ? ? ? agree
>>>>>> ? ? > ? ? > ? ? ? ? ? ? to two points:
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Either lightweight or with optional features.
>>>>>> Else, it
>>>>>> ? ? > ? ? would only
>>>>>> ? ? > ? ? > ? ? ? ? ? ? transfer bloat to freenet-ext.jar. For example:
>>>>>> log2socket,
>>>>>> ? ? > ? ? config
>>>>>> ? ? > ? ? > ? ? ? ? ? ? management and multiple logging instances;
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Implementable in a few LoC. Specially, it
>>>>>> shouldn't need
>>>>>> ? ? > ? ? specialized
>>>>>> ? ? > ? ? > ? ? ? ? ? ? Formatter and Writer.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? Plus, it should be fast.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? ?From the quick research I made (yep, too many
>>>>>> lists):
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - SLF4J already fails on point one: it is simply
>>>>>> a wrapper;
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - The Java logging API fails on point two:
>>>>>> specialized
>>>>>> ? ? > ? ? classes would
>>>>>> ? ? > ? ? > ? ? ? ? ? ? have to be written to deal with log rotation,
>>>>>> per-class
>>>>>> ? ? > ? ? filtering and
>>>>>> ? ? > ? ? > ? ? ? ? ? ? formatting, plus a wrapper for
>>>>>> Logger.{info,warning,...}()
>>>>>> ? ? > ? ? methods.
>>>>>> ? ? > ? ? > ? ? ? ? ? ? Exactly the same as a custom logger, with one
>>>>>> more
>>>>>> ? ? dependency
>>>>>> ? ? > ? ? and using
>>>>>> ? ? > ? ? > ? ? ? ? ? ? more LoC;
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? No dependancies, it's part of the JDK, isn't it?
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? More classes need to be loaded at startup. It's just me
>>>>>> ? ? thinking too
>>>>>> ? ? > ? ? much.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? However, if it's not a clearer/simpler API, it
>>>>>> probably
>>>>>> ? ? doesn't make
>>>>>> ? ? > ? ? > ? ? ? ? much sense.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? - Log4J seems to fail on point one - it only
>>>>>> lacks a button
>>>>>> ? ? > ? ? that brings
>>>>>> ? ? > ? ? > ? ? ? ? ? ? back the dead. It seems interesting, and I
>>>>>> haven't dropped
>>>>>> ? ? > ? ? this yet.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? ? ? In either case (custom or external), log* would
>>>>>> be
>>>>>> ? ? banished.
>>>>>> ? ? > ? ? Forever.
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? ? ? I don't follow. You object to using a separate logs
>>>>>> folder?
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > ? ? log* == log{MINOR,DEBUG}, not the logs folder.
>>>>>> ? ? > ? ? > ? ? _________________________________________________
>>>>>> ? ? > ? ? > ? ? Devl mailing list
>>>>>> ? ? > ? ? > ? ? Devl at freenetproject.org <mailto:Devl at
>>>>>> freenetproject.org>
>>>>>> ? ? <mailto:Devl at freenetproject.org <mailto:Devl at
>>>>>> freenetproject.org>>
>>>>>> ? ? > ? ? <mailto:Devl at freenetproject.org <mailto:Devl at
>>>>>> freenetproject.org>
>>>>>> ? ? <mailto:Devl at freenetproject.org <mailto:Devl at
>>>>>> freenetproject.org>>>
>>>>>> ? ? > ? ? > ? ?
>>>>>> https://emu.freenetproject.__org/cgi-bin/mailman/listinfo/__devl
>>>>>> ? ? > ? ? > ? ?
>>>>>> <https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl>
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? >
>>>>>> ? ? > ? ? > _______________________________________________
>>>>>> ? ? > ? ? > Devl mailing list
>>>>>> ? ? > ? ? > Devl at freenetproject.org <mailto:Devl at
>>>>>> freenetproject.org>
>>>>>> ? ? <mailto:Devl at freenetproject.org <mailto: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
>>>>>> <https://launchpad.net/%7Einfinity0>
>>>>>> ? ? >
>>>>>> ? ? >
>>>>>> ? ? > ? ? _______________________________________________
>>>>>> ? ? > ? ? Devl mailing list
>>>>>> ? ? > ? ? Devl at freenetproject.org <mailto:Devl at freenetproject.org>
>>>>>> ? ? <mailto:Devl at freenetproject.org <mailto:Devl at
>>>>>> freenetproject.org>>
>>>>>> ? ? > ? ? https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
>>>>>> ? ? >
>>>>>> ? ? >
>>>>>> ? ? >
>>>>>> ? ? > _______________________________________________
>>>>>> ? ? > Devl mailing list
>>>>>> ? ? > Devl at freenetproject.org <mailto: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 <https://launchpad.net/%7Einfinity0>
>>>>>>
>>>>>>
>>>>>> ? ? _______________________________________________
>>>>>> ? ? Devl mailing list
>>>>>> ? ? Devl at freenetproject.org <mailto: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
>>>> _______________________________________________
>>>> 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
>> _______________________________________________
>> 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
