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 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.
To answer concisely, and I'm not going to keep on arguing this indefinitely:
1. Performance:
1000 * 2 boolean's is a negligible amount of memory. The reason we check is
because generating the strings is expensive. The reason we check a boolean
rather than calling shouldLog() is that it is way faster. The reason that
boolean is volatile is that then we don't have to lock anything when we call
it. This is born out of profiling work, mostly by Florent. It's not just me
complicating things just for the sake of it.
2. Logger.info(this, "Blah: ", uid, " is ", state)
If you have a scheme for making string generation less expensive that might be
interesting - but there will still be overheads (array allocation/cleanup
[memory churn is actually something of an issue here], autoboxing, above all
lock contention). Your benchmarks don't implement filtering by classname, so
are meaningless.
3. Using a HashMap
This will use more memory than the current situation, but it is negligible
either way. If it is generated globally all at once you need a reliable way to
enumerate all classes - they may not have been loaded yet, and this will need
to be re-run when loading or unloading a plugin. We could do it lazily, but
would need to cleanup when unloading a plugin, and it would increase the worst
case latency. One way to simplify it would be to change the format of the log
filter config - currently it is a list of <classname prefix>:<level>, we could
make it take only actual class names.
However, whatever you do, you end up synchronizing when accessing the HashMap,
and this becomes a major concurrency hotspot. This may be solvable using some
sort of concurrent map structure, although that may have consequences if we are
creating it lazily.
4. Caching is cheap.
Compared to a system call on each log line, caching in fred is really, really
cheap. I think you've more or less conceded the sync vs async issue, which is a
performance no-brainer. Practically speaking debugging doesn't need synchronous
log writing - it just needs it to hit disk within a reasonable (and
configurable at present) period.
5. Dumping messages is bad but a necessary evil.
This only happens when you're logging too much, and can be easily solved by
changing the settings. I normally run a tail --follow=name ... | grep ERROR so
I see errors, including those shown when losing logging data.
6. INFO vs MINOR
I don't mind what we call them, if INFO is the standard we could switch.
7. Stack and reflection.
If you can do it fast then great, maybe there is some uber-cool optimisation
that will make it work. However, I seriously doubt it.
-------------- 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/20120320/24553349/attachment.pgp>
