RFR: 8141211: Convert TraceExceptions to Unified Logging

[Thomas Stüfe]

Hi John,

On Fri, Dec 18, 2015 at 5:13 AM, John Rose <john.r.rose at oracle.com> wrote:

> On Dec 17, 2015, at 11:39 AM, Thomas Stüfe <thomas.stuefe at gmail.com>
> wrote:
>
>
> When we print it, we precede the multiline message with the decorators in
> the first line and indent the rest of the lines to the same position:
>
> [time][pid][tid]  hallo1
>                   hallo2
>                   hallo3
>
> This approach has served us quite well. We decided against locking done by
> the caller because users to minimize the danger of deadlocks.
>
>
> I agree that buffering is a better approach than locking.
> In the old logging system, large amounts of logging are
> produced by the compiler threads, and is buffered separately
> per thread.  Smaller amounts are dumped into a common "tty"
> stream, which is available only to one thread at a time.
>
> The effect of the ttyLocker is to ensure unbroken multi-line output.
> It doesn't intrinsically need to block other writers.
>
> Buffering is a great way to keep integrity without blocking.
> This could be introduced into the new UL framework like this:
>
>    LogHandle(logging) log0;
>    if (log0.is_debug()) {
>      LogBuffer log(log0);
>      int result = compute_debug_result();
>      log.debug("result = %d", result).trace(" tracing info");
>      obj->print_on(log.debug_stream());
>    }
>
> Or just:
>    { LogBuffer(logging) log;
>      if (log.is_debug()) {
>        int result = compute_debug_result();
>        log.debug("result = %d", result).trace(" tracing info");
>        obj->print_on(log.debug_stream());
>    } }
>
> The "log" is a separate object from "log0" which has the same API,
> and buffers all output before flushing to the underlying "log0".
> (The RAII destructor flushes.  Maybe it also has explicit flush.)
>
> Note that "log" has true object state, whereas "log0" is just a
> bundle of static methods.
>
>
This is almost exactly what we did.

Note that this approach is subtly different to ttyLocker in that is only
affects your own logging calls. If the code section in which you assemble
the LogBuffer were larger and interspersed with other logging calls to
other tags (e.g. in functions you call), those other logging calls would go
on unmolested. I find this actually better.

Perhaps LogBuffer could be economically used inside the Log methods
> themselves; currently they do buffering equivalent to what LogBuffer
> does, but using random logic (see uses of constant LogBufferSize).
> Basically, wherever a "printf" format is used with Log API points,
> there is already a hidden buffer (it resizes at most once, since
> there is just one printf call).
>
> Optional parameters to LogBuffer would control behavior related
> to (possibly) splitting very large outputs (like PrintAssembly),
> or buffering to files (using the rotating archive mechanism).
>
> This would provide a road to replacing the existing LogCompilation
> implementation, which has thread-local logs buffered to temp files.
>
> I.e., a long-lived, thread-local, file-backed LogBuffer would allow
> a compiler thread to produce gigabytes of output, all properly
> sequenced, with no interruptions and no blocking of other logs.
>
> Having a separate layer "LogBuffer" for keeping lines together
> will not penalize users of the underlying line-at-time facility.
>
> — John
>

Note that you also could hide the buffer management completely in UL and
just expose a database-like commit semantic, coupled with a thread-local
buffer. Like this:

log.start_multiline_message();
log..
log..
log..
log.commit_multiline_message();

All log calls between start_multiline_message() and
commit_multiline_message() would not go to the normal destination but to a
temporary buffer which is anchored in native thread local storage (not
necessarily Thread::current() as that may or may not exist). In
commit_multiline_message(), this buffer then is flushed to the real
destination.

Advantage:
- You keep the normal logging calls as much as possible
- this is very similar to the already existing ttyLocker semantic
Disadvantage:
- As said earlier, this affects all logging calls inbetween
start_multiline_message() and commit_multiline_message(), not just yours

Neither advantage nor disadvantage: you keep the TLS-anchored buffer
around. This is nice because next time you log you save an allocation call,
but needs to be managed to not be a memory drain. For instance, in
commit_multiline_message() the buffer should be cut back to certain maximum
size.

I am unsure which approach I find better - the one where the caller creates
an explicit buffer or the one where the logging system manages the buffer.
Any would be fine for us.

Kind Regards, Thomas
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://mail.openjdk.java.net/pipermail/serviceability-dev/attachments/20151218/27a9a495/attachment.html>