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 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?
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.
>
> >> 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.
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.
>
> > 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.
Unfortunately this is not the case. Arguably I use too much shotgun debugging
(debugging through heavy logging), but sometimes it's the only way to deal with
a problem, due to there being lots of threads and stuff happening over seconds.
>
> >> Currently, the log format is '<severity>\t<message>'.
> > We need the timestamp, in a great many cases.
> In my todo list. Which object keeps track of uptime?
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.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 198 bytes
Desc: This is a digitally signed message part.
URL:
<https://emu.freenetproject.org/pipermail/devl/attachments/20120319/fdbe4962/attachment.pgp>
