[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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  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  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
 " 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

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

As to why it still creates garbage even if you do not touch the
arguments in the testWithout method, I would guess that different
inlining rules apply to large methods, small methods and methods that
are already inlined within other methods.

To give definitive answer I'll have to look through the opto assembly
which will take me a couple of hours.  There was something in the
-XX:+LogCompilation output but that's just a hint.  To get to the
truth you need the assembly code.

Back to the original issue

Some kind of automated post-processing can be set up that cause
compilation errors if anything other than LOG.log is used inside of an
if (isLoggable) predicate.  I've seen an example where AspectJ can be
set up to trigger compilation errors every time it encounters a
System.out and System.err reference.  I'm sure there are many
solutions, some even integrate with IDEs.

On Fri, Mar 23, 2012 at 11:02 PM, 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  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
>>> " 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

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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  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
>> " 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

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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
" 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  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  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 listToLog = new ArrayList(1000);;

 ? ? ? ? ? while (true) {
 ? ? ? ? ? ? ? log(" list size is {1} ",
 ? ? ? ? ? ? ? ? new Object() {
 ? ? ? ? ? ? ? ? ? ? ? ? public String toString() {
 ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? ? return String.value

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

The only bug-vector I see in the current predicate approach is that
when used incorrectly it cause the size of methods to explode.  There
are some hard-coded thresholds for the method size in bytecodes that
turn off some or all JIT optimizations; there are also a whole host of
compilation parameters which are optimized with smaller methods in
mind.

Unless someone can offer a great syntactic improvement I recommend
against home-brew frameworks.  Aspects may be able to clean things up
nicely though, I'd be very curious to see some examples.

On Fri, Mar 23, 2012 at 9:56 PM, 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.
>
> On Fri, Mar 23, 2012 at 9:33 PM, Ximin Luo  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 listToLog = new ArrayList(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  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 base

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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.

On Fri, Mar 23, 2012 at 9:33 PM, Ximin Luo  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 listToLog = new ArrayList(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  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 >>> > wrote:

 ? ? The "drastically cleaner syntax" is a red herring. Most of the time 
>>>

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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 listToLog = new ArrayList(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  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 > > 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" > ? ? 
>> ? ? > >> wrote:
>> ? ? >
>> ? ? > ? ? Lazy evaluation is trivial.
>> ? ? >
>> ? ? > ? ? Log.info("{1} did {2}",
>> ? ? > ? ? ?new Object(){ public String toString() { return ITEM_1; } },
>> ? ? > ? ? ?new Object(){ public String toString() { return

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

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  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  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
 " 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

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

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.java2012-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  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
>>> " 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



signature.asc
Description: OpenPGP digital signature
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

As to why it still creates garbage even if you do not touch the
arguments in the testWithout method, I would guess that different
inlining rules apply to large methods, small methods and methods that
are already inlined within other methods.

To give definitive answer I'll have to look through the opto assembly
which will take me a couple of hours.  There was something in the
-XX:+LogCompilation output but that's just a hint.  To get to the
truth you need the assembly code.

Back to the original issue

Some kind of automated post-processing can be set up that cause
compilation errors if anything other than LOG.log is used inside of an
if (isLoggable) predicate.  I've seen an example where AspectJ can be
set up to trigger compilation errors every time it encounters a
System.out and System.err reference.  I'm sure there are many
solutions, some even integrate with IDEs.

On Fri, Mar 23, 2012 at 11:02 PM, 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  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
>>> " 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

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

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  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
>> " 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

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

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
> " 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



signature.asc
Description: OpenPGP digital signature
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

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
" 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  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  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 listToLog = new ArrayList(1000);;

           while (true) {
               log(" list size is {1} ",
                 new Object() {
                         public String toString() {
                                 return String.value

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

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  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 listToLog = new ArrayList(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  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 m

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

The only bug-vector I see in the current predicate approach is that
when used incorrectly it cause the size of methods to explode.  There
are some hard-coded thresholds for the method size in bytecodes that
turn off some or all JIT optimizations; there are also a whole host of
compilation parameters which are optimized with smaller methods in
mind.

Unless someone can offer a great syntactic improvement I recommend
against home-brew frameworks.  Aspects may be able to clean things up
nicely though, I'd be very curious to see some examples.

On Fri, Mar 23, 2012 at 9:56 PM, 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.
>
> On Fri, Mar 23, 2012 at 9:33 PM, Ximin Luo  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 listToLog = new ArrayList(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  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 base

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

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.

On Fri, Mar 23, 2012 at 9:33 PM, Ximin Luo  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 listToLog = new ArrayList(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  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 >>> > wrote:

     The "drastically cleaner syntax" is a red herring. Most of the time 
 w

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

Sorry, bad typing. "inside its own" not "inside its only".

On 24/03/12 01:33, Ximin Luo 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 listToLog = new ArrayList(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  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 >>> > 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 toStri

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

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 listToLog = new ArrayList(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  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 >> > 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 es

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

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 listToLog = new ArrayList(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  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 > > 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" >     
>>     > >> 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; } }

[freenet-dev] Logging in Fred

[Matthew Toseland]

>   >   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"
> >>>>>   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.
> >>
> 
> 
-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/a2034fe0/attachment.pgp>

[freenet-dev] Logging in Fred

[Matthew Toseland]

>  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.
> 
> 
-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/c4ee8c15/attachment.pgp>

[freenet-dev] Refactoring Freenet and Library was Re: Gun.IO and Freenet

[Matthew Toseland]

 events framework? Executor and Ticker? If you're not even talking about 
DB* then what classes are we arguing about here?
> 
> > I agree we should make *Executor use the standard APIs though - while 
> > keeping the ability to change thread priorities.
> >>
> >> An events framework could handle errant plugins by setting a timeout for 
> >> all
> >> blocking jobs. If they don't complete within X time, interrupt the thread
> >> and/or kill it if it doesn't respond to the interrupt. If the plugin can't
> >> handle it, tough shit their fault. (This is how certain companies run 
> >> reliable
> >> services on a massive scale.)
> > 
> > Can't be done. Period.
> > 
> > It's Java. Java does not support killing threads. According to the 
> > documentation the reason for this is that killing a thread might cause 
> > synchronization problems. Which is true, but I would have thought it was 
> > solvable ... Anyway if you need to be able to kill stuff it has to run in 
> > *a separate JVM*.
> 
> Then interrupt is fine and covers most cases.

It covers some cases. It will not provide reliability against broken plugins; 
it's like Future.cancel(), it only works if you implement it. For most plugins, 
interrupting a running thread isn't useful - work isn't easily reverted. If you 
want specific plugins to use Future's I have no issue with importing the 
relevant APIs from Java or even from (small) third party libraries.
> 
> >> As for the updater, simply seeing where the currently-running JARs are, is 
> >> not
> >> enough, if an update introduces extra JARs as a dependancy. It's necessary 
> >> to
> >> have an explicit list of all the dependencies. Unfortunately it's not 
> >> enough to
> >> simply use the Class-Path attribute of the manifest of freenet.jar, because
> >> that hard-codes the path to the other JARs, whereas we need it to be 
> >> variable
> >> for packaging purposes. So, this information can only be figured out at
> >> *package time* (for arbitrary package layouts), and the updater needs a
> >> mechanism to read this information, and probably update that as well.

To clarify, I suggest the solution to the Class-Path problem is simply not to 
include a Class-Path in the jar.
> > 
> > You are planning to have a packaged version which is able to 
> > auto-update-over-Freenet?
> > 
> > Currently class-path hardcoded freenet-ext.jar for convenience more than 
> > much else. 99% of installs use the wrapper.
> 
> Any software package should support being installed into any arbitrary layout.
> It's just good practise.

You have to tell it where everything is somehow. At a minimum that involves a 
config file. If we are using the wrapper we can probably find the jars from 
that. If we are not I guess they could be configurable but it's messy IMHO. 
See, different definitions of elegance - don't impose yours on me if you don't 
want me to impose mine on you! Alternatively we could come to a civil 
compromise.
-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/f4d5de49/attachment.pgp>

[freenet-dev] Refactoring Freenet and Library was Re: Gun.IO and Freenet

[Matthew Toseland]

On Friday 23 Mar 2012 13:23:50 Ian Clarke wrote:
> On Thu, Mar 22, 2012 at 7:00 AM, Matthew Toseland  amphibian.dyndns.org
> > wrote:
> 
> > Making stuff static is tempting but means we can't do
> > multi-nodes-in-one-VM tests
> 
> Have we ever actually done that?  It seems like we're always making
> decisions to accomodate rare (and sometimes fictional) edge-cases.

Yes, we have tests that do this. One of them runs every day on my PC. It's also 
useful for sanity checking routing changes on occasion.
-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/50876992/attachment.pgp>

[freenet-dev] Logging in Fred

[Matthew Toseland]

s 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.
-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/1a822204/attachment.pgp>

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Friday 23 Mar 2012 11:35:44 Ximin Luo wrote:
> lol, OK.
> 
> I am just annoyed with everyone that keeps arguing "we need to implement our
> own generic X framework because of minor issue Y whose importance I am
> over-inflating, even though countless other projects with similar requirements
> get around these adequately".

So does that mean you think this will not have an unacceptable performance 
impact?
-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/18a90512/attachment.pgp>

[freenet-dev] Logging in Fred

[Marco Schulze]

Sure. Since the class name lookups will only be used for debugging, they 
can be as generic as necessary, as long it doesn't add any requirements 
to users. Match-on-load and match-on-demand are both fine.

On 23-03-2012 13:19, Matthew Toseland wrote:
> On Friday 23 Mar 2012 16:00:15 Marco Schulze wrote:
>> Yes, and yes.
>>
>> On 23-03-2012 12:43, Matthew Toseland wrote:
>>> On Friday 23 Mar 2012 15:29:44 you wrote:
 Right now, the map is only used to list class thresholds which are
 different from the global threshold, which means it is empty 99% of the
 time. This is the simplest solution, but it also means that the
 possibility of lock contention is way higher. However, unless this
 proves to be very bad in a real run, I'll stick with it.
>>> Sounds like you need to use a volatile.
>>>
>>> Also your design implies that the log level details will be changed to not 
>>> support wildcards/prefixes?
> Is there any way to avoid this? Prefixes are really handy in some debugging 
> situations. Possibly we could hook into the classloader and apply the 
> wildcards on loading?
>
 On 23-03-2012 10:39, Matthew Toseland wrote:
> On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:
>> I already have all but log rotation and async ready, and haven't yet
>> found a single benchmark supporting the use of a branch as the
>> performance holy grail. For example (outputting to /dev/null):
>>
>> public static void main (String[] args) {
>> for (int i = 0; i<100; i++) {
>> Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
>> out, ' ');
>> Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
>> out, ' ');
>> }
>> }
>>
>> Every call means, minimally, varargs boxing, another call (since fatal()
>> and trace() are simple convenience methods) and an isLoggable() check
>> composed by a ConcurrentHashMap lookup against the class name and
>> (possibly) a synchronized read on the global threshold. trace() is
>> filtered but fatal() is not.
> Don't do a synchronized read on the global threshold. Don't do 
> synchronized anything. Just recompute all the classes when the thresholds 
> change.
>
> However, you still haven't told me how you're going to ensure all classes 
> are paged in when you do set all the thresholds in the map?
>> This snipped ran in an average 6.482 seconds. If the call to trace() is
>> commented out (thus removing the filtering overhead), the average falls
>> to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
>> 1:35.880, respectively. Over a million calls, checking costs only a few
>> milliseconds.
>>
>> To be sure, this is a fairly simple example: it all runs on a single
>> thread, the hash table is empty and the pressure on the GC is low.
>> Still, differences are very small. Plus, there's no overhead due to a
>> dedicated logging thread.
>>
>> On 22-03-2012 18: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">> >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"
>>>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 basical

[freenet-dev] Logging in Fred

[Marco Schulze]

Yes, and yes.

On 23-03-2012 12:43, Matthew Toseland wrote:
> On Friday 23 Mar 2012 15:29:44 you wrote:
>> Right now, the map is only used to list class thresholds which are
>> different from the global threshold, which means it is empty 99% of the
>> time. This is the simplest solution, but it also means that the
>> possibility of lock contention is way higher. However, unless this
>> proves to be very bad in a real run, I'll stick with it.
> Sounds like you need to use a volatile.
>
> Also your design implies that the log level details will be changed to not 
> support wildcards/prefixes?
>> On 23-03-2012 10:39, Matthew Toseland wrote:
>>> On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:
 I already have all but log rotation and async ready, and haven't yet
 found a single benchmark supporting the use of a branch as the
 performance holy grail. For example (outputting to /dev/null):

 public static void main (String[] args) {
for (int i = 0; i<   100; i++) {
Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
 out, ' ');
Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
 out, ' ');
}
 }

 Every call means, minimally, varargs boxing, another call (since fatal()
 and trace() are simple convenience methods) and an isLoggable() check
 composed by a ConcurrentHashMap lookup against the class name and
 (possibly) a synchronized read on the global threshold. trace() is
 filtered but fatal() is not.
>>> Don't do a synchronized read on the global threshold. Don't do synchronized 
>>> anything. Just recompute all the classes when the thresholds change.
>>>
>>> However, you still haven't told me how you're going to ensure all classes 
>>> are paged in when you do set all the thresholds in the map?
 This snipped ran in an average 6.482 seconds. If the call to trace() is
 commented out (thus removing the filtering overhead), the average falls
 to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
 1:35.880, respectively. Over a million calls, checking costs only a few
 milliseconds.

 To be sure, this is a fairly simple example: it all runs on a single
 thread, the hash table is empty and the pressure on the GC is low.
 Still, differences are very small. Plus, there's no overhead due to a
 dedicated logging thread.

 On 22-03-2012 18: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" >   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"
>   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{M

[freenet-dev] Logging in Fred

[Marco Schulze]

Right now, the map is only used to list class thresholds which are 
different from the global threshold, which means it is empty 99% of the 
time. This is the simplest solution, but it also means that the 
possibility of lock contention is way higher. However, unless this 
proves to be very bad in a real run, I'll stick with it.

On 23-03-2012 10:39, Matthew Toseland wrote:
> On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:
>> I already have all but log rotation and async ready, and haven't yet
>> found a single benchmark supporting the use of a branch as the
>> performance holy grail. For example (outputting to /dev/null):
>>
>> public static void main (String[] args) {
>>   for (int i = 0; i<  100; i++) {
>>   Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
>> out, ' ');
>>   Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
>> out, ' ');
>>   }
>> }
>>
>> Every call means, minimally, varargs boxing, another call (since fatal()
>> and trace() are simple convenience methods) and an isLoggable() check
>> composed by a ConcurrentHashMap lookup against the class name and
>> (possibly) a synchronized read on the global threshold. trace() is
>> filtered but fatal() is not.
> Don't do a synchronized read on the global threshold. Don't do synchronized 
> anything. Just recompute all the classes when the thresholds change.
>
> However, you still haven't told me how you're going to ensure all classes are 
> paged in when you do set all the thresholds in the map?
>> This snipped ran in an average 6.482 seconds. If the call to trace() is
>> commented out (thus removing the filtering overhead), the average falls
>> to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
>> 1:35.880, respectively. Over a million calls, checking costs only a few
>> milliseconds.
>>
>> To be sure, this is a fairly simple example: it all runs on a single
>> thread, the hash table is empty and the pressure on the GC is low.
>> Still, differences are very small. Plus, there's no overhead due to a
>> dedicated logging thread.
>>
>> On 22-03-2012 18: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">> >  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"
>>>  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).
>>>   

[freenet-dev] Logging in Fred

[Ximin Luo]

g* == 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

-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 900 bytes
Desc: OpenPGP digital signature
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/01dd04a7/attachment.pgp>

Re: [freenet-dev] Logging in Fred

[Marco Schulze]

Sure. Since the class name lookups will only be used for debugging, they 
can be as generic as necessary, as long it doesn't add any requirements 
to users. Match-on-load and match-on-demand are both fine.


On 23-03-2012 13:19, Matthew Toseland wrote:

On Friday 23 Mar 2012 16:00:15 Marco Schulze wrote:

Yes, and yes.

On 23-03-2012 12:43, Matthew Toseland wrote:

On Friday 23 Mar 2012 15:29:44 you wrote:

Right now, the map is only used to list class thresholds which are
different from the global threshold, which means it is empty 99% of the
time. This is the simplest solution, but it also means that the
possibility of lock contention is way higher. However, unless this
proves to be very bad in a real run, I'll stick with it.

Sounds like you need to use a volatile.

Also your design implies that the log level details will be changed to not 
support wildcards/prefixes?

Is there any way to avoid this? Prefixes are really handy in some debugging 
situations. Possibly we could hook into the classloader and apply the wildcards 
on loading?


On 23-03-2012 10:39, Matthew Toseland wrote:

On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:

I already have all but log rotation and async ready, and haven't yet
found a single benchmark supporting the use of a branch as the
performance holy grail. For example (outputting to /dev/null):

public static void main (String[] args) {
for (int i = 0; i<100; i++) {
Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
out, ' ');
Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
out, ' ');
}
}

Every call means, minimally, varargs boxing, another call (since fatal()
and trace() are simple convenience methods) and an isLoggable() check
composed by a ConcurrentHashMap lookup against the class name and
(possibly) a synchronized read on the global threshold. trace() is
filtered but fatal() is not.

Don't do a synchronized read on the global threshold. Don't do synchronized 
anything. Just recompute all the classes when the thresholds change.

However, you still haven't told me how you're going to ensure all classes are 
paged in when you do set all the thresholds in the map?

This snipped ran in an average 6.482 seconds. If the call to trace() is
commented out (thus removing the filtering overhead), the average falls
to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
1:35.880, respectively. Over a million calls, checking costs only a few
milliseconds.

To be sure, this is a fairly simple example: it all runs on a single
thread, the hash table is empty and the pressure on the GC is low.
Still, differences are very small. Plus, there's no overhead due to a
dedicated logging thread.

On 22-03-2012 18: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"mailto:infini...@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"
   mailto:marco.c.schu...@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
   

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Friday 23 Mar 2012 16:00:15 Marco Schulze wrote:
> Yes, and yes.
> 
> On 23-03-2012 12:43, Matthew Toseland wrote:
> > On Friday 23 Mar 2012 15:29:44 you wrote:
> >> Right now, the map is only used to list class thresholds which are
> >> different from the global threshold, which means it is empty 99% of the
> >> time. This is the simplest solution, but it also means that the
> >> possibility of lock contention is way higher. However, unless this
> >> proves to be very bad in a real run, I'll stick with it.
> > Sounds like you need to use a volatile.
> >
> > Also your design implies that the log level details will be changed to not 
> > support wildcards/prefixes?

Is there any way to avoid this? Prefixes are really handy in some debugging 
situations. Possibly we could hook into the classloader and apply the wildcards 
on loading?

> >> On 23-03-2012 10:39, Matthew Toseland wrote:
> >>> On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:
>  I already have all but log rotation and async ready, and haven't yet
>  found a single benchmark supporting the use of a branch as the
>  performance holy grail. For example (outputting to /dev/null):
> 
>  public static void main (String[] args) {
> for (int i = 0; i<   100; i++) {
> Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
>  out, ' ');
> Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
>  out, ' ');
> }
>  }
> 
>  Every call means, minimally, varargs boxing, another call (since fatal()
>  and trace() are simple convenience methods) and an isLoggable() check
>  composed by a ConcurrentHashMap lookup against the class name and
>  (possibly) a synchronized read on the global threshold. trace() is
>  filtered but fatal() is not.
> >>> Don't do a synchronized read on the global threshold. Don't do 
> >>> synchronized anything. Just recompute all the classes when the thresholds 
> >>> change.
> >>>
> >>> However, you still haven't told me how you're going to ensure all classes 
> >>> are paged in when you do set all the thresholds in the map?
>  This snipped ran in an average 6.482 seconds. If the call to trace() is
>  commented out (thus removing the filtering overhead), the average falls
>  to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
>  1:35.880, respectively. Over a million calls, checking costs only a few
>  milliseconds.
> 
>  To be sure, this is a fairly simple example: it all runs on a single
>  thread, the hash table is empty and the pressure on the GC is low.
>  Still, differences are very small. Plus, there's no overhead due to a
>  dedicated logging thread.
> 
>  On 22-03-2012 18: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" > >   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"
> >   mailto:marco.c.schu...@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
> >

[freenet-dev] Logging in Fred

[Nicolas Hernandez]

On Fri, Mar 23, 2012 at 8:58 AM, David ?Bombe? Roden <
bombe at pterodactylus.net> wrote:

> Yes, kids, both your penisses are incredibly long. Now shut up and let the
> grown-ups do some refactoring.
>
>
> Greetings,
>
>David
>
>
Thanks daddy !

Nicolas
-- next part --
An HTML attachment was scrubbed...
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/05a86057/attachment.html>

Re: [freenet-dev] Logging in Fred

[Marco Schulze]

Yes, and yes.

On 23-03-2012 12:43, Matthew Toseland wrote:

On Friday 23 Mar 2012 15:29:44 you wrote:

Right now, the map is only used to list class thresholds which are
different from the global threshold, which means it is empty 99% of the
time. This is the simplest solution, but it also means that the
possibility of lock contention is way higher. However, unless this
proves to be very bad in a real run, I'll stick with it.

Sounds like you need to use a volatile.

Also your design implies that the log level details will be changed to not 
support wildcards/prefixes?

On 23-03-2012 10:39, Matthew Toseland wrote:

On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:

I already have all but log rotation and async ready, and haven't yet
found a single benchmark supporting the use of a branch as the
performance holy grail. For example (outputting to /dev/null):

public static void main (String[] args) {
   for (int i = 0; i<   100; i++) {
   Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
out, ' ');
   Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
out, ' ');
   }
}

Every call means, minimally, varargs boxing, another call (since fatal()
and trace() are simple convenience methods) and an isLoggable() check
composed by a ConcurrentHashMap lookup against the class name and
(possibly) a synchronized read on the global threshold. trace() is
filtered but fatal() is not.

Don't do a synchronized read on the global threshold. Don't do synchronized 
anything. Just recompute all the classes when the thresholds change.

However, you still haven't told me how you're going to ensure all classes are 
paged in when you do set all the thresholds in the map?

This snipped ran in an average 6.482 seconds. If the call to trace() is
commented out (thus removing the filtering overhead), the average falls
to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
1:35.880, respectively. Over a million calls, checking costs only a few
milliseconds.

To be sure, this is a fairly simple example: it all runs on a single
thread, the hash table is empty and the pressure on the GC is low.
Still, differences are very small. Plus, there's no overhead due to a
dedicated logging thread.

On 22-03-2012 18: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"mailto:infini...@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"
  mailto:marco.c.schu...@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_ libr

[freenet-dev] Logging in Fred

[David ‘Bombe’ Roden]

Yes, kids, both your penisses are incredibly long. Now shut up and let the 
grown-ups do some refactoring.


Greetings,

David

On 23.03.2012, at 04:47, Ximin Luo 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 > > 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" >
>>> >> 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" >
>>>>> gmail.com>>
 > >>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:
>

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Friday 23 Mar 2012 15:29:44 you wrote:
> Right now, the map is only used to list class thresholds which are 
> different from the global threshold, which means it is empty 99% of the 
> time. This is the simplest solution, but it also means that the 
> possibility of lock contention is way higher. However, unless this 
> proves to be very bad in a real run, I'll stick with it.

Sounds like you need to use a volatile.

Also your design implies that the log level details will be changed to not 
support wildcards/prefixes?
> 
> On 23-03-2012 10:39, Matthew Toseland wrote:
> > On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:
> >> I already have all but log rotation and async ready, and haven't yet
> >> found a single benchmark supporting the use of a branch as the
> >> performance holy grail. For example (outputting to /dev/null):
> >>
> >> public static void main (String[] args) {
> >>   for (int i = 0; i<  100; i++) {
> >>   Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
> >> out, ' ');
> >>   Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
> >> out, ' ');
> >>   }
> >> }
> >>
> >> Every call means, minimally, varargs boxing, another call (since fatal()
> >> and trace() are simple convenience methods) and an isLoggable() check
> >> composed by a ConcurrentHashMap lookup against the class name and
> >> (possibly) a synchronized read on the global threshold. trace() is
> >> filtered but fatal() is not.
> > Don't do a synchronized read on the global threshold. Don't do synchronized 
> > anything. Just recompute all the classes when the thresholds change.
> >
> > However, you still haven't told me how you're going to ensure all classes 
> > are paged in when you do set all the thresholds in the map?
> >> This snipped ran in an average 6.482 seconds. If the call to trace() is
> >> commented out (thus removing the filtering overhead), the average falls
> >> to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
> >> 1:35.880, respectively. Over a million calls, checking costs only a few
> >> milliseconds.
> >>
> >> To be sure, this is a fairly simple example: it all runs on a single
> >> thread, the hash table is empty and the pressure on the GC is low.
> >> Still, differences are very small. Plus, there's no overhead due to a
> >> dedicated logging thread.
> >>
> >> On 22-03-2012 18: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" >>> >  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"
> >>>  mailto:marco.c.schu...@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
> >>> 

Re: [freenet-dev] Logging in Fred

[Marco Schulze]

Right now, the map is only used to list class thresholds which are 
different from the global threshold, which means it is empty 99% of the 
time. This is the simplest solution, but it also means that the 
possibility of lock contention is way higher. However, unless this 
proves to be very bad in a real run, I'll stick with it.


On 23-03-2012 10:39, Matthew Toseland wrote:

On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:

I already have all but log rotation and async ready, and haven't yet
found a single benchmark supporting the use of a branch as the
performance holy grail. For example (outputting to /dev/null):

public static void main (String[] args) {
  for (int i = 0; i<  100; i++) {
  Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n',
out, ' ');
  Log.trace (Log.class, Log.class, "akd\n\n", i, '\n',
out, ' ');
  }
}

Every call means, minimally, varargs boxing, another call (since fatal()
and trace() are simple convenience methods) and an isLoggable() check
composed by a ConcurrentHashMap lookup against the class name and
(possibly) a synchronized read on the global threshold. trace() is
filtered but fatal() is not.

Don't do a synchronized read on the global threshold. Don't do synchronized 
anything. Just recompute all the classes when the thresholds change.

However, you still haven't told me how you're going to ensure all classes are 
paged in when you do set all the thresholds in the map?

This snipped ran in an average 6.482 seconds. If the call to trace() is
commented out (thus removing the filtering overhead), the average falls
to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and
1:35.880, respectively. Over a million calls, checking costs only a few
milliseconds.

To be sure, this is a fairly simple example: it all runs on a single
thread, the hash table is empty and the pressure on the GC is low.
Still, differences are very small. Plus, there's no overhead due to a
dedicated logging thread.

On 22-03-2012 18: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"mailto:infini...@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"
 mailto:marco.c.schu...@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 a

[freenet-dev] Refactoring Freenet and Library was Re: Gun.IO and Freenet

[Ian Clarke]

On Thu, Mar 22, 2012 at 7:00 AM, Matthew Toseland  wrote:

> Making stuff static is tempting but means we can't do
> multi-nodes-in-one-VM tests


Have we ever actually done that?  It seems like we're always making
decisions to accomodate rare (and sometimes fictional) edge-cases.

Ian.

-- 
Ian Clarke
Personal blog: http://blog.locut.us/
-- next part --
An HTML attachment was scrubbed...
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/968304fb/attachment.html>

[freenet-dev] Logging in Fred

[Marco Schulze]

No one is benchmarking JRE's JIT. If you look closer, there are figures 
with the average runtime without JIT, exactly to avoid overspecialization.

With JIT, there is a reduction of 0.02% in runtime. Without JIT, this 
becomes 0.06%. Negligible to all but the few people who do everything in 
assembly.

I am more worried with possible lock contention.

On 22-03-2012 23:30, Zlatin Balevsky wrote:
> The example you provide is fast because it does not do any object
> allocation.  Please don't take my word for it - download (or better
> yet, build one yourself) a "fastdebug" build from openjdk.org and look
> at the opto-assembly that gets generated when you pass the
> "-XX:+PrintOptoAssembly" switch.
>
> Benchmarking JIT's is a fascinating topic but beyond the scope of this
> list.  Furthermore, anything I say applies only to the Hotspot JVM.
>
> On Thu, Mar 22, 2012 at 8:18 PM, Marco Schulze
>   wrote:
>> I already have all but log rotation and async ready, and haven't yet found a 
>> single benchmark supporting the use of a branch as the performance holy 
>> grail. For example (outputting to /dev/null):
>>
>> public static void main (String[] args) {
>>  for (int i = 0; i<  100; i++) {
>>  Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n', out, ' 
>> ');
>>  Log.trace (Log.class, Log.class, "akd\n\n", i, '\n', out, ' 
>> ');
>>  }
>> }
>>
>> Every call means, minimally, varargs boxing, another call (since fatal() and 
>> trace() are simple convenience methods) and an isLoggable() check composed 
>> by a ConcurrentHashMap lookup against the class name and (possibly) a 
>> synchronized read on the global threshold. trace() is filtered but fatal() 
>> is not.
>>
>> This snipped ran in an average 6.482 seconds. If the call to trace() is 
>> commented out (thus removing the filtering overhead), the average falls to 
>> 6.366 seconds. Disabling JIT, the figures became 1:37.952 and 1:35.880, 
>> respectively. Over a million calls, checking costs only a few milliseconds.
>>
>> To be sure, this is a fairly simple example: it all runs on a single thread, 
>> the hash table is empty and the pressure on the GC is low. Still, 
>> differences are very small. Plus, there's no overhead due to a dedicated 
>> logging thread.
>>
>>
>> On 22-03-2012 18: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"  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">>> >  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
 

Re: [freenet-dev] Refactoring Freenet and Library was Re: Gun.IO and Freenet

[Matthew Toseland]

On Thursday 22 Mar 2012 20:34:53 Ximin Luo wrote:
> On 22/03/12 12:00, Matthew Toseland wrote:
> > On Wednesday 21 Mar 2012 00:30:42 Ximin Luo wrote:
> >> "Implicit dependency" means that changing some code in one area results in 
> >> a
> >> logical error in the other, that is not immediately apparent in the
> >> documentation nor any compile-time checking built into the language. 
> >> Obviously
> >> this is not necessarily a bad thing, but there is a lot of it in the config
> >> system, and elsewhere, including in how the configured values are used.
> > 
> > Okay...
> >>
> >> For example, for the longest time there was no centralised management of
> >> run-time files used by Freenet, and even now they are just a bunch of extra
> >> fields in Node.java because I had no existing structure to fit such a 
> >> system
> >> into. However, Node.java is such a fucking disorganised mess, with several
> >> hundred fields, that it's not immediately obvious to everyone that they 
> >> should
> >> be using "new File(Node.nodeDir(), fileName)" rather than "new 
> >> File(fileName)".
> >> I cleaned it up when I first wrote that part, but it looks like misuses 
> >> have
> >> slowly crept in again.
> > 
> > So your complaint is that there is no single central point to put all the 
> > folder names in? Feel free to create one.
> > 
> > Making stuff static is tempting but means we can't do multi-nodes-in-one-VM 
> > tests, although I believe classloader hacks can solve that? Is there much 
> > of a performance cost? Otherwise we can just use a global object and grab 
> > it from Node, or ClientContext.
> >>
> >> Yes, configs have EVERYTHING to do with "writing the values out". All the
> >> read/write logic is wrapped up into a ConfigCallback (which throws a
> >> InvalidConfigException) which is ONLY PASSED TO THE CONFIG SUBSYSTEM. Even
> >> ignoring the obvious intention of whoever named these classes, the target 
> >> of
> >> the read/write logic is completely detached from the logic itself.
> > 
> > ConfigCallback doesn't do any writing out. And the getters don't throw. It 
> > can only throw when a value is changed. So it's still not clear what the 
> > problem is.
> 
> Irrelevant. To repeat:
> 
> - the target of the read/write logic[1] is completely detached from the logic
> itself[2], and too strongly-coupled with the config system[3]
> - too much implicit dependency, due to the way the variables are poorly 
> managed
> 
> [1] whatever get/set acts on
> [2] ConfigCallback
> [3] via .register(), so only the config system sees it

There is some sort of sophisticated design elegance argument going on here that 
goes completely over my head, being a poor ignorant peasant.

As I said we could change it to use getters and setters via reflection, but it 
would only be marginally cleaner.
> 
> Who said anything about making stuff static? Stop making up random straw mans.
> 
> "Feel free to create one" - stop making excuses for not cleaning up your shit
> and telling someone else to do it when they complain! Node.java is a complete
> fucking mess. To make any sort of progress in having a well-structured config
> system, that needs to be cleaned out first.

I'm very happy for other people to clean it up. However for FPI purposes, I 
will only do major refactoring if 1) I am convinced the cost/benefit is 
positive or 2) Ian tells me to.
> 
> >> Your explanation about the ObjectContainer also assumes a severely stunted
> >> events framework can't support fine grained thread control. Why can't 
> >> there, in
> >> your imagination, exist SOMEWHERE, a framework that lets you mandate "only 
> >> run
> >> jobs of type J in thread T"?
> > 
> > And those jobs are called with parameters (ObjectContainer, ClientContext) 
> > ? Since we'll have to subclass it anyway, it's going to be more messy than 
> > the current solution, isn't it? Anyway DBJob/DBJobRunner is pretty simple 
> > (although it's hidden in NodeClientCore along with ClientContext 
> > initialisation which is kind of messy).
> 
> This is bullshit, there is already a "DBJobWrapper implements Runnable" which
> needs nothing extra passed in. In the general case, there are *always* ways to
> get around fiddly crap like this, and they are much simpler than WRITING YOUR
> OWN EVENTS FRAMEWORK (and logging framework and config framework etc etc etc).

What events framework? Executor and Ticker? If you're not even talking about 
DB* then what classes are we arguing about here?
> 
> > I agree we should make *Executor use the standard APIs though - while 
> > keeping the ability to change thread priorities.
> >>
> >> An events framework could handle errant plugins by setting a timeout for 
> >> all
> >> blocking jobs. If they don't complete within X time, interrupt the thread
> >> and/or kill it if it doesn't respond to the interrupt. If the plugin can't
> >> handle it, tough shit their fault. (This is how certain companies run 
> >> reliable
> >> services on a massive scale.)
> > 

Re: [freenet-dev] Refactoring Freenet and Library was Re: Gun.IO and Freenet

[Matthew Toseland]

On Friday 23 Mar 2012 13:23:50 Ian Clarke wrote:
> On Thu, Mar 22, 2012 at 7:00 AM, Matthew Toseland  > wrote:
> 
> > Making stuff static is tempting but means we can't do
> > multi-nodes-in-one-VM tests
> 
> Have we ever actually done that?  It seems like we're always making
> decisions to accomodate rare (and sometimes fictional) edge-cases.

Yes, we have tests that do this. One of them runs every day on my PC. It's also 
useful for sanity checking routing changes on occasion.


signature.asc
Description: This is a digitally signed message part.
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Friday 23 Mar 2012 00:18:02 Marco Schulze wrote:
> I already have all but log rotation and async ready, and haven't yet 
> found a single benchmark supporting the use of a branch as the 
> performance holy grail. For example (outputting to /dev/null):
> 
> public static void main (String[] args) {
>  for (int i = 0; i < 100; i++) {
>  Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n', 
> out, ' ');
>  Log.trace (Log.class, Log.class, "akd\n\n", i, '\n', 
> out, ' ');
>  }
> }
> 
> Every call means, minimally, varargs boxing, another call (since fatal() 
> and trace() are simple convenience methods) and an isLoggable() check 
> composed by a ConcurrentHashMap lookup against the class name and 
> (possibly) a synchronized read on the global threshold. trace() is 
> filtered but fatal() is not.

Don't do a synchronized read on the global threshold. Don't do synchronized 
anything. Just recompute all the classes when the thresholds change.

However, you still haven't told me how you're going to ensure all classes are 
paged in when you do set all the thresholds in the map?
> 
> This snipped ran in an average 6.482 seconds. If the call to trace() is 
> commented out (thus removing the filtering overhead), the average falls 
> to 6.366 seconds. Disabling JIT, the figures became 1:37.952 and 
> 1:35.880, respectively. Over a million calls, checking costs only a few 
> milliseconds.
> 
> To be sure, this is a fairly simple example: it all runs on a single 
> thread, the hash table is empty and the pressure on the GC is low. 
> Still, differences are very small. Plus, there's no overhead due to a 
> dedicated logging thread.
> 
> On 22-03-2012 18: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"  > > 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"
> > mailto:marco.c.schu...@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. Spe

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Friday 23 Mar 2012 11:35:44 Ximin Luo wrote:
> lol, OK.
> 
> I am just annoyed with everyone that keeps arguing "we need to implement our
> own generic X framework because of minor issue Y whose importance I am
> over-inflating, even though countless other projects with similar requirements
> get around these adequately".

So does that mean you think this will not have an unacceptable performance 
impact?


signature.asc
Description: This is a digitally signed message part.
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Refactoring Freenet and Library was Re: Gun.IO and Freenet

[Ian Clarke]

On Thu, Mar 22, 2012 at 7:00 AM, Matthew Toseland  wrote:

> Making stuff static is tempting but means we can't do
> multi-nodes-in-one-VM tests


Have we ever actually done that?  It seems like we're always making
decisions to accomodate rare (and sometimes fictional) edge-cases.

Ian.

-- 
Ian Clarke
Personal blog: http://blog.locut.us/
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

lol, OK.

I am just annoyed with everyone that keeps arguing "we need to implement our
own generic X framework because of minor issue Y whose importance I am
over-inflating, even though countless other projects with similar requirements
get around these adequately".

To anyone doing refactoring work: ignore them.

On 23/03/12 07:58, David ‘Bombe’ Roden wrote:
> Yes, kids, both your penisses are incredibly long. Now shut up and let the 
> grown-ups do some refactoring.
> 
> 
> Greetings,
> 
>   David
> 
> On 23.03.2012, at 04:47, Ximin Luo 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 >> > 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" >>
 >> 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" >>
>
> >> >>
>
>
>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'

Re: [freenet-dev] Logging in Fred

[Marco Schulze]

No one is benchmarking JRE's JIT. If you look closer, there are figures 
with the average runtime without JIT, exactly to avoid overspecialization.


With JIT, there is a reduction of 0.02% in runtime. Without JIT, this 
becomes 0.06%. Negligible to all but the few people who do everything in 
assembly.


I am more worried with possible lock contention.

On 22-03-2012 23:30, Zlatin Balevsky wrote:

The example you provide is fast because it does not do any object
allocation.  Please don't take my word for it - download (or better
yet, build one yourself) a "fastdebug" build from openjdk.org and look
at the opto-assembly that gets generated when you pass the
"-XX:+PrintOptoAssembly" switch.

