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 stack + reflection be cleaner for
the caller? Yes, performance impact. I will measure this later, if it's
even possible.
For the per-class filtering, I think a HashTable<String, Severity>
populated at init should solve the problem cleanly:
if severity < min_severity or if caller class is in table and severity <
table_severity
return
do_log
Performance hit should be negligible.
Currently this is handled in FileLoggerHook like everything else. Whatever
happens will need to be closely linked to the code that actually does the
writing for several reasons:
1. We need to do size-based rotation sometimes, especially with heavy log
settings.
2. On Windows, we cannot rename a file until we have closed it.
3. It's easier to ensure that everything goes to one log or another if we just
have the thread doing the writing close it and then open another one.
Figured as much. Inside Logger it is.
You can get it from Node IIRC? Not sure offhand. But have a look at the current
code, in FileLoggerHook.java. No doubt it can be tidied up but it does at least
meet all our requirements.
Will take a look. The format will possibly be: '[<uptime>] <thread_id>
<severity> <class> <message>'. I might put the message on the next line
with a bit of indentation if this format turns out to be too ugly.
_______________________________________________
Devl mailing list
[email protected]
https://emu.freenetproject.org/cgi-bin/mailman/listinfo/devl
