RFR: 8145934: Make ttyLocker equivalent for Unified Logging framework

[John Rose]

On Feb 16, 2016, at 8:32 AM, Marcus Larsson <marcus.larsson at oracle.com> wrote:
> 
> Alternative version where a LogMessage automatically writes its messages when it goes out of scope:
> http://cr.openjdk.java.net/~mlarsson/8145934/webrev.alt/ <http://cr.openjdk.java.net/~mlarsson/8145934/webrev.alt/>


I like this, with the LogMessageBuffer that does the heavy work, and the [Scoped]LogMessage which is the simplest way to use it.

The LogMessageBuffer should have a neutral unallocated state, for use through the LogMessage macro.  I.e., is_c_allocated should be a three-state flag, including 'not allocated at all'.  That way, if you create the thing only to ask 'is_debug' and get a false answer, you won't have done more than a few cycles of work.  Probably the set_prefix operation should be lazy in the same way.

I think the destructor should call a user-callable flush function, something like this:

  ~ScopedLogMessage() { flush(); }
  // in LogMessageBuffer:
  void flush() {
    if (_line_count > 0) {
      _log.write(*this);
      reset();
    }
  }
  void reset() {
     _line_count = 0;
     _message_buffer_size = 0;
  }

It will be rare for user code to want to either flush early or cancel pending output, but when you need it, it should be there.

> I still prefer the first patch though, where messages are neither tied to a particular log, nor automatically written when they go out of scope. Like I've said, the explicit write line makes it easier to read the code.

There's a tradeoff here:  It's easier to read the *logging* code if all the *logging* operations are explicit.  But the point of logging code is to add logging to code that is busy doing *other* operations besides logging.  That's why (I assume) people have been noting that some uses of logging are "intrusive":  The logging logic calls too much attention to itself, and with attention being a limited resource, it takes away attention from the actual algorithm that's being logged about.

The scoped (RAII) log buffer, with automatic write, is the best way I know to reduce the intrusiveness of this auxiliary mechanism.

Of course, I'm interested in finding out what your everyday customers think about it.  (Rachel, Coleen, David, Dan?)

> For comparison I've updated the first suggestion with the guarantee for unwritten messages, as well as cleaning it up a bit by moving the implementation to the .cpp rather than the .hpp.
> Full webrev: http://cr.openjdk.java.net/~mlarsson/8145934/webrev.01/ <http://cr.openjdk.java.net/~mlarsson/8145934/webrev.01/>
> Incremental: http://cr.openjdk.java.net/~mlarsson/8145934/webrev.00-01/ <http://cr.openjdk.java.net/~mlarsson/8145934/webrev.00-01/>
> 
> Let me know what you think.

That option is more intrusive than the RAII buffered log alias.

Separately, the review thread on JDK-8149383 shows a use for LogMessageBuffer to collect a complex log message.  The log message can then be sent down one of two log streams.  Something like:

  if (need_to_log) {
    ResourceMark rm;
    LogMessageBuffer buf;
    buf.write("Revoking bias of object " INTPTR_FORMAT " , mark "
                            INTPTR_FORMAT " , type %s , prototype header " INTPTR_FORMAT
                            " , allow rebias %d , requesting thread " INTPTR_FORMAT,
                            p2i((void *)obj),
                            (intptr_t) mark,
obj->klass()->external_name(),
                            (intptr_t) obj->klass()->prototype_header(),
                            (allow_rebias ? 1 : 0),
                            (intptr_t) requesting_thread);
    if (!is_bulk)
      log_info(biasedlocking).write(buf);
    else
      log_trace(biasedlocking).write(buf);
  }

It is important here (like you pointed out) that the LogMessageBuffer is decoupled from log levels and streams, so that it can be used as a flexible component of logic like this.

But the commonest usage should (IMO) be supported by a scoped auto-writing log alias.

— John