RFR: 8149383: Convert TraceBiasedLocking to Unified Logging

[Kim Barrett]

> On Feb 16, 2016, at 4:16 PM, Daniel D. Daugherty <daniel.daugherty at oracle.com> wrote:
> src/share/vm/runtime/biasedLocking.cpp
>    (old) L165     tty->print_cr("Revoking bias of object " INTPTR_FORMAT " , mark " INTPTR_FORMAT " , type %s , prototype header " INTPTR_FORMAT " , allow rebias %d , requesting thread " INTPTR_FORMAT,
>    (old) L166                   p2i((void *)obj), (intptr_t) mark, obj->klass()->external_name(), (intptr_t) obj->klass()->prototype_header(), (allow_rebias ? 1 : 0), (intptr_t) requesting_thread);
> 
>    (new)
> 163   if (!is_bulk) {
> 164     ResourceMark rm;
> 165     log_info(biasedlocking)("Revoking bias of object " INTPTR_FORMAT " , mark "
> 166                             INTPTR_FORMAT " , type %s , prototype header " INTPTR_FORMAT
> 167                             " , allow rebias %d , requesting thread " INTPTR_FORMAT,
> 168                             p2i((void *)obj),
> 169                             (intptr_t) mark,
> 170 obj->klass()->external_name(),
> 171                             (intptr_t) obj->klass()->prototype_header(),
> 172                             (allow_rebias ? 1 : 0),
> 173                             (intptr_t) requesting_thread);
> 174   } else {
> 175     ResourceMark rm;
> 176     log_trace(biasedlocking)("Revoking bias of object " INTPTR_FORMAT " , mark "
> 177                              INTPTR_FORMAT " , type %s , prototype header " INTPTR_FORMAT
> 178                              " , allow rebias %d , requesting thread " INTPTR_FORMAT,
> 179                              p2i((void *)obj),
> 180                              (intptr_t) mark,
> 181 obj->klass()->external_name(),
> 182                              (intptr_t) obj->klass()->prototype_header(),
> 183                              (allow_rebias ? 1 : 0),
> 184                              (intptr_t) requesting_thread);
> 185   }
>        Originally I missed the difference between "log_info" and
>        "log_trace". So "log_trace" is taking the place of the
>        Verbose option in this logging situation. Wow!
> 
>        I really don't like the duplication, but if I remember correctly
>        these are macros so we really can't do something like function
>        pointers or some other trick here. Ouch! This duplication pattern
>        is repeated in several places where the old logging was conditional
>        on two different option variables and a biased locking operational
>        state variable (is_bulk).
> 
>        I suppose the logging framework doesn't have an API that says
>        to log at different levels based on a parameter. Something like:
> 
>        log_info_or_trace(log_to /* true logs at 'info' level and
>                                    false logs at 'trace' level */, ...);
> 
>        would do it, but it's an API nightmare. Sigh…

I had a similar problem with figuring out what the new code was doing,
and ended up resorting to a character by character diff of the two
logging expressions.

Here's a way I think one might remove the duplication (not tested, may
have syntax errors):

  if (log_is_enabled(Info, biasedlocking)
      || (is_bulk && log_is_enabled(Trace, biasedlocking))) {
    LogHandle(startuptime) log;
    void (*writer)(const char* fmt, ...) ATTRIBUTE_PRINTF(1, 2) =
      is_bulk ? log.write<LogLevel::Trace> : log.write<LogLevel::Info>;
    writer("...", ... fmt args ...);
  }

I haven't looked at enough logging uses to know whether this sort of
thing is sufficiently common to warrant further packaging.