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

Unified logging flushing causes GC to be I/O bound

XMLWordPrintable

    • generic
    • generic

      A DESCRIPTION OF THE PROBLEM :
      During our upgrade from 8 to 17, we immediately noticed a significant impact to GC pause times. On investigation, we found that while legacy GC logging was buffered, unified logging flushes to the output on every event. At worst, we've seen services deadlock due to file system issues:

      Thread 4 (Thread 0x7f3ead221640 (LWP 1099) "G1 Main Marker"):
      #0 0x00007f3eaff2ae8d in write () from /lib/x86_64-linux-gnu/libc.so.6
      #1 0x00007f3eafe9d945 in _IO_file_write () from /lib/x86_64-linux-gnu/libc.so.6
      #2 0x00007f3eafe9e33d in _IO_file_xsputn () from /lib/x86_64-linux-gnu/libc.so.6
      #3 0x00007f3eafe896de in ?? () from /lib/x86_64-linux-gnu/libc.so.6
      #4 0x00007f3eaf444cc4 in jio_fprintf () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #5 0x00007f3eaf5335b5 in LogFileStreamOutput::flush() () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #6 0x00007f3eaf53296c in LogFileOutput::write(LogDecorations const&, char const*) () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #7 0x00007f3eaf539b96 in LogTagSet::vwrite(LogLevel::type, char const*, __va_list_tag*) () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #8 0x00007f3eaf265bea in void LogImpl<(LogTag::type)43, (LogTag::type)144, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0, (LogTag::type)0>::write<(LogLevel::type)3>(char const*, ...) () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #9 0x00007f3eaf26ddf1 in G1ConcurrentMark::mark_from_roots() () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #10 0x00007f3eaf275ed7 in G1ConcurrentMarkThread::phase_mark_loop() () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #11 0x00007f3eaf276af8 in G1ConcurrentMarkThread::concurrent_mark_cycle_do() () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #12 0x00007f3eaf276d55 in G1ConcurrentMarkThread::run_service() () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #13 0x00007f3eaf1591ad in ConcurrentGCThread::run() () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #14 0x00007f3eaf93904d in Thread::call_run() () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #15 0x00007f3eaf6bd3b1 in thread_native_entry(Thread*) () from /usr/lib/jvm/zulu-17-amd64/lib/server/libjvm.so
      #16 0x00007f3eafea7b07 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
      #17 0x00007f3eaff3d510 in ?? () from /lib/x86_64-linux-gnu/libc.so.6

      We've since enabled -Xlog:async by default where we can, as it would have been impossible to keep these logs on AWS EBS otherwise. However, we've still had services that don't use our JVM launch tooling impacted by these issues. GC logging is by far the most common use of unified logging, for many the sole reason for using the feature.

      I believe the risk of dropping events is far outweighed by the potential impact to application performance and availability, and buffered writes should be enabled by default.


      CUSTOMER SUBMITTED WORKAROUND :
      Use -Xlog:async

      FREQUENCY : often


            Unassigned Unassigned
            webbuggrp Webbug Group
            Votes:
            0 Vote for this issue
            Watchers:
            7 Start watching this issue

              Created:
              Updated: