Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8281195

Mistakenly used logging causes significant overhead in interpreter

XMLWordPrintable

    • Icon: Enhancement Enhancement
    • Resolution: Fixed
    • Icon: P4 P4
    • 19
    • 11, 17, 18, 19
    • hotspot
    • b10
    • generic
    • generic

      It looks like the function

      bool OopMapCacheEntry::verify_mask(CellTypeState* vars, CellTypeState* stack, int max_locals, int stack_top) {
        . . .
        Log(interpreter, oopmap) logv;
        LogStream st(logv.trace());

        st.print("Locals (%d): ", max_locals);
        for(int i = 0; i < max_locals; i++) {
          . . .
          st.print("%d", v1 ? 1 : 0);
        }
        st.cr();

        st.print("Stack (%d): ", stack_top);
        for(int j = 0; j < stack_top; j++) {
          . . .
          st.print("%d", v1 ? 1 : 0);
        }
        st.cr();
        return true;
      }

      was written in wrong belief that if logging is disabled for specific target than associated LogStream::print() does noting. That is a mistake. At first the control flow goes to outputStream::print() that calls sprintf(), then it goes to LogTagSet::vwrite() that calls vsnprintf(), and only after that in LogTagSet::log() it finds that the list of LogOutput's is empty.

      I developed a kinda of logging improvement when found that resulting log is full of [interpreter,oopmap] messages in spite of the fact that I configured only GC logging (see attached log file). I'd suggest to use regular log_trace() macro that checks the necessity before to generate a log message

        1. 4z.log.2
          42 kB
        2. delta.patch
          4 kB

            apavlyutkin Alexey Pavlyutkin
            apavlyutkin Alexey Pavlyutkin
            Votes:
            0 Vote for this issue
            Watchers:
            4 Start watching this issue

              Created:
              Updated:
              Resolved: