[freenet-dev] Logging in Fred

[Matthew Toseland]

On Tuesday 03 Apr 2012 02:26:03 Zlatin Balevsky wrote:
> On Mon, Apr 2, 2012 at 6:04 PM, Matthew Toseland
>  wrote:
> > On Saturday 31 Mar 2012 04:03:10 Zlatin Balevsky wrote:
> >> >>
> >> >> In 'log.info("Random message: %s", obj.toString())' evaluating 
> >> >> 'obj.toString()' was what caused issues, not recycling it, or so I 
> >> >> believe to remember.
> >> >
> >> > You don't need to call obj.toString() before calling log() - just pass 
> >> > the object itself. Then the only overheads are:
> >> > 1) Calling the function, including passing the arguments - which 
> >> > hopefully will be optimised to be on some stack (but the code might not 
> >> > have been JITted yet).
> >> > 2) Looking up whether it needs to be logged.
> >> >
> >>
> >> 3) Autoboxing because you cannot pass a primitive if the argument is
> >> Object without creating a .  Small ranges of
> >> Char/Short/Integer/Long values are cached, anything outside those will
> >> end up creating garbage if the shouldLog predicate evaluate true even
> >> once.
> >
> > Will it still autobox them if they are on the stack, and never used?
> 
> If the isDebuggable predicate never evaluates true, then it's not a
> problem.  But if it evaluates true even once for the lifetime of the
> loaded class it will create these objects.  It's a quirk of current
> hotspot jvm which will not affect production deployments but will
> affect the developer: turning on debug logging for one class will
> cause all primitives in all log statements to be instantiated.  I had
> some sample code earlier in the thread.

It means we need separate checks in each method, rather than having them all 
wrap the same generic logger method?
-- 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: 

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Saturday 31 Mar 2012 04:03:10 Zlatin Balevsky wrote:
> >>
> >> In 'log.info("Random message: %s", obj.toString())' evaluating 
> >> 'obj.toString()' was what caused issues, not recycling it, or so I believe 
> >> to remember.
> >
> > You don't need to call obj.toString() before calling log() - just pass the 
> > object itself. Then the only overheads are:
> > 1) Calling the function, including passing the arguments - which hopefully 
> > will be optimised to be on some stack (but the code might not have been 
> > JITted yet).
> > 2) Looking up whether it needs to be logged.
> >
> 
> 3) Autoboxing because you cannot pass a primitive if the argument is
> Object without creating a .  Small ranges of
> Char/Short/Integer/Long values are cached, anything outside those will
> end up creating garbage if the shouldLog predicate evaluate true even
> once.

Will it still autobox them if they are on the stack, and never used?
> 
> ... but you could get around this problem by adding many log functions
> with different signatures that take primitives.  The burden then falls
> on the programmer to find the appropriate function at each call site.
-- 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: 

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Tuesday 03 Apr 2012 02:26:03 Zlatin Balevsky wrote:
 On Mon, Apr 2, 2012 at 6:04 PM, Matthew Toseland
 t...@amphibian.dyndns.org wrote:
  On Saturday 31 Mar 2012 04:03:10 Zlatin Balevsky wrote:
  
   In 'log.info(Random message: %s, obj.toString())' evaluating 
   'obj.toString()' was what caused issues, not recycling it, or so I 
   believe to remember.
  
   You don't need to call obj.toString() before calling log() - just pass 
   the object itself. Then the only overheads are:
   1) Calling the function, including passing the arguments - which 
   hopefully will be optimised to be on some stack (but the code might not 
   have been JITted yet).
   2) Looking up whether it needs to be logged.
  
 
  3) Autoboxing because you cannot pass a primitive if the argument is
  Object without creating a ? extends Number.  Small ranges of
  Char/Short/Integer/Long values are cached, anything outside those will
  end up creating garbage if the shouldLog predicate evaluate true even
  once.
 
  Will it still autobox them if they are on the stack, and never used?
 
 If the isDebuggable predicate never evaluates true, then it's not a
 problem.  But if it evaluates true even once for the lifetime of the
 loaded class it will create these objects.  It's a quirk of current
 hotspot jvm which will not affect production deployments but will
 affect the developer: turning on debug logging for one class will
 cause all primitives in all log statements to be instantiated.  I had
 some sample code earlier in the thread.

It means we need separate checks in each method, rather than having them all 
wrap the same generic logger method?


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

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

On Mon, Apr 2, 2012 at 6:04 PM, Matthew Toseland
 wrote:
> On Saturday 31 Mar 2012 04:03:10 Zlatin Balevsky wrote:
>> >>
>> >> In 'log.info("Random message: %s", obj.toString())' evaluating 
>> >> 'obj.toString()' was what caused issues, not recycling it, or so I 
>> >> believe to remember.
>> >
>> > You don't need to call obj.toString() before calling log() - just pass the 
>> > object itself. Then the only overheads are:
>> > 1) Calling the function, including passing the arguments - which hopefully 
>> > will be optimised to be on some stack (but the code might not have been 
>> > JITted yet).
>> > 2) Looking up whether it needs to be logged.
>> >
>>
>> 3) Autoboxing because you cannot pass a primitive if the argument is
>> Object without creating a . ?Small ranges of
>> Char/Short/Integer/Long values are cached, anything outside those will
>> end up creating garbage if the shouldLog predicate evaluate true even
>> once.
>
> Will it still autobox them if they are on the stack, and never used?

If the isDebuggable predicate never evaluates true, then it's not a
problem.  But if it evaluates true even once for the lifetime of the
loaded class it will create these objects.  It's a quirk of current
hotspot jvm which will not affect production deployments but will
affect the developer: turning on debug logging for one class will
cause all primitives in all log statements to be instantiated.  I had
some sample code earlier in the thread.

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Saturday 31 Mar 2012 04:03:10 Zlatin Balevsky wrote:
 
  In 'log.info(Random message: %s, obj.toString())' evaluating 
  'obj.toString()' was what caused issues, not recycling it, or so I believe 
  to remember.
 
  You don't need to call obj.toString() before calling log() - just pass the 
  object itself. Then the only overheads are:
  1) Calling the function, including passing the arguments - which hopefully 
  will be optimised to be on some stack (but the code might not have been 
  JITted yet).
  2) Looking up whether it needs to be logged.
 
 
 3) Autoboxing because you cannot pass a primitive if the argument is
 Object without creating a ? extends Number.  Small ranges of
 Char/Short/Integer/Long values are cached, anything outside those will
 end up creating garbage if the shouldLog predicate evaluate true even
 once.

Will it still autobox them if they are on the stack, and never used?
 
 ... but you could get around this problem by adding many log functions
 with different signatures that take primitives.  The burden then falls
 on the programmer to find the appropriate function at each call site.


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

[Zlatin Balevsky]

On Mon, Apr 2, 2012 at 6:04 PM, Matthew Toseland
t...@amphibian.dyndns.org wrote:
 On Saturday 31 Mar 2012 04:03:10 Zlatin Balevsky wrote:
 
  In 'log.info(Random message: %s, obj.toString())' evaluating 
  'obj.toString()' was what caused issues, not recycling it, or so I 
  believe to remember.
 
  You don't need to call obj.toString() before calling log() - just pass the 
  object itself. Then the only overheads are:
  1) Calling the function, including passing the arguments - which hopefully 
  will be optimised to be on some stack (but the code might not have been 
  JITted yet).
  2) Looking up whether it needs to be logged.
 

 3) Autoboxing because you cannot pass a primitive if the argument is
 Object without creating a ? extends Number.  Small ranges of
 Char/Short/Integer/Long values are cached, anything outside those will
 end up creating garbage if the shouldLog predicate evaluate true even
 once.

 Will it still autobox them if they are on the stack, and never used?

If the isDebuggable predicate never evaluates true, then it's not a
problem.  But if it evaluates true even once for the lifetime of the
loaded class it will create these objects.  It's a quirk of current
hotspot jvm which will not affect production deployments but will
affect the developer: turning on debug logging for one class will
cause all primitives in all log statements to be instantiated.  I had
some sample code earlier in the thread.
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

>>
>> In 'log.info("Random message: %s", obj.toString())' evaluating 
>> 'obj.toString()' was what caused issues, not recycling it, or so I believe 
>> to remember.
>
> You don't need to call obj.toString() before calling log() - just pass the 
> object itself. Then the only overheads are:
> 1) Calling the function, including passing the arguments - which hopefully 
> will be optimised to be on some stack (but the code might not have been 
> JITted yet).
> 2) Looking up whether it needs to be logged.
>

3) Autoboxing because you cannot pass a primitive if the argument is
Object without creating a .  Small ranges of
Char/Short/Integer/Long values are cached, anything outside those will
end up creating garbage if the shouldLog predicate evaluate true even
once.

... but you could get around this problem by adding many log functions
with different signatures that take primitives.  The burden then falls
on the programmer to find the appropriate function at each call site.

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Wednesday 28 Mar 2012 19:56:19 postwall-freenet at yahoo.de wrote:
> If I remember right then the main issue with debug logging wasn't GC but that 
> generating some of the log string arguments in freenet was simply very 
> resource intensive in itself. 

I'm not sure. I do remember it greatly increased CPU usage, but I also remember 
spending a long period chasing memory churn issues.

> So if Java isn't somehow intelligent enough to detect that argument x isn't 
> needed since it won't be used in the end anyway and thus doesn't evaluate it 
> before passing the value, then removing the current logic will cause higher 
> ressource usage once again.
> 
> In 'log.info("Random message: %s", obj.toString())' evaluating 
> 'obj.toString()' was what caused issues, not recycling it, or so I believe to 
> remember.

You don't need to call obj.toString() before calling log() - just pass the 
object itself. Then the only overheads are:
1) Calling the function, including passing the arguments - which hopefully will 
be optimised to be on some stack (but the code might not have been JITted yet).
2) Looking up whether it needs to be logged.

This means performance may be acceptable, though it'd need to be tested.
> 
> The main things causing GC issues which I remember were not reusing threads 
> and spawning a few new objects per received and send packet, not the log 
> stuff, that probably just tipped things over the edge when GC was already 
> done heavily because of the former.
> 
> Speeking out of memory as a non Java-dev here, so ignore if applicable. :P
-- 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: 

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Wednesday 28 Mar 2012 19:56:19 postwall-free...@yahoo.de wrote:
 If I remember right then the main issue with debug logging wasn't GC but that 
 generating some of the log string arguments in freenet was simply very 
 resource intensive in itself. 

I'm not sure. I do remember it greatly increased CPU usage, but I also remember 
spending a long period chasing memory churn issues.

 So if Java isn't somehow intelligent enough to detect that argument x isn't 
 needed since it won't be used in the end anyway and thus doesn't evaluate it 
 before passing the value, then removing the current logic will cause higher 
 ressource usage once again.
 
 In 'log.info(Random message: %s, obj.toString())' evaluating 
 'obj.toString()' was what caused issues, not recycling it, or so I believe to 
 remember.

You don't need to call obj.toString() before calling log() - just pass the 
object itself. Then the only overheads are:
1) Calling the function, including passing the arguments - which hopefully will 
be optimised to be on some stack (but the code might not have been JITted yet).
2) Looking up whether it needs to be logged.

This means performance may be acceptable, though it'd need to be tested.
 
 The main things causing GC issues which I remember were not reusing threads 
 and spawning a few new objects per received and send packet, not the log 
 stuff, that probably just tipped things over the edge when GC was already 
 done heavily because of the former.
 
 Speeking out of memory as a non Java-dev here, so ignore if applicable. :P


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

[Zlatin Balevsky]

 In 'log.info(Random message: %s, obj.toString())' evaluating 
 'obj.toString()' was what caused issues, not recycling it, or so I believe 
 to remember.

 You don't need to call obj.toString() before calling log() - just pass the 
 object itself. Then the only overheads are:
 1) Calling the function, including passing the arguments - which hopefully 
 will be optimised to be on some stack (but the code might not have been 
 JITted yet).
 2) Looking up whether it needs to be logged.


3) Autoboxing because you cannot pass a primitive if the argument is
Object without creating a ? extends Number.  Small ranges of
Char/Short/Integer/Long values are cached, anything outside those will
end up creating garbage if the shouldLog predicate evaluate true even
once.

... but you could get around this problem by adding many log functions
with different signatures that take primitives.  The burden then falls
on the programmer to find the appropriate function at each call site.
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

[freenet-dev] Logging in Fred

[postwall-free...@yahoo.de]

If I remember right then the main issue with debug logging wasn't GC but that 
generating some of the log string arguments in freenet was simply very resource 
intensive in itself. So if Java isn't somehow intelligent enough to detect that 
argument x isn't needed since it won't be used in the end anyway and thus 
doesn't evaluate it before passing the value, then removing the current logic 
will cause higher ressource usage once again.

In 'log.info("Random message: %s", obj.toString())' evaluating 'obj.toString()' 
was what caused issues, not recycling it, or so I believe to remember.


The main things causing GC issues which I remember were not reusing threads and 
spawning a few new objects per received and send packet, not the log stuff, 
that probably just tipped things over the edge when GC was already done heavily 
because of the former.


Speeking out of memory as a non Java-dev here, so ignore if applicable. :P




 Von: Ximin Luo 
An: devl at freenetproject.org 
Gesendet: 4:33 Samstag, 24.M?rz 2012
Betreff: Re: [freenet-dev] Logging in Fred

I see.

Actually we didn't even need the side effects thing - I did notice that your
example stopped doing GC when setting "shouldLog = false" always, so I tried to
introduce your "if (shouldLog) { shouldLog = false; }" into my example, but was
still unable to reproduce GC. Then changing

- System.out.println("don't optimise me out");
+ System.out.println(format + args);

worked to re-introduce GC.

Well, that sucks. I guess the escape analyzer isn't sophisticated enough to see
that ar2.toString() does not cause ar2 to escape - and removing that from your
log() method does result in no GC.

I still think it's negligible though :p - for my test, I'm seeing only ~8ms
lost to GC after 20 million calls, and this appears to not change by much even
if I increase the number of arguments (and objects created) to log_info.

On 24/03/12 03:02, Zlatin Balevsky wrote:
> Your test has nothing to do with stack allocation because you never
> use the objects that you pass to the log_info method so JIT removes
> them.? Apply the following patch and see yourself create garbage in
> both testWith and testWithout.
> 
> --- Test2.java??? 2012-03-23 23:01:05.540475497 -0400
> +++ Test.java??? 2012-03-23 23:01:47.304477562 -0400
> @@ -6,8 +6,11 @@
>? ? final Object existing = new Object();
>? ? Object tmp = null;
> 
> +? long sideEffect;
>? ? public void log_info(String format, Object ... args) {
>? ? ? if (log_level) {
> +? ? ? for (Object o : args)
> +??? sideEffect += o.hashCode();
>? ? ? ? System.out.println("don't optimise me out");
>? ? ? }
>? ? }
> @@ -88,11 +91,8 @@
>? ? ? printSummary("with alloc", res[0], "w/o alloc", res[1]);
>? ? ? printSummary("with alloc", res[2], "w/o alloc", res[3]);
>? ? ? printSummary("with alloc", res[4], "w/o alloc", res[5]);
> -? ? System.out.println(" with stack allocation and \"real use case\"");
> -? ? res = testWithOtherCode(z);
> -? ? printSummary("log only", res[0], "log+work", res[1]);
> -? ? printSummary("log only", res[2], "log+work", res[3]);
> -? ? printSummary("log only", res[4], "log+work", res[5]);
> +
> +? ? System.out.println(sideEffect);
>? ? }
> 
>? ? public static void main(String[] args) {
> 
> 
> On Fri, Mar 23, 2012 at 10:48 PM, Ximin Luo  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 
>&

Re: [freenet-dev] Logging in Fred

[postwall-free...@yahoo.de]

If I remember right then the main issue with debug logging wasn't GC but that 
generating some of the log string arguments in freenet was simply very resource 
intensive in itself. So if Java isn't somehow intelligent enough to detect that 
argument x isn't needed since it won't be used in the end anyway and thus 
doesn't evaluate it before passing the value, then removing the current logic 
will cause higher ressource usage once again.

In 'log.info(Random message: %s, obj.toString())' evaluating 'obj.toString()' 
was what caused issues, not recycling it, or so I believe to remember.


The main things causing GC issues which I remember were not reusing threads and 
spawning a few new objects per received and send packet, not the log stuff, 
that probably just tipped things over the edge when GC was already done heavily 
because of the former.


Speeking out of memory as a non Java-dev here, so ignore if applicable. :P




 Von: Ximin Luo infini...@gmx.com
An: devl@freenetproject.org 
Gesendet: 4:33 Samstag, 24.März 2012
Betreff: Re: [freenet-dev] Logging in Fred
 
I see.

Actually we didn't even need the side effects thing - I did notice that your
example stopped doing GC when setting shouldLog = false always, so I tried to
introduce your if (shouldLog) { shouldLog = false; } into my example, but was
still unable to reproduce GC. Then changing

- System.out.println(don't optimise me out);
+ System.out.println(format + args);

worked to re-introduce GC.

Well, that sucks. I guess the escape analyzer isn't sophisticated enough to see
that ar2.toString() does not cause ar2 to escape - and removing that from your
log() method does result in no GC.

I still think it's negligible though :p - for my test, I'm seeing only ~8ms
lost to GC after 20 million calls, and this appears to not change by much even
if I increase the number of arguments (and objects created) to log_info.

On 24/03/12 03:02, Zlatin Balevsky wrote:
 Your test has nothing to do with stack allocation because you never
 use the objects that you pass to the log_info method so JIT removes
 them.  Apply the following patch and see yourself create garbage in
 both testWith and testWithout.
 
 --- Test2.java    2012-03-23 23:01:05.540475497 -0400
 +++ Test.java    2012-03-23 23:01:47.304477562 -0400
 @@ -6,8 +6,11 @@
    final Object existing = new Object();
    Object tmp = null;
 
 +  long sideEffect;
    public void log_info(String format, Object ... args) {
      if (log_level) {
 +      for (Object o : args)
 +    sideEffect += o.hashCode();
        System.out.println(don't optimise me out);
      }
    }
 @@ -88,11 +91,8 @@
      printSummary(with alloc, res[0], w/o alloc, res[1]);
      printSummary(with alloc, res[2], w/o alloc, res[3]);
      printSummary(with alloc, res[4], w/o alloc, res[5]);
 -    System.out.println( with stack allocation and \real use case\);
 -    res = testWithOtherCode(z);
 -    printSummary(log only, res[0], log+work, res[1]);
 -    printSummary(log only, res[2], log+work, res[3]);
 -    printSummary(log only, res[4], log+work, res[5]);
 +
 +    System.out.println(sideEffect);
    }
 
    public static void main(String[] args) {
 
 
 On Fri, Mar 23, 2012 at 10:48 PM, Ximin Luo infini...@gmx.com wrote:
 On 24/03/12 02:44, Zlatin Balevsky wrote:
 Wrong.  Extracting the log statement into its own method and calling
 that method inside the while loop still creates garbage.  Stack frames
 are different.


 How do you explain the results obtained from running my test code, then? Turn
 on -verbose:gc. testWithStackAllocation results in no GC,
 testWithoutStackAllocation results in lots of GC.

 Read again exactly how Escape Analysis works.  The objects it prevents
 from creating do not appear in heap histograms.  Take a jmap -histo
 pid and you will see a huge number of java.lang.Integer objects in
 the heap, not on the stack.


 If you're still talking about your example, this is exactly consistent with 
 my
 explanation, i.e. that escape analysis is NOT occurring, properly anyway.

 The difference in run times of your example could be due to many
 things.  How many iterations did you run?  It may be still in
 interpreted mode.  Enable -XX:+PrintCompilation and discard any
 results until JIT stops printing.

 Done that, JIT stops printing after the 3rd iteration and results are the 
 same
 thereafter.

 --
 GPG: 4096R/5FBBDBCE
 https://github.com/infinity0
 https://bitbucket.org/infinity0
 https://launchpad.net/~infinity0


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


-- 
GPG: 4096R/5FBBDBCE
https://github.com/infinity0
https://bitbucket.org/infinity0
https://launchpad.net/~infinity0

[freenet-dev] Logging in Fred

[Marco Schulze]

On 24-03-2012 09:26, Marco Schulze wrote:
> I finally got freenet.jar compiled and profiled. First, size-related 
> numbers:
>
> Number of lines removed: ~5000
> freenet.jar shrink: ~200k
>
> And profiling data (see below for details):
>
> freenet.support.FileLoggerHook$WriterThread.run: 8,35% (3)
Oops. Most of the method's time is 'spent' inside Object.wait(). As far 
as I can gather with my limited Java profiling experience, this figure 
is actually between 2% and 3%. I've attached the output of another, 3 
minute run (HPROF w/ cpu=times).

>
> freenet.support.Log.isLoggable: 0.09% (17)
> freenet.support.Log.write: 0,03% (26)
>
> These numbers come from a sanity check run, and _do not_ represent 
> what would happen in a real test run. Both were run in an empty 
> directory for a few minutes and then shut down. Of special note is the 
> lack of the seed nodes list, leaving out, I'd guess, 80% of fred code. 
> Also, lazy evaluation isn't used, so Log.write()'s share can be 
> expected to rise.
>
> There are still a few things to do before I can say whether predicates 
> are indispensable or not.
>
> On 18-03-2012 20:40, Marco Schulze wrote:
>> One thing has been bothering me: those 'if (logMINOR) 
>> Logger.minor(...', and the mess that logging is inside fred. I've 
>> written a very simple replacement for Logger + associated classes 
>> with the following changes:
>>
>> - Log level (renamed to severity) filtering is done by Logging.log();
>> - Specific writer classes are replaced by a simple OutputStream, 
>> which defaults to System.err. Formatting is also unified;
>> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG 
>> and TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
>> - No logging method accepts an Object parameter - hashCode() is not 
>> exactly useful.
>>
>> Additionally, log rotation will be moved outside (possibly inside Node).
>>
>> Currently, the log format is '\t'.
-- next part --
CPU TIME (ms) BEGIN (total = 1676345) Sun Mar 25 13:54:57 2012
rank   self  accum   count trace method
   1 10,74% 10,74%   3 306148 
freenet.support.PooledExecutor$MyThread.realRun
   2 10,72% 21,46%   1 306331 
freenet.support.FileLoggerHook$WriterThread.run
   3 10,56% 32,02% 354 303612 freenet.io.NetworkInterface.accept
   4 10,03% 42,05%1680 305239 freenet.node.PacketSender.realRun
   5 10,00% 52,05%4346 305240 freenet.support.PrioritizedTicker.realRun
   6  9,94% 61,99%   1 306286 
java.net.AbstractPlainDatagramSocketImpl.receive
   7  9,63% 71,62%  90 305699 freenet.client.async.DatastoreChecker.realRun
   8  9,54% 81,16%  16 306056 freenet.node.DNSRequester.realRun
   9  7,72% 88,88%   3 303235 java.lang.Object.wait
  10  7,72% 96,60%2330 303243 java.lang.ref.ReferenceQueue.remove
  11  0,84% 97,43%   1 305391 
org.tanukisoftware.wrapper.WrapperManager$4.run
  12  0,31% 97,74%  36 304762 freenet.client.async.USKManager.subscribe
  13  0,25% 97,99%  19 304873 freenet.client.async.USKFetcher.schedule
  14  0,18% 98,17% 1846080 303770 sun.security.provider.SHA2.lf_S
  15  0,17% 98,34%3205 303778 sun.security.provider.SHA2.implCompress
  16  0,14% 98,48%   9 306294 java.lang.Thread.join
  17  0,11% 98,58%  205120 303774 sun.security.provider.SHA2.lf_sigma1
  18  0,10% 98,69%  205120 303776 sun.security.provider.SHA2.lf_sigma0
  19  0,09% 98,77%  153840 303773 sun.security.provider.SHA2.lf_delta0
  20  0,08% 98,85%  153840 303772 sun.security.provider.SHA2.lf_delta1
  21  0,06% 98,91%   1 306334 
org.tanukisoftware.wrapper.WrapperManager.stopCommon
  22  0,03% 98,94%   1 306332 
freenet.support.FileLoggerHook$CloserThread.run
  23  0,03% 98,97%   1 306345 
org.tanukisoftware.wrapper.WrapperManager.dispose
  24  0,03% 99,00%  307680 303771 sun.security.provider.SHA2.lf_R
  25  0,02% 99,02%   42831 300120 java.lang.AbstractStringBuilder.append
  26  0,02% 99,04%  205120 303775 sun.security.provider.SHA2.lf_ch
  27  0,02% 99,07%  205120 303777 sun.security.provider.SHA2.lf_maj
  28  0,02% 99,09%  40 303514 
freenet.crypt.DiffieHellman.checkDHExponentialValidity
  29  0,02% 99,10%   40919 303500 java.math.BigInteger.testBit
  30  0,02% 99,12%1131 300767 java.lang.ClassLoader.defineClass
  31  0,01% 99,13%   1 306343 
org.tanukisoftware.wrapper.WrapperManager.signalStopped
  32  0,01% 99,15%   11837 305291 
freenet.client.async.ClientRequestSelector.removeFirstAccordingToPriorities
  33  0,01% 99,16%   18303 300177 java.util.HashMap.get
  34  0,01% 99,17%   45574 303826 java.lang.Long.compareTo
  35  0,01% 99,18%   45574 303825 java.lang.Long.compareTo
  36  0,01% 99,18%   16762 300475 java.util.HashMap.put
  37  0,01% 99,19%   38768 300121 java.lang.StringBuilder.append
  38  0,01% 99,20%   41182 303263 java.math.BigInteger.bitLength
  39  0,01% 99,21%3268 302615 sun.security.provider.ByteArrayAccess.b2iBig64
  40  0,01% 99,22%   82459 303844 java.lang.Math.abs
  41  

Re: [freenet-dev] Logging in Fred

[Marco Schulze]

On 24-03-2012 09:26, Marco Schulze wrote:
I finally got freenet.jar compiled and profiled. First, size-related 
numbers:


Number of lines removed: ~5000
freenet.jar shrink: ~200k

And profiling data (see below for details):

freenet.support.FileLoggerHook$WriterThread.run: 8,35% (3)
Oops. Most of the method's time is 'spent' inside Object.wait(). As far 
as I can gather with my limited Java profiling experience, this figure 
is actually between 2% and 3%. I've attached the output of another, 3 
minute run (HPROF w/ cpu=times).




freenet.support.Log.isLoggable: 0.09% (17)
freenet.support.Log.write: 0,03% (26)

These numbers come from a sanity check run, and _do not_ represent 
what would happen in a real test run. Both were run in an empty 
directory for a few minutes and then shut down. Of special note is the 
lack of the seed nodes list, leaving out, I'd guess, 80% of fred code. 
Also, lazy evaluation isn't used, so Log.write()'s share can be 
expected to rise.


There are still a few things to do before I can say whether predicates 
are indispensable or not.


On 18-03-2012 20:40, Marco Schulze wrote:
One thing has been bothering me: those 'if (logMINOR) 
Logger.minor(...', and the mess that logging is inside fred. I've 
written a very simple replacement for Logger + associated classes 
with the following changes:


- Log level (renamed to severity) filtering is done by Logging.log();
- Specific writer classes are replaced by a simple OutputStream, 
which defaults to System.err. Formatting is also unified;
- Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG 
and TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
- No logging method accepts an Object parameter - hashCode() is not 
exactly useful.


Additionally, log rotation will be moved outside (possibly inside Node).

Currently, the log format is 'severity\tmessage'.
CPU TIME (ms) BEGIN (total = 1676345) Sun Mar 25 13:54:57 2012
rank   self  accum   count trace method
   1 10,74% 10,74%   3 306148 
freenet.support.PooledExecutor$MyThread.realRun
   2 10,72% 21,46%   1 306331 
freenet.support.FileLoggerHook$WriterThread.run
   3 10,56% 32,02% 354 303612 freenet.io.NetworkInterface.accept
   4 10,03% 42,05%1680 305239 freenet.node.PacketSender.realRun
   5 10,00% 52,05%4346 305240 freenet.support.PrioritizedTicker.realRun
   6  9,94% 61,99%   1 306286 
java.net.AbstractPlainDatagramSocketImpl.receive
   7  9,63% 71,62%  90 305699 freenet.client.async.DatastoreChecker.realRun
   8  9,54% 81,16%  16 306056 freenet.node.DNSRequester.realRun
   9  7,72% 88,88%   3 303235 java.lang.Object.wait
  10  7,72% 96,60%2330 303243 java.lang.ref.ReferenceQueue.remove
  11  0,84% 97,43%   1 305391 
org.tanukisoftware.wrapper.WrapperManager$4.run
  12  0,31% 97,74%  36 304762 freenet.client.async.USKManager.subscribe
  13  0,25% 97,99%  19 304873 freenet.client.async.USKFetcher.schedule
  14  0,18% 98,17% 1846080 303770 sun.security.provider.SHA2.lf_S
  15  0,17% 98,34%3205 303778 sun.security.provider.SHA2.implCompress
  16  0,14% 98,48%   9 306294 java.lang.Thread.join
  17  0,11% 98,58%  205120 303774 sun.security.provider.SHA2.lf_sigma1
  18  0,10% 98,69%  205120 303776 sun.security.provider.SHA2.lf_sigma0
  19  0,09% 98,77%  153840 303773 sun.security.provider.SHA2.lf_delta0
  20  0,08% 98,85%  153840 303772 sun.security.provider.SHA2.lf_delta1
  21  0,06% 98,91%   1 306334 
org.tanukisoftware.wrapper.WrapperManager.stopCommon
  22  0,03% 98,94%   1 306332 
freenet.support.FileLoggerHook$CloserThread.run
  23  0,03% 98,97%   1 306345 
org.tanukisoftware.wrapper.WrapperManager.dispose
  24  0,03% 99,00%  307680 303771 sun.security.provider.SHA2.lf_R
  25  0,02% 99,02%   42831 300120 java.lang.AbstractStringBuilder.append
  26  0,02% 99,04%  205120 303775 sun.security.provider.SHA2.lf_ch
  27  0,02% 99,07%  205120 303777 sun.security.provider.SHA2.lf_maj
  28  0,02% 99,09%  40 303514 
freenet.crypt.DiffieHellman.checkDHExponentialValidity
  29  0,02% 99,10%   40919 303500 java.math.BigInteger.testBit
  30  0,02% 99,12%1131 300767 java.lang.ClassLoader.defineClass
  31  0,01% 99,13%   1 306343 
org.tanukisoftware.wrapper.WrapperManager.signalStopped
  32  0,01% 99,15%   11837 305291 
freenet.client.async.ClientRequestSelector.removeFirstAccordingToPriorities
  33  0,01% 99,16%   18303 300177 java.util.HashMap.get
  34  0,01% 99,17%   45574 303826 java.lang.Long.compareTo
  35  0,01% 99,18%   45574 303825 java.lang.Long.compareTo
  36  0,01% 99,18%   16762 300475 java.util.HashMap.put
  37  0,01% 99,19%   38768 300121 java.lang.StringBuilder.append
  38  0,01% 99,20%   41182 303263 java.math.BigInteger.bitLength
  39  0,01% 99,21%3268 302615 sun.security.provider.ByteArrayAccess.b2iBig64
  40  0,01% 99,22%   82459 303844 java.lang.Math.abs
  41  0,01% 99,23%   78754 300087 java.lang.String.length
  42  0,01% 99,24%   53433 300119 

[freenet-dev] Logging in Fred

[Marco Schulze]

I finally got freenet.jar compiled and profiled. First, size-related 
numbers:

Number of lines removed: ~5000
freenet.jar shrink: ~200k

And profiling data (see below for details):

freenet.support.FileLoggerHook$WriterThread.run: 8,35% (3)

freenet.support.Log.isLoggable: 0.09% (17)
freenet.support.Log.write: 0,03% (26)

These numbers come from a sanity check run, and _do not_ represent what 
would happen in a real test run. Both were run in an empty directory for 
a few minutes and then shut down. Of special note is the lack of the 
seed nodes list, leaving out, I'd guess, 80% of fred code. Also, lazy 
evaluation isn't used, so Log.write()'s share can be expected to rise.

There are still a few things to do before I can say whether predicates 
are indispensable or not.

On 18-03-2012 20:40, Marco Schulze wrote:
> One thing has been bothering me: those 'if (logMINOR) 
> Logger.minor(...', and the mess that logging is inside fred. I've 
> written a very simple replacement for Logger + associated classes with 
> the following changes:
>
> - Log level (renamed to severity) filtering is done by Logging.log();
> - Specific writer classes are replaced by a simple OutputStream, which 
> defaults to System.err. Formatting is also unified;
> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and 
> TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
> - No logging method accepts an Object parameter - hashCode() is not 
> exactly useful.
>
> Additionally, log rotation will be moved outside (possibly inside Node).
>
> Currently, the log format is '\t'.

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

[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

-- next part --
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 900 bytes
Desc: OpenPGP digital signature
URL: 

[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 

[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 

[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 

[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

Re: [freenet-dev] Logging in Fred

[Marco Schulze]

I finally got freenet.jar compiled and profiled. First, size-related 
numbers:


Number of lines removed: ~5000
freenet.jar shrink: ~200k

And profiling data (see below for details):

freenet.support.FileLoggerHook$WriterThread.run: 8,35% (3)

freenet.support.Log.isLoggable: 0.09% (17)
freenet.support.Log.write: 0,03% (26)

These numbers come from a sanity check run, and _do not_ represent what 
would happen in a real test run. Both were run in an empty directory for 
a few minutes and then shut down. Of special note is the lack of the 
seed nodes list, leaving out, I'd guess, 80% of fred code. Also, lazy 
evaluation isn't used, so Log.write()'s share can be expected to rise.


There are still a few things to do before I can say whether predicates 
are indispensable or not.


On 18-03-2012 20:40, Marco Schulze wrote:
One thing has been bothering me: those 'if (logMINOR) 
Logger.minor(...', and the mess that logging is inside fred. I've 
written a very simple replacement for Logger + associated classes with 
the following changes:


- Log level (renamed to severity) filtering is done by Logging.log();
- Specific writer classes are replaced by a simple OutputStream, which 
defaults to System.err. Formatting is also unified;
- Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and 
TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
- No logging method accepts an Object parameter - hashCode() is not 
exactly useful.


Additionally, log rotation will be moved outside (possibly inside Node).

Currently, the log format is 'severity\tmessage'.

___
Devl mailing list
Devl@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 

[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 

[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() { 

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

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

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

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

[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 

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

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

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" >>
>
> >> >> gmail.com
>>>
>
>
>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
>

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

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

[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
 

[freenet-dev] Logging in Fred

[Ximin Luo]

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
> 
> >  gmail.com>>
> > >     > >
> > >
> > >
> > > 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 

[freenet-dev] Logging in Fred

[Ximin Luo]

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

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 infini...@gmx.com
 mailto:infini...@gmx.com wrote:
 
The drastically cleaner syntax is a red herring. Most of the time when 
 you
are doing a complex calculation, you are not going to put it on one line
anyway. In such cases, the function you are using to do the calculation 
 might
as well be the toString() method of some object.
 
Your claim of double-digit millisecond pauses is worthless without some
benchmarking and actual numbers. Modern JVMs do escape analysis to avoid 
 heap
allocation and this helps especially for transient computations like in
logging.
 
On 22/03/12 21:59, Zlatin Balevsky wrote:
 Double-digit millisecond pauses are not nothing.  They may be acceptable
right
 now but unless you can offer a drastically cleaner syntax Fred should stick
 with predicates as they are handled much better by the hotspot jit.
 
 On Mar 22, 2012 5:36 PM, Ximin Luo infini...@gmx.com
mailto:infini...@gmx.com
 mailto:infini...@gmx.com 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 marco.c.schu...@gmail.com
mailto:marco.c.schu...@gmail.com
mailto:marco.c.schu...@gmail.com mailto:marco.c.schu...@gmail.com
 mailto:marco.c.schu...@gmail.com
mailto:marco.c.schu...@gmail.com mailto:marco.c.schu...@gmail.com
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:
 
  

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

[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 infini...@gmx.com
 mailto:infini...@gmx.com wrote:

The drastically cleaner syntax is a red herring. Most of the time when 
 you
are doing a complex calculation, you are not going to put it on one line
anyway. In such cases, the function you are using to do the calculation 
 might
as well be the toString() method of some object.

Your claim of double-digit millisecond pauses is worthless without some
benchmarking and actual numbers. Modern JVMs do escape analysis to avoid 
 heap
allocation and this helps especially for transient computations like in
logging.

On 22/03/12 21:59, Zlatin Balevsky wrote:
 Double-digit millisecond pauses are not nothing.  They may be acceptable
right
 now but unless you can offer a drastically cleaner syntax Fred should stick
 with predicates as they are handled much better by the hotspot jit.

 On Mar 22, 2012 5:36 PM, Ximin Luo infini...@gmx.com
mailto:infini...@gmx.com
 mailto:infini...@gmx.com 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 marco.c.schu...@gmail.com
mailto:marco.c.schu...@gmail.com
mailto:marco.c.schu...@gmail.com mailto:marco.c.schu...@gmail.com
 mailto:marco.c.schu...@gmail.com
mailto:marco.c.schu...@gmail.com mailto:marco.c.schu...@gmail.com
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 

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] 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 infini...@gmx.com 
  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
  marco.c.schu...@gmail.com mailto:marco.c.schu...@gmail.com
   mailto:marco.c.schu...@gmail.com
  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):
 

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 Luoinfini...@gmx.com
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
 marco.c.schu...@gmail.commailto:marco.c.schu...@gmail.com
   mailto:marco.c.schu...@gmail.com
 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 

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 Luoinfini...@gmx.com
  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
   marco.c.schu...@gmail.commailto:marco.c.schu...@gmail.com
 mailto:marco.c.schu...@gmail.com
   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).

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 Luoinfini...@gmx.com
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
  marco.c.schu...@gmail.commailto:marco.c.schu...@gmail.com
 mailto:marco.c.schu...@gmail.com
  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 

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; i100; 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 Luoinfini...@gmx.com
mailto:infini...@gmx.comwrote:

   Lazy evaluation is trivial.

   Log.info({1} did {2},
new Object(){ public String toString() { return ITEM_1; } },
new Object(){ public String toString() { return ITEM_2; } }
   );

   Garbage collection with short-lived objects costs next to nothing.

   On 22/03/12 21:15, Zlatin Balevsky wrote:
   Constructing the logging strings is half of the problem.  The
   amount of garbage
   they will generate will result in significantly more time in
   garbage collection
   pauses.
   
   Unless you figure out a way to mimic lazy evaluation you have to
   live with the
   isLoggable predicates.  varargs are not an option either because
   they also
   create garbage.
   
   On Mar 22, 2012 8:11 AM, Marco Schulze
   marco.c.schu...@gmail.commailto:marco.c.schu...@gmail.com
   mailto:marco.c.schu...@gmail.com
   mailto:marco.c.schu...@gmail.comwrote:
   
   
   
   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

[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 ListObject listToLog = new ArrayListObject(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 infini...@gmx.com wrote:
 LOL, are you kidding me?

 Please point to the exact lines of code that results in double-digit
 millisecond pauses?

 Talk is cheap, show us some numbers.

 BTW, the example I gave is not real code, and contains no variable
 declarations, so your challenge makes no sense. Since you apparently didn't
 understand my implicit argument, here it is in more detail: a typical method
 that computes something simply for the purpose of logging it somewhere, 
 usually
 only allocates local variables that are not stored anywhere in the long term.
 Escape analysis can turn these into stack allocations, saving GC overhead. (If
 they do use more long-term variables, they will need to be stored on the heap,
 but then GC doesn't need to clean these up anyway.)

 Why are you even looking at blog entries? Escape analysis has been around for
 years. http://hg.openjdk.java.net/jdk6/jdk6/hotspot/rev/357d4e2eb4dd

 On 23/03/12 02:06, Zlatin Balevsky wrote:
 My claim is based on day-to-day observations of hundreds of JVMs under 
 various
 load scenarios.

 Your claim that modern JVMs do escape analysis is worthless as it shows 
 that
 you have merely read some blog posts, and even those you've read only
 partially.  Please point to the exact lines of code in hotspot or any other
 modern jvm that will optimize the specific lazy evaluation example you
 presented, together with the opto-assembly that their JITs produce.  Failing
 that, take your attitude elsewhere.

 On Thu, Mar 22, 2012 at 8:49 PM, Ximin Luo infini...@gmx.com
 mailto:infini...@gmx.com wrote:

     The drastically cleaner syntax is a red herring. Most of the time when 
 you
     are doing a complex calculation, you are not going to put it on one line
     anyway. In such cases, the function you are using to do the calculation 
 might
     as well be the toString() method of some object.

     Your claim of double-digit millisecond pauses is worthless without some
     benchmarking and actual numbers. Modern JVMs do escape analysis to avoid 
 heap
     allocation and this helps especially for transient computations like in
     logging.

     On 22/03/12 21:59, Zlatin Balevsky wrote:
      Double-digit millisecond pauses are not nothing.  They may be 
 acceptable
     right
      now but unless you can offer a drastically cleaner syntax Fred should 
 stick
      with predicates as they are handled much better by the hotspot jit.
     
      On Mar 22, 2012 5:36 PM, Ximin Luo infini...@gmx.com
     mailto:infini...@gmx.com
      mailto:infini...@gmx.com 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 

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 ListObject listToLog = new ArrayListObject(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 infini...@gmx.com wrote:
 LOL, are you kidding me?

 Please point to the exact lines of code that results in double-digit
 millisecond pauses?

 Talk is cheap, show us some numbers.

 BTW, the example I gave is not real code, and contains no variable
 declarations, so your challenge makes no sense. Since you apparently didn't
 understand my implicit argument, here it is in more detail: a typical method
 that computes something simply for the purpose of logging it somewhere, 
 usually
 only allocates local variables that are not stored anywhere in the long term.
 Escape analysis can turn these into stack allocations, saving GC overhead. 
 (If
 they do use more long-term variables, they will need to be stored on the 
 heap,
 but then GC doesn't need to clean these up anyway.)

 Why are you even looking at blog entries? Escape analysis has been around for
 years. http://hg.openjdk.java.net/jdk6/jdk6/hotspot/rev/357d4e2eb4dd

 On 23/03/12 02:06, Zlatin Balevsky wrote:
 My claim is based on day-to-day observations of hundreds of JVMs under 
 various
 load scenarios.

 Your claim that modern JVMs do escape analysis is worthless as it shows 
 that
 you have merely read some blog posts, and even those you've read only
 partially.  Please point to the exact lines of code in hotspot or any other
 modern jvm that will optimize the specific lazy evaluation example you
 presented, together with the opto-assembly that their JITs produce.  Failing
 that, take your attitude elsewhere.

 On Thu, Mar 22, 2012 at 8:49 PM, Ximin Luo infini...@gmx.com
 mailto:infini...@gmx.com wrote:

 The drastically cleaner syntax is a red herring. Most of the time 
 when you
 are doing a complex calculation, you are not going to put it on one line
 anyway. In such cases, the function you are using to do the calculation 
 might
 as well be the toString() method of some object.

 Your claim of double-digit millisecond pauses is worthless without 
 some
 benchmarking and actual numbers. Modern JVMs do escape analysis to 
 avoid heap
 allocation and this helps especially for transient computations like in
 logging.

 On 22/03/12 21:59, Zlatin Balevsky wrote:
  Double-digit millisecond pauses are not nothing. 

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 ListObject listToLog = new ArrayListObject(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 infini...@gmx.com wrote:
 LOL, are you kidding me?

 Please point to the exact lines of code that results in double-digit
 millisecond pauses?

 Talk is cheap, show us some numbers.

 BTW, the example I gave is not real code, and contains no variable
 declarations, so your challenge makes no sense. Since you apparently didn't
 understand my implicit argument, here it is in more detail: a typical method
 that computes something simply for the purpose of logging it somewhere, 
 usually
 only allocates local variables that are not stored anywhere in the long 
 term.
 Escape analysis can turn these into stack allocations, saving GC overhead. 
 (If
 they do use more long-term variables, they will need to be stored on the 
 heap,
 but then GC doesn't need to clean these up anyway.)

 Why are you even looking at blog entries? Escape analysis has been around 
 for
 years. http://hg.openjdk.java.net/jdk6/jdk6/hotspot/rev/357d4e2eb4dd

 On 23/03/12 02:06, Zlatin Balevsky wrote:
 My claim is based on day-to-day observations of hundreds of JVMs under 
 various
 load scenarios.

 Your claim that modern JVMs do escape analysis is worthless as it shows 
 that
 you have merely read some blog posts, and even those you've read only
 partially.  Please point to the exact lines of code in hotspot or any other
 modern jvm that will optimize the specific lazy evaluation example you
 presented, together with the opto-assembly that their JITs produce.  
 Failing
 that, take your attitude elsewhere.

 On Thu, Mar 22, 2012 at 8:49 PM, Ximin Luo infini...@gmx.com
 mailto:infini...@gmx.com wrote:

 The drastically cleaner syntax is a red herring. Most of the time 
 when you
 are doing a complex calculation, you are not going to put it on one 
 line
 anyway. In such cases, the function you are using to do the 
 calculation might
 as well be the toString() method of some object.

 Your claim of double-digit millisecond pauses is worthless without 
 some
 benchmarking and actual numbers. Modern JVMs do escape analysis to 
 avoid heap
 allocation and this helps especially for transient computations like in
 

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 infini...@gmx.com wrote:
 That is because in your example you're allocating all those new Object()s in
 the same stack frame, so the allocator runs out of space on the stack.

 If you put the call to log(x, new Object()) inside its only function call, 
 each
 Object will be destroyed once that call exits, and no GC occurs.

 Example code here:
 https://gist.github.com/2177070

 The real use case just adds one simple operation with each logging call
 (since you're never logging without doing something else as well) to show how
 little of a difference it makes in real terms (5%).

 X

 On 24/03/12 01:15, Zlatin Balevsky wrote:
 You're right, the example you gave will put the arguments on the
 stack.  I wanted to clarify Escape Analysis in its current form works
 only if a new object doesn't exit the stack frame where it's created.
 Because of that, the moment you do something slightly more complicated
 you will create garbage like this:

    private static void logListSize ( final List? listToLog ) {
         LOG.log( list size is {1} ,
                 new Object() {
                         public String toString() {
                                 return String.valueOf(listToLog.size());
                         }
                 });
     }

 Here is the tricky part - if you can guarantee that everywhere in the
 jvm the LOG.log method is disabled by the logging system, then the
 entire call will compile to noop and no objects will be created.
 However, if even one call site enables logging you will end up
 creating the temp objects even if they don't get logged.  Below is a
 full example, compile and run passing -verbosegc -XX:+PrintGC and
 watch it GC all the time.

 =  LazyEvalTest.java ===
 import java.util.*;

 public class LazyEvalTest {

     // only if this is is always false does logging produce no garbage.
     private static boolean shouldLog = true;

     private static void log(String ar1, Object ar2) {
         if (shouldLog)
              System.out.println(ar1 + ar2.toString());
         shouldLog = false;
     }

     public static void main(String []ar) {

         final ListObject listToLog = new ArrayListObject(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 infini...@gmx.com wrote:
 LOL, are you kidding me?

 Please point to the exact lines of code that results in double-digit
 millisecond pauses?

 Talk is cheap, show us some numbers.

 BTW, the example I gave is not real code, and contains no variable
 declarations, so your challenge makes no sense. Since you apparently didn't
 understand my implicit argument, here it is in more detail: a typical method
 that computes something simply for the purpose of logging it somewhere, 
 usually
 only allocates local variables that are not stored anywhere in the long 
 term.
 Escape analysis can turn these into stack allocations, saving GC overhead. 
 (If
 they do use more long-term variables, they will need to be stored on the 
 heap,
 but then GC doesn't need to clean these up anyway.)

 Why are you even looking at blog entries? Escape analysis has been around 
 for
 years. http://hg.openjdk.java.net/jdk6/jdk6/hotspot/rev/357d4e2eb4dd

 On 23/03/12 02:06, Zlatin Balevsky wrote:
 My claim is based on day-to-day observations of hundreds of JVMs under 
 various
 load scenarios.

 Your claim that modern JVMs do escape analysis is worthless as it shows 
 that
 you have merely read some blog posts, and even those you've read only
 partially.  Please point to the exact lines of code in hotspot or any other
 modern jvm that will optimize the specific lazy evaluation example you
 presented, together with the opto-assembly that their JITs produce.  
 Failing
 that, take your attitude elsewhere.

 On Thu, Mar 22, 2012 at 8:49 PM, Ximin Luo infini...@gmx.com
 mailto:infini...@gmx.com wrote:

     The drastically cleaner syntax is a red herring. Most of the time 
 when you
     are doing a complex calculation, you are not going to put it on one 
 line
     anyway. In such cases, the function you are using to do the 
 calculation might
     as well be the toString() method of some object.

     Your 

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 zlat...@gmail.com 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 infini...@gmx.com wrote:
 That is because in your example you're allocating all those new Object()s in
 the same stack frame, so the allocator runs out of space on the stack.

 If you put the call to log(x, new Object()) inside its only function call, 
 each
 Object will be destroyed once that call exits, and no GC occurs.

 Example code here:
 https://gist.github.com/2177070

 The real use case just adds one simple operation with each logging call
 (since you're never logging without doing something else as well) to show how
 little of a difference it makes in real terms (5%).

 X

 On 24/03/12 01:15, Zlatin Balevsky wrote:
 You're right, the example you gave will put the arguments on the
 stack.  I wanted to clarify Escape Analysis in its current form works
 only if a new object doesn't exit the stack frame where it's created.
 Because of that, the moment you do something slightly more complicated
 you will create garbage like this:

    private static void logListSize ( final List? listToLog ) {
         LOG.log( list size is {1} ,
                 new Object() {
                         public String toString() {
                                 return String.valueOf(listToLog.size());
                         }
                 });
     }

 Here is the tricky part - if you can guarantee that everywhere in the
 jvm the LOG.log method is disabled by the logging system, then the
 entire call will compile to noop and no objects will be created.
 However, if even one call site enables logging you will end up
 creating the temp objects even if they don't get logged.  Below is a
 full example, compile and run passing -verbosegc -XX:+PrintGC and
 watch it GC all the time.

 =  LazyEvalTest.java ===
 import java.util.*;

 public class LazyEvalTest {

     // only if this is is always false does logging produce no garbage.
     private static boolean shouldLog = true;

     private static void log(String ar1, Object ar2) {
         if (shouldLog)
              System.out.println(ar1 + ar2.toString());
         shouldLog = false;
     }

     public static void main(String []ar) {

         final ListObject listToLog = new ArrayListObject(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 infini...@gmx.com wrote:
 LOL, are you kidding me?

 Please point to the exact lines of code that results in double-digit
 millisecond pauses?

 Talk is cheap, show us some numbers.

 BTW, the example I gave is not real code, and contains no variable
 declarations, so your challenge makes no sense. Since you apparently didn't
 understand my implicit argument, here it is in more detail: a typical 
 method
 that computes something simply for the purpose of logging it somewhere, 
 usually
 only allocates local variables that are not stored anywhere in the long 
 term.
 Escape analysis can turn these into stack allocations, saving GC overhead. 
 (If
 they do use more long-term variables, they will need to be stored on the 
 heap,
 but then GC doesn't need to clean these up anyway.)

 Why are you even looking at blog entries? Escape analysis has been around 
 for
 years. http://hg.openjdk.java.net/jdk6/jdk6/hotspot/rev/357d4e2eb4dd

 On 23/03/12 02:06, Zlatin Balevsky wrote:
 My claim is based on day-to-day observations of hundreds of JVMs under 
 various
 load scenarios.

 Your claim that modern JVMs do escape analysis is worthless as it shows 
 that
 you have merely read some blog posts, and even those you've read only
 partially.  Please point to the exact lines of code 

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 infini...@gmx.com wrote:
 That is because in your example you're allocating all those new Object()s in
 the same stack frame, so the allocator runs out of space on the stack.

 If you put the call to log(x, new Object()) inside its only function call, 
 each
 Object will be destroyed once that call exits, and no GC occurs.

 Example code here:
 https://gist.github.com/2177070

 The real use case just adds one simple operation with each logging call
 (since you're never logging without doing something else as well) to show how
 little of a difference it makes in real terms (5%).

 X

 On 24/03/12 01:15, Zlatin Balevsky wrote:
 You're right, the example you gave will put the arguments on the
 stack.  I wanted to clarify Escape Analysis in its current form works
 only if a new object doesn't exit the stack frame where it's created.
 Because of that, the moment you do something slightly more complicated
 you will create garbage like this:

private static void logListSize ( final List? listToLog ) {
 LOG.log( list size is {1} ,
 new Object() {
 public String toString() {
 return String.valueOf(listToLog.size());
 }
 });
 }

 Here is the tricky part - if you can guarantee that everywhere in the
 jvm the LOG.log method is disabled by the logging system, then the
 entire call will compile to noop and no objects will be created.
 However, if even one call site enables logging you will end up
 creating the temp objects even if they don't get logged.  Below is a
 full example, compile and run passing -verbosegc -XX:+PrintGC and
 watch it GC all the time.

 =  LazyEvalTest.java ===
 import java.util.*;

 public class LazyEvalTest {

 // only if this is is always false does logging produce no garbage.
 private static boolean shouldLog = true;

 private static void log(String ar1, Object ar2) {
 if (shouldLog)
  System.out.println(ar1 + ar2.toString());
 shouldLog = false;
 }

 public static void main(String []ar) {

 final ListObject listToLog = new ArrayListObject(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 infini...@gmx.com wrote:
 LOL, are you kidding me?

 Please point to the exact lines of code that results in double-digit
 millisecond pauses?

 Talk is cheap, show us some numbers.

 BTW, the example I gave is not real code, and contains no variable
 declarations, so your challenge makes no sense. Since you apparently didn't
 understand my implicit argument, here it is in more detail: a typical 
 method
 that computes something simply for the purpose of logging it somewhere, 
 usually
 only allocates local variables that are not stored anywhere in the long 
 term.
 

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
pid and you will see a huge number of java.lang.Integer objects in
the heap, not on the stack.

The difference in run times of your example could be due to many
things.  How many iterations did you run?  It may be still in
interpreted mode.  Enable -XX:+PrintCompilation and discard any
results until JIT stops printing.

On Fri, Mar 23, 2012 at 10:28 PM, Ximin Luo infini...@gmx.com wrote:
 On 24/03/12 01:56, Zlatin Balevsky wrote:
 Not really.  Here, I'll change my call to allocate everything on one level:

   while (true) {
               log( list size is {1} ,
                 new Integer(listToLog.size()));
           }

 I don't see how using this you can log primitive values without garbage.


 This still allocates many new Integer() on the stack without giving them an
 opportunity to be destroyed, because this occurs all on the same stack frame.
 Eventually there is no more space for stack allocation, leading to heap
 allocation and GC. This is an uncommon situation to pop up in real code
 however, because in most cases you don't have an extremely long loop.

 Have a look at the difference between testWithStackAllocation and
 testWithoutStackAllocation in the example I posted, and the huge difference in
 their run times; maybe it will be clearer then.

 Arguably the JVM should be smart enough to destroy things at the end of a code
 block when things go out of scope, including loops, but practically that
 doesn't appear to be the case. (Unless you have another explanation for the
 behaviour encountered when running my test code?)

 One reason I'm opposed to the predicate form, is because it encourages things 
 like

 | if (log_level) {
 |   // huge complex calculation
 |   // that takes up many lines
 |   // and distracts from the rest of the code
 |   log.level(args);
 | }

 We could agree to restrict logging calls to be of the form

 | if (log_level) log.level(
 |    args ... );

 which would at least force the complex calculations to be factored out into
 another method.

 On Fri, Mar 23, 2012 at 9:33 PM, Ximin Luo infini...@gmx.com wrote:
 That is because in your example you're allocating all those new Object()s in
 the same stack frame, so the allocator runs out of space on the stack.

 If you put the call to log(x, new Object()) inside its only function call, 
 each
 Object will be destroyed once that call exits, and no GC occurs.

 Example code here:
 https://gist.github.com/2177070

 The real use case just adds one simple operation with each logging call
 (since you're never logging without doing something else as well) to show 
 how
 little of a difference it makes in real terms (5%).

 X

 On 24/03/12 01:15, Zlatin Balevsky wrote:
 You're right, the example you gave will put the arguments on the
 stack.  I wanted to clarify Escape Analysis in its current form works
 only if a new object doesn't exit the stack frame where it's created.
 Because of that, the moment you do something slightly more complicated
 you will create garbage like this:

    private static void logListSize ( final List? listToLog ) {
         LOG.log( list size is {1} ,
                 new Object() {
                         public String toString() {
                                 return String.valueOf(listToLog.size());
                         }
                 });
     }

 Here is the tricky part - if you can guarantee that everywhere in the
 jvm the LOG.log method is disabled by the logging system, then the
 entire call will compile to noop and no objects will be created.
 However, if even one call site enables logging you will end up
 creating the temp objects even if they don't get logged.  Below is a
 full example, compile and run passing -verbosegc -XX:+PrintGC and
 watch it GC all the time.

 =  LazyEvalTest.java ===
 import java.util.*;

 public class LazyEvalTest {

     // only if this is is always false does logging produce no garbage.
     private static boolean shouldLog = true;

     private static void log(String ar1, Object ar2) {
         if (shouldLog)
              System.out.println(ar1 + ar2.toString());
         shouldLog = false;
     }

     public static void main(String []ar) {

         final ListObject listToLog = new ArrayListObject(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 

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 infini...@gmx.com wrote:
 On 24/03/12 02:44, Zlatin Balevsky wrote:
 Wrong.  Extracting the log statement into its own method and calling
 that method inside the while loop still creates garbage.  Stack frames
 are different.


 How do you explain the results obtained from running my test code, then? Turn
 on -verbose:gc. testWithStackAllocation results in no GC,
 testWithoutStackAllocation results in lots of GC.

 Read again exactly how Escape Analysis works.  The objects it prevents
 from creating do not appear in heap histograms.  Take a jmap -histo
 pid and you will see a huge number of java.lang.Integer objects in
 the heap, not on the stack.


 If you're still talking about your example, this is exactly consistent with 
 my
 explanation, i.e. that escape analysis is NOT occurring, properly anyway.

 The difference in run times of your example could be due to many
 things.  How many iterations did you run?  It may be still in
 interpreted mode.  Enable -XX:+PrintCompilation and discard any
 results until JIT stops printing.

 Done that, JIT stops printing after the 3rd iteration and results are the 
 same
 thereafter.

 --
 GPG: 4096R/5FBBDBCE
 https://github.com/infinity0
 https://bitbucket.org/infinity0
 https://launchpad.net/~infinity0


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


-- 
GPG: 4096R/5FBBDBCE
https://github.com/infinity0
https://bitbucket.org/infinity0
https://launchpad.net/~infinity0



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]

It doesn't look like a big deal but if all of Fred was using lazy
evaluation for logging it would make one common use case very
annoying:

Say I'm working on a specific class and need to run that class with
debug logging enabled.  This would have the side effect of changing
the compiled LOG.debug( ... ) method globally across the JVM and would
cause every log lazily evaluated parameter for every debug statement
to be instantiated.  Production deployments would not be affected but
the developer experience would.

P.S. nice trick with the Double.MIN_VALUE, I'll use that sometime :)

On Fri, Mar 23, 2012 at 11:33 PM, Ximin Luo infini...@gmx.com wrote:
 I see.

 Actually we didn't even need the side effects thing - I did notice that your
 example stopped doing GC when setting shouldLog = false always, so I tried 
 to
 introduce your if (shouldLog) { shouldLog = false; } into my example, but 
 was
 still unable to reproduce GC. Then changing

 - System.out.println(don't optimise me out);
 + System.out.println(format + args);

 worked to re-introduce GC.

 Well, that sucks. I guess the escape analyzer isn't sophisticated enough to 
 see
 that ar2.toString() does not cause ar2 to escape - and removing that from your
 log() method does result in no GC.

 I still think it's negligible though :p - for my test, I'm seeing only ~8ms
 lost to GC after 20 million calls, and this appears to not change by much even
 if I increase the number of arguments (and objects created) to log_info.

 On 24/03/12 03:02, Zlatin Balevsky wrote:
 Your test has nothing to do with stack allocation because you never
 use the objects that you pass to the log_info method so JIT removes
 them.  Apply the following patch and see yourself create garbage in
 both testWith and testWithout.

 --- Test2.java        2012-03-23 23:01:05.540475497 -0400
 +++ Test.java 2012-03-23 23:01:47.304477562 -0400
 @@ -6,8 +6,11 @@
    final Object existing = new Object();
    Object tmp = null;

 +  long sideEffect;
    public void log_info(String format, Object ... args) {
      if (log_level) {
 +      for (Object o : args)
 +     sideEffect += o.hashCode();
        System.out.println(don't optimise me out);
      }
    }
 @@ -88,11 +91,8 @@
      printSummary(with alloc, res[0], w/o alloc, res[1]);
      printSummary(with alloc, res[2], w/o alloc, res[3]);
      printSummary(with alloc, res[4], w/o alloc, res[5]);
 -    System.out.println( with stack allocation and \real use case\);
 -    res = testWithOtherCode(z);
 -    printSummary(log only, res[0], log+work, res[1]);
 -    printSummary(log only, res[2], log+work, res[3]);
 -    printSummary(log only, res[4], log+work, res[5]);
 +
 +    System.out.println(sideEffect);
    }

    public static void main(String[] args) {


 On Fri, Mar 23, 2012 at 10:48 PM, Ximin Luo infini...@gmx.com wrote:
 On 24/03/12 02:44, Zlatin Balevsky wrote:
 Wrong.  Extracting the log statement into its own method and calling
 that method inside the while loop still creates garbage.  Stack frames
 are different.


 How do you explain the results obtained from running my test code, then? 
 Turn
 on -verbose:gc. testWithStackAllocation results in no GC,
 testWithoutStackAllocation results in lots of GC.

 Read again exactly how Escape Analysis works.  The objects it prevents
 from creating do not appear in heap histograms.  Take a jmap -histo
 pid and you will see a huge number of java.lang.Integer objects in
 the heap, not on the stack.


 If you're still talking about your example, this is exactly consistent with 
 my
 explanation, i.e. that escape analysis is NOT occurring, properly anyway.

 The difference in run times of your example could be due to many
 things.  How many iterations did you run?  It may be still in
 interpreted mode.  Enable -XX:+PrintCompilation and discard any
 results until JIT stops printing.

 Done that, JIT stops printing after the 3rd iteration and results are the 
 same
 thereafter.

 --
 GPG: 4096R/5FBBDBCE
 https://github.com/infinity0
 https://bitbucket.org/infinity0
 https://launchpad.net/~infinity0


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


 --
 GPG: 4096R/5FBBDBCE
 https://github.com/infinity0
 https://bitbucket.org/infinity0
 https://launchpad.net/~infinity0


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

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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

[Zlatin Balevsky]

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

[freenet-dev] Logging in Fred

[Ximin Luo]

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
> transfer bloat to freenet-ext.jar. For example: log2socket, config
> management and multiple logging instances;
> - Implementable in a few LoC. Specially, it shouldn't need 
> specialized
> Formatter and Writer.
> 
> Plus, it should be fast.
> 
>  From the quick research I made (yep, too many lists):
> 
> - SLF4J already fails on point one: it is simply a wrapper;
> - The Java logging API fails on point two: specialized classes 
> would
> have to be written to deal with log rotation, per-class filtering 
> and
> formatting, plus a wrapper for Logger.{info,warning,...}() 
> methods.
> Exactly the same as a custom logger, with one more dependency and 
> using
> more LoC;
> 
> No dependancies, it's part of the JDK, isn't it?
> 
> More classes need to be loaded at startup. It's just me thinking too much.
> 
> 
> However, if it's not a clearer/simpler API, it probably doesn't make
> much sense.
> 
> - Log4J seems to fail on point one - it only lacks a button that 
> brings
> back the dead. It seems interesting, and I haven't dropped this 
> yet.
> 
> In either case (custom or external), log* would be banished. 
> Forever.
> 
> I don't follow. You object to using a separate logs folder?
> 
> log* == log{MINOR,DEBUG}, not the logs folder.
> _
> Devl mailing list
> Devl at freenetproject.org 
> 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: 

[freenet-dev] Logging in Fred

[Marco Schulze]

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

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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
> > transfer bloat to freenet-ext.jar. For example: log2socket,
> config
> > management and multiple logging instances;
> > - Implementable in a few LoC. Specially, it shouldn't need
> specialized
> > Formatter and Writer.
> >
> > Plus, it should be fast.
> >
> >  From the quick research I made (yep, too many lists):
> >
> > - SLF4J already fails on point one: it is simply a wrapper;
> > - The Java logging API fails on point two: specialized
> classes would
> > have to be written to deal with log rotation, per-class
> filtering and
> > formatting, plus a wrapper for Logger.{info,warning,...}()
> methods.
> > Exactly the same as a custom logger, with one more
> dependency and using
> > more LoC;
> >
> > No dependancies, it's part of the JDK, isn't it?
> >
> > More classes need to be loaded at startup. It's just me thinking too
> much.
> >
> >
> > However, if it's not a clearer/simpler API, it probably doesn't
> make
> > much sense.
> >
> > - Log4J seems to fail on point one - it only lacks a button
> that brings
> > back the dead. It seems interesting, and I haven't dropped
> this yet.
> >
> > In either case (custom or external), log* would be banished.
> Forever.
> >
> > I don't follow. You object to using a separate logs folder?
> >
> > log* == log{MINOR,DEBUG}, not the logs folder.
> > _
> > Devl mailing list
> > Devl at freenetproject.org 
> > https://emu.freenetproject.__org/cgi-bin/mailman/listinfo/__devl
> > 
> >
> >
> >
> > ___
> > Devl mailing list
> > Devl at freenetproject.org
> > https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
>
>
> --
> GPG: 4096R/5FBBDBCE
> https://github.com/infinity0
> https://bitbucket.org/infinity0
> https://launchpad.net/~infinity0
>
>
> ___
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
>
-- next part --
An HTML attachment was scrubbed...
URL: 

[freenet-dev] Logging in Fred

[Zlatin Balevsky]

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
>>> transfer bloat to freenet-ext.jar. For example: log2socket, config
>>> management and multiple logging instances;
>>> - Implementable in a few LoC. Specially, it shouldn't need specialized
>>> Formatter and Writer.
>>>
>>> Plus, it should be fast.
>>>
>>>  From the quick research I made (yep, too many lists):
>>>
>>> - SLF4J already fails on point one: it is simply a wrapper;
>>> - The Java logging API fails on point two: specialized classes would
>>> have to be written to deal with log rotation, per-class filtering and
>>> formatting, plus a wrapper for Logger.{info,warning,...}() methods.
>>> Exactly the same as a custom logger, with one more dependency and using
>>> more LoC;
>>>
>> No dependancies, it's part of the JDK, isn't it?
>>
> More classes need to be loaded at startup. It's just me thinking too much.
>
>
>> However, if it's not a clearer/simpler API, it probably doesn't make much
>> sense.
>>
>>  - Log4J seems to fail on point one - it only lacks a button that brings
>>> back the dead. It seems interesting, and I haven't dropped this yet.
>>>
>>> In either case (custom or external), log* would be banished. Forever.
>>>
>> I don't follow. You object to using a separate logs folder?
>>
> log* == log{MINOR,DEBUG}, not the logs folder.
> __**_
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.**org/cgi-bin/mailman/listinfo/**devl
>
-- next part --
An HTML attachment was scrubbed...
URL: 

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

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

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Thursday 22 Mar 2012 05:50:48 David ?Bombe? Roden wrote:
> On Tue, 2012-03-20 at 22:44 +, Matthew Toseland wrote:
> 
> > I am speaking from experience. write() is supposed to either succeed or 
> > throw. PrintWriter busy-loops on disk full when stderr is redirected to a 
> > file. Feel free to test it, it may be that it doesn't happen with modern 
> > JVMs. But it's unacceptable.
> 
> I have just checked PrintWriter?s source code (OpenJDK 6). There?s no
> sign of it busy-looping anywhere. I have also checked PrintStream: no
> busy-looping.
> 
> And just for the hell of it I downloaded JDK 1.1.8? and I wasn?t able to
> find any busy-looping in there, either. So whatever it was that bit you
> back then it must have been something different and you just
> mis-diagnosed it. :/

Hmmm, perhaps. write() either succeeds or throws ... maybe it throws and we 
catch it and re-call it? Dunno...
-- 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: 

[freenet-dev] Logging in Fred

[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'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.

[freenet-dev] Logging in Fred

[David ‘Bombe’ Roden]

On Tue, 2012-03-20 at 22:44 +, Matthew Toseland wrote:

> I am speaking from experience. write() is supposed to either succeed or 
> throw. PrintWriter busy-loops on disk full when stderr is redirected to a 
> file. Feel free to test it, it may be that it doesn't happen with modern 
> JVMs. But it's unacceptable.

I have just checked PrintWriter?s source code (OpenJDK 6). There?s no
sign of it busy-looping anywhere. I have also checked PrintStream: no
busy-looping.

And just for the hell of it I downloaded JDK 1.1.8? and I wasn?t able to
find any busy-looping in there, either. So whatever it was that bit you
back then it must have been something different and you just
mis-diagnosed it. :/


Greetings,

David
-- 
David ?Bombe? Roden 
-- 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: 

Re: [freenet-dev] Logging in Fred

[Matthew Toseland]

On Thursday 22 Mar 2012 05:50:48 David ‘Bombe’ Roden wrote:
 On Tue, 2012-03-20 at 22:44 +, Matthew Toseland wrote:
 
  I am speaking from experience. write() is supposed to either succeed or 
  throw. PrintWriter busy-loops on disk full when stderr is redirected to a 
  file. Feel free to test it, it may be that it doesn't happen with modern 
  JVMs. But it's unacceptable.
 
 I have just checked PrintWriter’s source code (OpenJDK 6). There’s no
 sign of it busy-looping anywhere. I have also checked PrintStream: no
 busy-looping.
 
 And just for the hell of it I downloaded JDK 1.1.8… and I wasn’t able to
 find any busy-looping in there, either. So whatever it was that bit you
 back then it must have been something different and you just
 mis-diagnosed it. :/

Hmmm, perhaps. write() either succeeds or throws ... maybe it throws and we 
catch it and re-call it? Dunno...


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

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?


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

[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'd be enough, but, personally,
the mess that the logging backend is does warrant a replacement.
According to toad, the current system needs log{MINOR,DEBUG} to function
in a timely manner. Based on this, I think we all agree a replacement is
desirable.

Logging has a few additional requirements:

- Log rotation (possibly live);
- Reentrant;
- Per-class filtering;
- Specific information in log (class-name, for example).

Now, _any_ library which fits would make me happy, as long as they agree
to two points:

- Either lightweight or with optional features. Else, it would only
transfer bloat to freenet-ext.jar. For example: log2socket, config
management and multiple logging instances;
- Implementable in a few LoC. Specially, it shouldn't need specialized
Formatter and Writer.

Plus, it should be fast.

  From the quick research I made (yep, too many lists):

- SLF4J already fails on point one: it is simply a wrapper;
- The Java logging API fails on point two: specialized classes would
have to be written to deal with log rotation, per-class filtering and
formatting, plus a wrapper for Logger.{info,warning,...}() methods.
Exactly the same as a custom logger, with one more dependency and using
more LoC;

No dependancies, it's part of the JDK, isn't it?

More classes need to be loaded at startup. It's just me thinking too much.



However, if it's not a clearer/simpler API, it probably doesn't make much sense.


- Log4J seems to fail on point one - it only lacks a button that brings
back the dead. It seems interesting, and I haven't dropped this yet.

In either case (custom or external), log* would be banished. Forever.

I don't follow. You object to using a separate logs folder?

log* == log{MINOR,DEBUG}, not the logs folder.
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

Lazy evaluation is trivial.

Log.info({1} did {2},
  new Object(){ public String toString() { return ITEM_1; } },
  new Object(){ public String toString() { return ITEM_2; } }
);

Garbage collection with short-lived objects costs next to nothing.

On 22/03/12 21:15, Zlatin Balevsky wrote:
 Constructing the logging strings is half of the problem.  The amount of 
 garbage
 they will generate will result in significantly more time in garbage 
 collection
 pauses. 
 
 Unless you figure out a way to mimic lazy evaluation you have to live with the
 isLoggable predicates.  varargs are not an option either because they also
 create garbage.
 
 On Mar 22, 2012 8:11 AM, Marco Schulze marco.c.schu...@gmail.com
 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;
 - The Java logging API fails on point two: specialized classes 
 would
 have to be written to deal with log rotation, per-class filtering 
 and
 formatting, plus a wrapper for Logger.{info,warning,...}() 
 methods.
 Exactly the same as a custom logger, with one more dependency and 
 using
 more LoC;
 
 No dependancies, it's part of the JDK, isn't it?
 
 More classes need to be loaded at startup. It's just me thinking too much.
 
 
 However, if it's not a clearer/simpler API, it probably doesn't make
 much sense.
 
 - Log4J seems to fail on point one - it only lacks a button that 
 brings
 back the dead. It seems interesting, and I haven't dropped this 
 yet.
 
 In either case (custom or external), log* would be banished. 
 Forever.
 
 I don't follow. You object to using a separate logs folder?
 
 log* == log{MINOR,DEBUG}, not the logs folder.
 _
 Devl mailing list
 Devl@freenetproject.org mailto:Devl@freenetproject.org
 https://emu.freenetproject.__org/cgi-bin/mailman/listinfo/__devl
 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]

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 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 marco.c.schu...@gmail.com
  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;
  - The Java logging API fails on point two: specialized
 classes would
  have to be written to deal with log rotation, per-class
 filtering and
  formatting, plus a wrapper for Logger.{info,warning,...}()
 methods.
  Exactly the same as a custom logger, with one more
 dependency and using
  more LoC;
 
  No dependancies, it's part of the JDK, isn't it?
 
  More classes need to be loaded at startup. It's just me thinking too
 much.
 
 
  However, if it's not a clearer/simpler API, it probably doesn't
 make
  much sense.
 
  - Log4J seems to fail on point one - it only lacks a button
 that brings
  back the dead. It seems interesting, and I haven't dropped
 this yet.
 
  In either case (custom or external), log* would be banished.
 Forever.
 
  I don't follow. You object to using a separate logs folder?
 
  log* == log{MINOR,DEBUG}, not the logs folder.
  _
  Devl mailing list
  Devl@freenetproject.org mailto:Devl@freenetproject.org
  https://emu.freenetproject.__org/cgi-bin/mailman/listinfo/__devl
  https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
 
 
 
  ___
  Devl mailing list
  Devl@freenetproject.org
  https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl


 --
 GPG: 4096R/5FBBDBCE
 https://github.com/infinity0
 https://bitbucket.org/infinity0
 https://launchpad.net/~infinity0


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

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

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

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 infini...@gmx.com wrote:

 The drastically cleaner syntax is a red herring. Most of the time when
 you
 are doing a complex calculation, you are not going to put it on one line
 anyway. In such cases, the function you are using to do the calculation
 might
 as well be the toString() method of some object.

 Your claim of double-digit millisecond pauses is worthless without some
 benchmarking and actual numbers. Modern JVMs do escape analysis to avoid
 heap
 allocation and this helps especially for transient computations like in
 logging.

 On 22/03/12 21:59, Zlatin Balevsky wrote:
  Double-digit millisecond pauses are not nothing.  They may be acceptable
 right
  now but unless you can offer a drastically cleaner syntax Fred should
 stick
  with predicates as they are handled much better by the hotspot jit.
 
  On Mar 22, 2012 5:36 PM, Ximin Luo infini...@gmx.com
  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 
 marco.c.schu...@gmail.com
  mailto:marco.c.schu...@gmail.com
   mailto:marco.c.schu...@gmail.com 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;
   - 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 

Re: [freenet-dev] Logging in Fred

[Zlatin Balevsky]

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
marco.c.schu...@gmail.com 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 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 marco.c.schu...@gmail.com
  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;
              - 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 

Re: [freenet-dev] Logging in Fred

[Ximin Luo]

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 infini...@gmx.com
 mailto:infini...@gmx.com wrote:
 
 The drastically cleaner syntax is a red herring. Most of the time when 
 you
 are doing a complex calculation, you are not going to put it on one line
 anyway. In such cases, the function you are using to do the calculation 
 might
 as well be the toString() method of some object.
 
 Your claim of double-digit millisecond pauses is worthless without some
 benchmarking and actual numbers. Modern JVMs do escape analysis to avoid 
 heap
 allocation and this helps especially for transient computations like in
 logging.
 
 On 22/03/12 21:59, Zlatin Balevsky wrote:
  Double-digit millisecond pauses are not nothing.  They may be acceptable
 right
  now but unless you can offer a drastically cleaner syntax Fred should 
 stick
  with predicates as they are handled much better by the hotspot jit.
 
  On Mar 22, 2012 5:36 PM, Ximin Luo infini...@gmx.com
 mailto:infini...@gmx.com
  mailto:infini...@gmx.com 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 
 marco.c.schu...@gmail.com
 mailto:marco.c.schu...@gmail.com
  mailto:marco.c.schu...@gmail.com 
 mailto:marco.c.schu...@gmail.com
   mailto:marco.c.schu...@gmail.com
 mailto:marco.c.schu...@gmail.com mailto:marco.c.schu...@gmail.com
 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:
  

[freenet-dev] Logging in Fred

[Marco Schulze]

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

On 21-03-2012 13:47, Ian Clarke wrote:
> Is there a good reason to roll our own logging framework?  What about 
> http://www.slf4j.org/ or one of the many other alternatives?
>
> Ian.
>
> On Sun, Mar 18, 2012 at 6:40 PM, Marco Schulze 
> mailto:marco.c.schulze at gmail.com>> wrote:
>
> One thing has been bothering me: those 'if (logMINOR)
> Logger.minor(...', and the mess that logging is inside fred. I've
> written a very simple replacement for Logger + associated classes
> with the following changes:
>
> - Log level (renamed to severity) filtering is done by Logging.log();
> - Specific writer classes are replaced by a simple OutputStream,
> which defaults to System.err. Formatting is also unified;
> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG
> and TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
> - No logging method accepts an Object parameter - hashCode() is
> not exactly useful.
>
> Additionally, log rotation will be moved outside (possibly inside
> Node).
>
> Currently, the log format is '\t'.
> ___
> Devl mailing list
> Devl at freenetproject.org 
> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
>
>
>
>
> -- 
> Ian Clarke
> Personal blog: http://blog.locut.us/
>
>
> ___
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
-- next part --
An HTML attachment was scrubbed...
URL: 

[freenet-dev] Logging in Fred

[Ian Clarke]

Is there a good reason to roll our own logging framework?  What about
http://www.slf4j.org/ or one of the many other alternatives?

Ian.

On Sun, Mar 18, 2012 at 6:40 PM, Marco Schulze wrote:

> One thing has been bothering me: those 'if (logMINOR) Logger.minor(...',
> and the mess that logging is inside fred. I've written a very simple
> replacement for Logger + associated classes with the following changes:
>
> - Log level (renamed to severity) filtering is done by Logging.log();
> - Specific writer classes are replaced by a simple OutputStream, which
> defaults to System.err. Formatting is also unified;
> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and
> TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
> - No logging method accepts an Object parameter - hashCode() is not
> exactly useful.
>
> Additionally, log rotation will be moved outside (possibly inside Node).
>
> Currently, the log format is '\t'.
> __**_
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.**org/cgi-bin/mailman/listinfo/**devl
>



-- 
Ian Clarke
Personal blog: http://blog.locut.us/
-- next part --
An HTML attachment was scrubbed...
URL: 

Re: [freenet-dev] Logging in Fred

[Ian Clarke]

Is there a good reason to roll our own logging framework?  What about
http://www.slf4j.org/ or one of the many other alternatives?

Ian.

On Sun, Mar 18, 2012 at 6:40 PM, Marco Schulze marco.c.schu...@gmail.comwrote:

 One thing has been bothering me: those 'if (logMINOR) Logger.minor(...',
 and the mess that logging is inside fred. I've written a very simple
 replacement for Logger + associated classes with the following changes:

 - Log level (renamed to severity) filtering is done by Logging.log();
 - Specific writer classes are replaced by a simple OutputStream, which
 defaults to System.err. Formatting is also unified;
 - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and
 TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
 - No logging method accepts an Object parameter - hashCode() is not
 exactly useful.

 Additionally, log rotation will be moved outside (possibly inside Node).

 Currently, the log format is 'severity\tmessage'.
 __**_
 Devl mailing list
 Devl@freenetproject.org
 https://emu.freenetproject.**org/cgi-bin/mailman/listinfo/**devlhttps://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl




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

[Marco Schulze]

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

On 21-03-2012 13:47, Ian Clarke wrote:
Is there a good reason to roll our own logging framework?  What about 
http://www.slf4j.org/ or one of the many other alternatives?


Ian.

On Sun, Mar 18, 2012 at 6:40 PM, Marco Schulze 
marco.c.schu...@gmail.com mailto:marco.c.schu...@gmail.com wrote:


One thing has been bothering me: those 'if (logMINOR)
Logger.minor(...', and the mess that logging is inside fred. I've
written a very simple replacement for Logger + associated classes
with the following changes:

- Log level (renamed to severity) filtering is done by Logging.log();
- Specific writer classes are replaced by a simple OutputStream,
which defaults to System.err. Formatting is also unified;
- Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG
and TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
- No logging method accepts an Object parameter - hashCode() is
not exactly useful.

Additionally, log rotation will be moved outside (possibly inside
Node).

Currently, the log format is 'severity\tmessage'.
___
Devl mailing list
Devl@freenetproject.org mailto:Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl




--
Ian Clarke
Personal blog: http://blog.locut.us/


___
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

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Monday 19 Mar 2012 21:56:42 Marco Schulze wrote:
> On 19-03-2012 16:42, Matthew Toseland wrote:
> > No it doesn't. We need to be able to filter *by class name*, not just 
> > globally. I agree that in theory the if(logMINOR) is optional if the 
> > message is static though; I guess the JVM is fast enough that this won't 
> > cost us any cycles?
> >
> > However, the minimum form of the boilerplate code is only:
> >
> > static {
> > volatile boolean logMINOR;
> > volatile boolean logDEBUG;
> > Logger.registerClass(Blah.class);
> > }
> Fred source tree (@master) contains 1012 *.java files. Even if 
> conservatively assuming  that only 50% of those classes contain this 
> snippet, and that they all use this minimal form, we have 2530 LoC for 
> boilerplate code alone. Plus, 3379 hits to either logMINOR or logDEBUG.
> 
> That's a lot of code and memory use just to decide if a message is to be 
> logged or not. (Yes, speed. See below)
> 
> > Hmm, maybe. Something like s[n]printf even - log("request %u rejected by 
> > %o", requestID, peer) ??? Might be clearer code? Lot of work to change it 
> > though - and fractionally lower runtime performance than the if(). 
> > Unfortunately java doesn't have macros - but even if it did we'd like to be 
> > able to turn it on at runtime.
> I was thinking in something along the lines of Python's print() - if the 
> message is to be logged:
> 
> Logger.info("This: ", this, ", and that: ", this.that)
> 
> is completely equivalent to:
> 
> Logger.info("This: " + this + ", and that: " + this.that)
> 
> If the message is discarded, the overhead is a function call + cost of 
> filtering (most likely a simple table lookup and two int comparisons in 
> the worst case).
> 
> If you'd like a strict comparison between the overhead of using an if, 
> against the overhead of a function call, I ran three simple test cases:
> 
> - Call an empty function;
> - Test a boolean and then call an empty function, with the boolean set 
> to either true or false.
> 
> The test case was inside a for loop, repeating for about 2 billion 
> times. The test was run thrice, with only milliseconds of difference 
> between runs. More importantly, JIT was disabled through -Xint.
> 
> Function call: ~31 seconds
> Test + call: ~33 seconds
> Failed test: ~23 seconds
> 
> So yes, in my machine, using an if saves 7 seconds over 2 billion best 
> case tests. That's ~3,26 nanoseconds saved per test - an insignificant 
> microptimization.
> 
> If JIT is enabled, it could be argued that it's easier for the JVM to 
> perform optimizations based on a single boolean, than on multiple 
> volatile booleans.
> 
> > PrintWriter (System.err) busy-loops. :( It is probably possible to get the 
> > underlying OutputStream though.
> Will take a look at it.
> 
> > Yes. There is no reason to have each and every thread wait on disk I/O 
> > (whether this is cached or not), and furthermore this will lead to 
> > locking/concurrency problems. We get best performance by writing off 
> > thread, and we can then have that thread dump excess log messages if it 
> > can't keep up, avoiding blocking; or if something has to block, it's that 
> > thread and no other; and it can also handle log rotation cleanly. And even 
> > more importantly, we can keep lock contention to an absolute minimum, so 
> > other threads logging data create a byte[] and then lock only to add it to 
> > a queue (and delete surplus from the other end if necessary), which takes 
> > insignificant time.
> >
> > All of this stuff is in FileLoggerHook.java.
> Synchronization is the reason every thread should wait. If the log is 
> always flushed and fred crashes, you know exactly where the last good 
> checkpoint was before the crash. If the log is buffered (or 
> asynchronous), the thread may be miles ahead from the last message 
> written to disk, and suddenly you have no idea where to look for the 
> bug. Shotgun debugging indeed.
> 
> Granted, if you want to generate lots of traces and debug data, it is 
> desirable to churn out data at the highest rate possible. Possibly a 
> configuration variable? Something like 'logger.mode = safe' (sync + 
> flush) and 'logger.mode = unsafe' (async + buffered)?
> 
> Now, I'd wager the cost of maintaining a cache of log messages far 
> surpass the cost of generating them in the first place except for very 
> costly messages regenerated sparingly (or not at all). I haven't seen 
> the current implementation, so there might exist some trick I'm failing 
> to grasp.
> 
> > I beg to differ. This shouldn't happen in normal use anyway. It's a message 
> > to devs doing shotgun debugging that they need a narrower filter (or faster 
> > disks!). We do indicate when stuff has been dropped.
> Indication is no substitute for missing data. Speed doesn't really 
> matter if you lose that critical message.
> 
> > Would that be solved by renaming?
> Since most people are used to DEBUG and INFO levels, their use becomes 
> 

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Monday 19 Mar 2012 22:37:05 Marco Schulze wrote:
> On 19-03-2012 18:56, Marco Schulze wrote:
> > On 19-03-2012 16:42, Matthew Toseland wrote:
> >> PrintWriter (System.err) busy-loops. :( It is probably possible to 
> >> get the underlying OutputStream though.
> > Will take a look at it.
>  From what I found after a quick googling, full disk errors do throw an 
> IOException, but is silently ignored by various OutputStream subclasses 
> (except for write(byte[])). No mention of any busy-loop, however.

I am speaking from experience. write() is supposed to either succeed or throw. 
PrintWriter busy-loops on disk full when stderr is redirected to a file. Feel 
free to test it, it may be that it doesn't happen with modern JVMs. But it's 
unacceptable.

Usually when you see this sort of convoluted stuff, there is a reason for it. 
Any solution that "simplifies" it and makes it more "elegant" must address all 
the problems that caused the complexity in the first place! If it doesn't the 
various patches will just be re-added, wasting everyone's time.
-- 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: 

[freenet-dev] Logging in Fred

[Marco Schulze]

On normal conditions, never. My reasoning was way off... streams are 
finalized (and flushed) even on abnormal exit.

On 20-03-2012 05:09, Martin Nyhus wrote:
> On Tuesday 20. March 2012 00:34:11 Marco Schulze wrote:
>> How often does what happen?
> Crashes that cause the log buffer to be lost before it is written to disk and
> whatever else you had in mind when you wrote this:
>
> On Monday 19. March 2012 22:56:42 Marco Schulze wrote:
>> Synchronization is the reason every thread should wait. If the log is
>> always flushed and fred crashes, you know exactly where the last good
>> checkpoint was before the crash. If the log is buffered (or
>> asynchronous), the thread may be miles ahead from the last message
>> written to disk, and suddenly you have no idea where to look for the
>> bug. Shotgun debugging indeed.
> ___
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

[freenet-dev] Logging in Fred

[Martin Nyhus]

On Tuesday 20. March 2012 00:34:11 Marco Schulze wrote:
> How often does what happen?

Crashes that cause the log buffer to be lost before it is written to disk and 
whatever else you had in mind when you wrote this:

On Monday 19. March 2012 22:56:42 Marco Schulze wrote:
> Synchronization is the reason every thread should wait. If the log is
> always flushed and fred crashes, you know exactly where the last good
> checkpoint was before the crash. If the log is buffered (or
> asynchronous), the thread may be miles ahead from the last message
> written to disk, and suddenly you have no idea where to look for the
> bug. Shotgun debugging indeed.

[freenet-dev] Logging in Fred

[Martin Nyhus]

On Monday 19. March 2012 22:56:42 Marco Schulze wrote:
> Synchronization is the reason every thread should wait. If the log is
> always flushed and fred crashes, you know exactly where the last good
> checkpoint was before the crash. If the log is buffered (or
> asynchronous), the thread may be miles ahead from the last message
> written to disk, and suddenly you have no idea where to look for the
> bug. Shotgun debugging indeed.

How often does this actually happen? Considering the performance penalty it 
has to fix a very real problem IMHO, especially since having logging change 
how the code behaves in such a dramatic way will make debugging anything that 
depends on timing that much harder.

Re: [freenet-dev] Logging in Fred

[Martin Nyhus]

On Tuesday 20. March 2012 00:34:11 Marco Schulze wrote:
 How often does what happen?

Crashes that cause the log buffer to be lost before it is written to disk and 
whatever else you had in mind when you wrote this:

On Monday 19. March 2012 22:56:42 Marco Schulze wrote:
 Synchronization is the reason every thread should wait. If the log is
 always flushed and fred crashes, you know exactly where the last good
 checkpoint was before the crash. If the log is buffered (or
 asynchronous), the thread may be miles ahead from the last message
 written to disk, and suddenly you have no idea where to look for the
 bug. Shotgun debugging indeed.
___
Devl mailing list
Devl@freenetproject.org
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

Re: [freenet-dev] Logging in Fred

[Marco Schulze]

On normal conditions, never. My reasoning was way off... streams are 
finalized (and flushed) even on abnormal exit.


On 20-03-2012 05:09, Martin Nyhus wrote:

On Tuesday 20. March 2012 00:34:11 Marco Schulze wrote:

How often does what happen?

Crashes that cause the log buffer to be lost before it is written to disk and
whatever else you had in mind when you wrote this:

On Monday 19. March 2012 22:56:42 Marco Schulze wrote:

Synchronization is the reason every thread should wait. If the log is
always flushed and fred crashes, you know exactly where the last good
checkpoint was before the crash. If the log is buffered (or
asynchronous), the thread may be miles ahead from the last message
written to disk, and suddenly you have no idea where to look for the
bug. Shotgun debugging indeed.

___
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

[Matthew Toseland]

On Monday 19 Mar 2012 22:37:05 Marco Schulze wrote:
 On 19-03-2012 18:56, Marco Schulze wrote:
  On 19-03-2012 16:42, Matthew Toseland wrote:
  PrintWriter (System.err) busy-loops. :( It is probably possible to 
  get the underlying OutputStream though.
  Will take a look at it.
  From what I found after a quick googling, full disk errors do throw an 
 IOException, but is silently ignored by various OutputStream subclasses 
 (except for write(byte[])). No mention of any busy-loop, however.

I am speaking from experience. write() is supposed to either succeed or throw. 
PrintWriter busy-loops on disk full when stderr is redirected to a file. Feel 
free to test it, it may be that it doesn't happen with modern JVMs. But it's 
unacceptable.

Usually when you see this sort of convoluted stuff, there is a reason for it. 
Any solution that simplifies it and makes it more elegant must address all 
the problems that caused the complexity in the first place! If it doesn't the 
various patches will just be re-added, wasting everyone's time.


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 Monday 19 Mar 2012 21:56:42 Marco Schulze wrote:
 On 19-03-2012 16:42, Matthew Toseland wrote:
  No it doesn't. We need to be able to filter *by class name*, not just 
  globally. I agree that in theory the if(logMINOR) is optional if the 
  message is static though; I guess the JVM is fast enough that this won't 
  cost us any cycles?
 
  However, the minimum form of the boilerplate code is only:
 
  static {
  volatile boolean logMINOR;
  volatile boolean logDEBUG;
  Logger.registerClass(Blah.class);
  }
 Fred source tree (@master) contains 1012 *.java files. Even if 
 conservatively assuming  that only 50% of those classes contain this 
 snippet, and that they all use this minimal form, we have 2530 LoC for 
 boilerplate code alone. Plus, 3379 hits to either logMINOR or logDEBUG.
 
 That's a lot of code and memory use just to decide if a message is to be 
 logged or not. (Yes, speed. See below)
 
  Hmm, maybe. Something like s[n]printf even - log(request %u rejected by 
  %o, requestID, peer) ??? Might be clearer code? Lot of work to change it 
  though - and fractionally lower runtime performance than the if(). 
  Unfortunately java doesn't have macros - but even if it did we'd like to be 
  able to turn it on at runtime.
 I was thinking in something along the lines of Python's print() - if the 
 message is to be logged:
 
 Logger.info(This: , this, , and that: , this.that)
 
 is completely equivalent to:
 
 Logger.info(This:  + this + , and that:  + this.that)
 
 If the message is discarded, the overhead is a function call + cost of 
 filtering (most likely a simple table lookup and two int comparisons in 
 the worst case).
 
 If you'd like a strict comparison between the overhead of using an if, 
 against the overhead of a function call, I ran three simple test cases:
 
 - Call an empty function;
 - Test a boolean and then call an empty function, with the boolean set 
 to either true or false.
 
 The test case was inside a for loop, repeating for about 2 billion 
 times. The test was run thrice, with only milliseconds of difference 
 between runs. More importantly, JIT was disabled through -Xint.
 
 Function call: ~31 seconds
 Test + call: ~33 seconds
 Failed test: ~23 seconds
 
 So yes, in my machine, using an if saves 7 seconds over 2 billion best 
 case tests. That's ~3,26 nanoseconds saved per test - an insignificant 
 microptimization.
 
 If JIT is enabled, it could be argued that it's easier for the JVM to 
 perform optimizations based on a single boolean, than on multiple 
 volatile booleans.
 
  PrintWriter (System.err) busy-loops. :( It is probably possible to get the 
  underlying OutputStream though.
 Will take a look at it.
 
  Yes. There is no reason to have each and every thread wait on disk I/O 
  (whether this is cached or not), and furthermore this will lead to 
  locking/concurrency problems. We get best performance by writing off 
  thread, and we can then have that thread dump excess log messages if it 
  can't keep up, avoiding blocking; or if something has to block, it's that 
  thread and no other; and it can also handle log rotation cleanly. And even 
  more importantly, we can keep lock contention to an absolute minimum, so 
  other threads logging data create a byte[] and then lock only to add it to 
  a queue (and delete surplus from the other end if necessary), which takes 
  insignificant time.
 
  All of this stuff is in FileLoggerHook.java.
 Synchronization is the reason every thread should wait. If the log is 
 always flushed and fred crashes, you know exactly where the last good 
 checkpoint was before the crash. If the log is buffered (or 
 asynchronous), the thread may be miles ahead from the last message 
 written to disk, and suddenly you have no idea where to look for the 
 bug. Shotgun debugging indeed.
 
 Granted, if you want to generate lots of traces and debug data, it is 
 desirable to churn out data at the highest rate possible. Possibly a 
 configuration variable? Something like 'logger.mode = safe' (sync + 
 flush) and 'logger.mode = unsafe' (async + buffered)?
 
 Now, I'd wager the cost of maintaining a cache of log messages far 
 surpass the cost of generating them in the first place except for very 
 costly messages regenerated sparingly (or not at all). I haven't seen 
 the current implementation, so there might exist some trick I'm failing 
 to grasp.
 
  I beg to differ. This shouldn't happen in normal use anyway. It's a message 
  to devs doing shotgun debugging that they need a narrower filter (or faster 
  disks!). We do indicate when stuff has been dropped.
 Indication is no substitute for missing data. Speed doesn't really 
 matter if you lose that critical message.
 
  Would that be solved by renaming?
 Since most people are used to DEBUG and INFO levels, their use becomes 
 apparent.
 
  Both. When doing shotgun debugging a dev needs to be able to search by 
  class name, this is why we log(this, ...), and even more 

[freenet-dev] Logging in Fred

[Marco Schulze]

How often does what happen?

On 19-03-2012 20:21, Martin Nyhus wrote:
> On Monday 19. March 2012 22:56:42 Marco Schulze wrote:
>> Synchronization is the reason every thread should wait. If the log is
>> always flushed and fred crashes, you know exactly where the last good
>> checkpoint was before the crash. If the log is buffered (or
>> asynchronous), the thread may be miles ahead from the last message
>> written to disk, and suddenly you have no idea where to look for the
>> bug. Shotgun debugging indeed.
> How often does this actually happen? Considering the performance penalty it
> has to fix a very real problem IMHO, especially since having logging change
> how the code behaves in such a dramatic way will make debugging anything that
> depends on timing that much harder.
> ___
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

[freenet-dev] Logging in Fred

[Marco Schulze]

Never worked with aspects. Could you provide some snippets?

On 19-03-2012 09:52, Nicolas Hernandez wrote:
> Hello,
>
> It is really difficult to have a complete log system working. One 
> solution is to use aspects.
>
> Is this a good idea ?
>
> - Nicolas Hernandez
> a-n - aleph-networks
> /associ?/
> http://www.aleph-networks.com
>
>
>
>
> On Mon, Mar 19, 2012 at 12:40 AM, Marco Schulze 
> mailto:marco.c.schulze at gmail.com>> wrote:
>
> One thing has been bothering me: those 'if (logMINOR)
> Logger.minor(...', and the mess that logging is inside fred. I've
> written a very simple replacement for Logger + associated classes
> with the following changes:
>
> - Log level (renamed to severity) filtering is done by Logging.log();
> - Specific writer classes are replaced by a simple OutputStream,
> which defaults to System.err. Formatting is also unified;
> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG
> and TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
> - No logging method accepts an Object parameter - hashCode() is
> not exactly useful.
>
> Additionally, log rotation will be moved outside (possibly inside
> Node).
>
> Currently, the log format is '\t'.
> ___
> 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
-- next part --
An HTML attachment was scrubbed...
URL: 

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Monday 19 Mar 2012 12:17:51 Marco Schulze wrote:
> On 18-03-2012 21:50, Matthew Toseland wrote:
> > On Sunday 18 Mar 2012 23:40:44 Marco Schulze wrote:
> >> One thing has been bothering me: those 'if (logMINOR) Logger.minor(...',
> >> and the mess that logging is inside fred. I've written a very simple
> >> replacement for Logger + associated classes with the following changes:
> > You're not using the java logging API?
> First thing I thought, but the Java logging mechanisms are complex (more 
> LoC), at least compared to what I have now. It also lacks those cute 
> error()/debug() methods, so a wrapper would be needed anyway.
> 
> > The if(logMINOR) is *ABSOLUTELY VITAL* for performance. You simply cannot 
> > get rid of it. Generating the strings costs significantly more CPU than the 
> > rest of what Freenet does put together.
> In most cases I've seen so far, either the message is constant, or is 
> interpolated with one or two variables. In those cases where building a 
> message to be logged is actually expensive, directly checking the logger 
> state (Logger.min_severity) saves that contrived prolog used to setup 
> logMINOR and logDEBUG.

No it doesn't. We need to be able to filter *by class name*, not just globally. 
I agree that in theory the if(logMINOR) is optional if the message is static 
though; I guess the JVM is fast enough that this won't cost us any cycles?

However, the minimum form of the boilerplate code is only:

static {
volatile boolean logMINOR;
volatile boolean logDEBUG;
Logger.registerClass(Blah.class);
}
> 
> If string building is really slow (possibly because some object's 
> toString() is going wild), logging methods can be changed to something 
> like: public void Logger.info(Object... objs), and the final string 
> would only be built by the logger if it would actually use it.

Hmm, maybe. Something like s[n]printf even - log("request %u rejected by %o", 
requestID, peer) ??? Might be clearer code? Lot of work to change it though - 
and fractionally lower runtime performance than the if(). Unfortunately java 
doesn't have macros - but even if it did we'd like to be able to turn it on at 
runtime.
> 
> >> - Log level (renamed to severity) filtering is done by Logging.log();
> > Feel free to rename it. I don't see much point though unless you are trying 
> > to use a standard API, which *may* be a good idea.
> No special reason for the change, I just though Logger.Severity sounded 
> better than Logger.LogLevel.
> 
> >> - Specific writer classes are replaced by a simple OutputStream, which
> >> defaults to System.err. Formatting is also unified;
> > Very bad idea. There are many excellent reasons for the complexity that is 
> > FileLoggerHook. One is that if System.err is blocked (e.g. a full disk), 
> > everything grinds to a halt.
> Doesn't write() throw an IOException when the disk is full?

PrintWriter (System.err) busy-loops. :( It is probably possible to get the 
underlying OutputStream though.
> 
> > Adequate caching is also essential, and I'm not certain whether there are 
> > locking issues;
> You mean, caching of log messages? Could you elaborate?

Yes. There is no reason to have each and every thread wait on disk I/O (whether 
this is cached or not), and furthermore this will lead to locking/concurrency 
problems. We get best performance by writing off thread, and we can then have 
that thread dump excess log messages if it can't keep up, avoiding blocking; or 
if something has to block, it's that thread and no other; and it can also 
handle log rotation cleanly. And even more importantly, we can keep lock 
contention to an absolute minimum, so other threads logging data create a 
byte[] and then lock only to add it to a queue (and delete surplus from the 
other end if necessary), which takes insignificant time.

All of this stuff is in FileLoggerHook.java.
> 
> > and dropping log lines when we can't keep up rather than just slowing down 
> > the rest of the node is a good thing.
> Sorry, but I heavily disagree with you here. Not only dropping messages 
> makes logs misleading, the output stream should either be unbuffered or 
> flushed after every message. If everything is slowing down because of 
> this, it is either expected (DEBUG or TRACE messages are written), or 
> fred is logging too much above the default INFO threshold.

I beg to differ. This shouldn't happen in normal use anyway. It's a message to 
devs doing shotgun debugging that they need a narrower filter (or faster 
disks!). We do indicate when stuff has been dropped.
> 
> >> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and
> >> TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
> > Using the standard classes is fine by me.
> The biggest problem is that MINOR and NORMAL aren't being used the same 
> way by all classes, and their use isn't exactly clear.

Would that be solved by renaming?
> 
> >> - No logging method accepts an Object 

[freenet-dev] Logging in Fred

[Marco Schulze]

On 19-03-2012 18:56, Marco Schulze wrote:
> On 19-03-2012 16:42, Matthew Toseland wrote:
>> PrintWriter (System.err) busy-loops. :( It is probably possible to 
>> get the underlying OutputStream though.
> Will take a look at it.
 From what I found after a quick googling, full disk errors do throw an 
IOException, but is silently ignored by various OutputStream subclasses 
(except for write(byte[])). No mention of any busy-loop, however.

[freenet-dev] Logging in Fred

[Marco Schulze]

On 19-03-2012 16:42, Matthew Toseland wrote:
> No it doesn't. We need to be able to filter *by class name*, not just 
> globally. I agree that in theory the if(logMINOR) is optional if the message 
> is static though; I guess the JVM is fast enough that this won't cost us any 
> cycles?
>
> However, the minimum form of the boilerplate code is only:
>
> static {
>   volatile boolean logMINOR;
>   volatile boolean logDEBUG;
>   Logger.registerClass(Blah.class);
> }
Fred source tree (@master) contains 1012 *.java files. Even if 
conservatively assuming  that only 50% of those classes contain this 
snippet, and that they all use this minimal form, we have 2530 LoC for 
boilerplate code alone. Plus, 3379 hits to either logMINOR or logDEBUG.

That's a lot of code and memory use just to decide if a message is to be 
logged or not. (Yes, speed. See below)

> Hmm, maybe. Something like s[n]printf even - log("request %u rejected by %o", 
> requestID, peer) ??? Might be clearer code? Lot of work to change it though - 
> and fractionally lower runtime performance than the if(). Unfortunately java 
> doesn't have macros - but even if it did we'd like to be able to turn it on 
> at runtime.
I was thinking in something along the lines of Python's print() - if the 
message is to be logged:

Logger.info("This: ", this, ", and that: ", this.that)

is completely equivalent to:

Logger.info("This: " + this + ", and that: " + this.that)

If the message is discarded, the overhead is a function call + cost of 
filtering (most likely a simple table lookup and two int comparisons in 
the worst case).

If you'd like a strict comparison between the overhead of using an if, 
against the overhead of a function call, I ran three simple test cases:

- Call an empty function;
- Test a boolean and then call an empty function, with the boolean set 
to either true or false.

The test case was inside a for loop, repeating for about 2 billion 
times. The test was run thrice, with only milliseconds of difference 
between runs. More importantly, JIT was disabled through -Xint.

Function call: ~31 seconds
Test + call: ~33 seconds
Failed test: ~23 seconds

So yes, in my machine, using an if saves 7 seconds over 2 billion best 
case tests. That's ~3,26 nanoseconds saved per test - an insignificant 
microptimization.

If JIT is enabled, it could be argued that it's easier for the JVM to 
perform optimizations based on a single boolean, than on multiple 
volatile booleans.

> PrintWriter (System.err) busy-loops. :( It is probably possible to get the 
> underlying OutputStream though.
Will take a look at it.

> Yes. There is no reason to have each and every thread wait on disk I/O 
> (whether this is cached or not), and furthermore this will lead to 
> locking/concurrency problems. We get best performance by writing off thread, 
> and we can then have that thread dump excess log messages if it can't keep 
> up, avoiding blocking; or if something has to block, it's that thread and no 
> other; and it can also handle log rotation cleanly. And even more 
> importantly, we can keep lock contention to an absolute minimum, so other 
> threads logging data create a byte[] and then lock only to add it to a queue 
> (and delete surplus from the other end if necessary), which takes 
> insignificant time.
>
> All of this stuff is in FileLoggerHook.java.
Synchronization is the reason every thread should wait. If the log is 
always flushed and fred crashes, you know exactly where the last good 
checkpoint was before the crash. If the log is buffered (or 
asynchronous), the thread may be miles ahead from the last message 
written to disk, and suddenly you have no idea where to look for the 
bug. Shotgun debugging indeed.

Granted, if you want to generate lots of traces and debug data, it is 
desirable to churn out data at the highest rate possible. Possibly a 
configuration variable? Something like 'logger.mode = safe' (sync + 
flush) and 'logger.mode = unsafe' (async + buffered)?

Now, I'd wager the cost of maintaining a cache of log messages far 
surpass the cost of generating them in the first place except for very 
costly messages regenerated sparingly (or not at all). I haven't seen 
the current implementation, so there might exist some trick I'm failing 
to grasp.

> I beg to differ. This shouldn't happen in normal use anyway. It's a message 
> to devs doing shotgun debugging that they need a narrower filter (or faster 
> disks!). We do indicate when stuff has been dropped.
Indication is no substitute for missing data. Speed doesn't really 
matter if you lose that critical message.

> Would that be solved by renaming?
Since most people are used to DEBUG and INFO levels, their use becomes 
apparent.

> Both. When doing shotgun debugging a dev needs to be able to search by class 
> name, this is why we log(this, ...), and even more importantly they need to 
> be able to identify which classes to log properly.
Right, but wouldn't the use of call 

[freenet-dev] Logging in Fred

[Nicolas Hernandez]

Hello,

It is really difficult to have a complete log system working. One solution
is to use aspects.

Is this a good idea ?

- Nicolas Hernandez
a-n - aleph-networks
*associ?*
http://www.aleph-networks.com




On Mon, Mar 19, 2012 at 12:40 AM, Marco Schulze
wrote:

> One thing has been bothering me: those 'if (logMINOR) Logger.minor(...',
> and the mess that logging is inside fred. I've written a very simple
> replacement for Logger + associated classes with the following changes:
>
> - Log level (renamed to severity) filtering is done by Logging.log();
> - Specific writer classes are replaced by a simple OutputStream, which
> defaults to System.err. Formatting is also unified;
> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and
> TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
> - No logging method accepts an Object parameter - hashCode() is not
> exactly useful.
>
> Additionally, log rotation will be moved outside (possibly inside Node).
>
> Currently, the log format is '\t'.
> __**_
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.**org/cgi-bin/mailman/listinfo/**devl
>
-- next part --
An HTML attachment was scrubbed...
URL: 

[freenet-dev] Logging in Fred

[Marco Schulze]

On 18-03-2012 21:50, Matthew Toseland wrote:
> On Sunday 18 Mar 2012 23:40:44 Marco Schulze wrote:
>> One thing has been bothering me: those 'if (logMINOR) Logger.minor(...',
>> and the mess that logging is inside fred. I've written a very simple
>> replacement for Logger + associated classes with the following changes:
> You're not using the java logging API?
First thing I thought, but the Java logging mechanisms are complex (more 
LoC), at least compared to what I have now. It also lacks those cute 
error()/debug() methods, so a wrapper would be needed anyway.

> The if(logMINOR) is *ABSOLUTELY VITAL* for performance. You simply cannot get 
> rid of it. Generating the strings costs significantly more CPU than the rest 
> of what Freenet does put together.
In most cases I've seen so far, either the message is constant, or is 
interpolated with one or two variables. In those cases where building a 
message to be logged is actually expensive, directly checking the logger 
state (Logger.min_severity) saves that contrived prolog used to setup 
logMINOR and logDEBUG.

If string building is really slow (possibly because some object's 
toString() is going wild), logging methods can be changed to something 
like: public void Logger.info(Object... objs), and the final string 
would only be built by the logger if it would actually use it.

>> - Log level (renamed to severity) filtering is done by Logging.log();
> Feel free to rename it. I don't see much point though unless you are trying 
> to use a standard API, which *may* be a good idea.
No special reason for the change, I just though Logger.Severity sounded 
better than Logger.LogLevel.

>> - Specific writer classes are replaced by a simple OutputStream, which
>> defaults to System.err. Formatting is also unified;
> Very bad idea. There are many excellent reasons for the complexity that is 
> FileLoggerHook. One is that if System.err is blocked (e.g. a full disk), 
> everything grinds to a halt.
Doesn't write() throw an IOException when the disk is full?

> Adequate caching is also essential, and I'm not certain whether there are 
> locking issues;
You mean, caching of log messages? Could you elaborate?

> and dropping log lines when we can't keep up rather than just slowing down 
> the rest of the node is a good thing.
Sorry, but I heavily disagree with you here. Not only dropping messages 
makes logs misleading, the output stream should either be unbuffered or 
flushed after every message. If everything is slowing down because of 
this, it is either expected (DEBUG or TRACE messages are written), or 
fred is logging too much above the default INFO threshold.

>> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and
>> TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
> Using the standard classes is fine by me.
The biggest problem is that MINOR and NORMAL aren't being used the same 
way by all classes, and their use isn't exactly clear.

>> - No logging method accepts an Object parameter - hashCode() is not
>> exactly useful.
> We're not after the hashcode, we're after the class name. We need to be able 
> to filter by it, and that is essential.
The problem is disambiguation, or per-object log threshold?

>> Additionally, log rotation will be moved outside (possibly inside Node).
> Not a good idea, for reasons of locking, file handle handling, the fact that 
> you can't rename a file that is open on Windows ...
I see. A LogRotator would solve it then.

> There are GOOD REASONS for all the complexity, but feel free to tinker with 
> the API, or give specific arguments other than "this is all so complicated it 
> *ought to* be possible to do something radically simpler".
Not that it *ought to be* simpler, I just think current requirements are 
a bit exaggerated.

>> Currently, the log format is '\t'.
> We need the timestamp, in a great many cases.
In my todo list. Which object keeps track of uptime?

>
>
> ___
> Devl mailing list
> Devl at freenetproject.org
> https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
-- next part --
An HTML attachment was scrubbed...
URL: 

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Monday 19 Mar 2012 00:50:33 Matthew Toseland wrote:
> On Sunday 18 Mar 2012 23:40:44 Marco Schulze wrote:
...
> > - No logging method accepts an Object parameter - hashCode() is not 
> > exactly useful.
> 
> We're not after the hashcode, we're after the class name. We need to be able 
> to filter by it, and that is essential.

Oh, now I see what you mean. Including the object in the generated string is 
quite often important when you are tracing a sequence of events when something 
strange has happened. For the same reason that, at the lowest level of 
debugging logging, it is often necessary to include request UID's.
-- 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: 

[freenet-dev] Logging in Fred

[Matthew Toseland]

On Sunday 18 Mar 2012 23:40:44 Marco Schulze wrote:
> One thing has been bothering me: those 'if (logMINOR) Logger.minor(...', 
> and the mess that logging is inside fred. I've written a very simple 
> replacement for Logger + associated classes with the following changes:

You're not using the java logging API?

The if(logMINOR) is *ABSOLUTELY VITAL* for performance. You simply cannot get 
rid of it. Generating the strings costs significantly more CPU than the rest of 
what Freenet does put together.
> 
> - Log level (renamed to severity) filtering is done by Logging.log();

Feel free to rename it. I don't see much point though unless you are trying to 
use a standard API, which *may* be a good idea.

> - Specific writer classes are replaced by a simple OutputStream, which 
> defaults to System.err. Formatting is also unified;

Very bad idea. There are many excellent reasons for the complexity that is 
FileLoggerHook. One is that if System.err is blocked (e.g. a full disk), 
everything grinds to a halt. Adequate caching is also essential, and I'm not 
certain whether there are locking issues; and dropping log lines when we can't 
keep up rather than just slowing down the rest of the node is a good thing.

> - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and 
> TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;

Using the standard classes is fine by me.

> - No logging method accepts an Object parameter - hashCode() is not 
> exactly useful.

We're not after the hashcode, we're after the class name. We need to be able to 
filter by it, and that is essential.
> 
> Additionally, log rotation will be moved outside (possibly inside Node).

Not a good idea, for reasons of locking, file handle handling, the fact that 
you can't rename a file that is open on Windows ... There are GOOD REASONS for 
all the complexity, but feel free to tinker with the API, or give specific 
arguments other than "this is all so complicated it *ought to* be possible to 
do something radically simpler".
> 
> Currently, the log format is '\t'.

We need the timestamp, in a great many cases.
-- 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: 

Re: [freenet-dev] Logging in Fred

[Nicolas Hernandez]

Hello,

It is really difficult to have a complete log system working. One solution
is to use aspects.

Is this a good idea ?

- Nicolas Hernandez
a-n - aleph-networks
*associé*
http://www.aleph-networks.com




On Mon, Mar 19, 2012 at 12:40 AM, Marco Schulze
marco.c.schu...@gmail.comwrote:

 One thing has been bothering me: those 'if (logMINOR) Logger.minor(...',
 and the mess that logging is inside fred. I've written a very simple
 replacement for Logger + associated classes with the following changes:

 - Log level (renamed to severity) filtering is done by Logging.log();
 - Specific writer classes are replaced by a simple OutputStream, which
 defaults to System.err. Formatting is also unified;
 - Severity cases are broadened (FATAL, ERROR, WARNING, INFO, DEBUG and
 TRACE), MINOR is mapped to DEBUG, and NORMAL is mapped to INFO;
 - No logging method accepts an Object parameter - hashCode() is not
 exactly useful.

 Additionally, log rotation will be moved outside (possibly inside Node).

 Currently, the log format is 'severity\tmessage'.
 __**_
 Devl mailing list
 Devl@freenetproject.org
 https://emu.freenetproject.**org/cgi-bin/mailman/listinfo/**devlhttps://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl

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