Benchmarking JIT's is a fascinating topic but beyond the scope of this
list.  Furthermore, anything I say applies only to the Hotspot JVM.

On Thu, Mar 22, 2012 at 8:18 PM, Marco Schulze
  wrote:

I already have all but log rotation and async ready, and haven't yet found a 
single benchmark supporting the use of a branch as the performance holy grail. 
For example (outputting to /dev/null):

public static void main (String[] args) {
 for (int i = 0; i<  100; i++) {
 Log.fatal (Log.class, Log.class, "akd\n\n", i, '\n', out, ' ');
 Log.trace (Log.class, Log.class, "akd\n\n", i, '\n', out, ' ');
 }
}

Every call means, minimally, varargs boxing, another call (since fatal() and 
trace() are simple convenience methods) and an isLoggable() check composed by a 
ConcurrentHashMap lookup against the class name and (possibly) a synchronized 
read on the global threshold. trace() is filtered but fatal() is not.

This snipped ran in an average 6.482 seconds. If the call to trace() is 
commented out (thus removing the filtering overhead), the average falls to 
6.366 seconds. Disabling JIT, the figures became 1:37.952 and 1:35.880, 
respectively. Over a million calls, checking costs only a few milliseconds.

To be sure, this is a fairly simple example: it all runs on a single thread, 
the hash table is empty and the pressure on the GC is low. Still, differences 
are very small. Plus, there's no overhead due to a dedicated logging thread.


On 22-03-2012 18: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"  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"mailto:marco.c.schu...@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;
 

[freenet-dev] Logging in Fred

[Ximin Luo]

> > > 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

-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 900 bytes
Desc: OpenPGP digital signature
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/7e20e5e4/attachment.pgp>

Re: [freenet-dev] Logging in Fred

[Nicolas Hernandez]

On Fri, Mar 23, 2012 at 8:58 AM, David ‘Bombe’ Roden <
bo...@pterodactylus.net> wrote:

> Yes, kids, both your penisses are incredibly long. Now shut up and let the
> grown-ups do some refactoring.
>
>
> Greetings,
>
>David
>
>
Thanks daddy !

Nicolas
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Logging in Fred

[David ‘Bombe’ Roden]

Yes, kids, both your penisses are incredibly long. Now shut up and let the 
grown-ups do some refactoring.


Greetings,

David

On 23.03.2012, at 04:47, Ximin Luo 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 > > 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" >
>>> >> 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" >
>>>>
 > >>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 (p

[freenet-dev] Logging in Fred

[Ximin Luo]

#x27;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>>
> > 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>
> > 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 <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

-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 900 bytes
Desc: OpenPGP digital signature
URL: 
<https://emu.freenetproject.org/pipermail/devl/attachments/20120323/4fe16ae1/attachment.pgp>