6941923: RFE: Handling large log files produced by long running Java Applications

Summary: supply optinal flags to realize gc log rotation
Reviewed-by: ysr, jwilhelm

src/share/vm/gc_implementation/shared/concurrentGCThread.cpp

@@ -43,17 +43,6 @@ ConcurrentGCThread::ConcurrentGCThread() :
   _sts.initialize();
 };
 
-void ConcurrentGCThread::stopWorldAndDo(VoidClosure* op) {
-  MutexLockerEx x(Heap_lock,
-                  Mutex::_no_safepoint_check_flag);
-  // warning("CGC: about to try stopping world");
-  SafepointSynchronize::begin();
-  // warning("CGC: successfully stopped world");
-  op->do_void();
-  SafepointSynchronize::end();
-  // warning("CGC: successfully restarted world");
-}
-
 void ConcurrentGCThread::safepoint_synchronize() {
   _sts.suspend_all();
 }

src/share/vm/gc_implementation/shared/concurrentGCThread.hpp

@@ -95,8 +95,6 @@ protected:
   static int set_CGC_flag(int b)           { return _CGC_flag |= b; }
   static int reset_CGC_flag(int b)         { return _CGC_flag &= ~b; }
 
-  void stopWorldAndDo(VoidClosure* op);
-
   // All instances share this one set.
   static SuspendibleThreadSet _sts;
 

src/share/vm/runtime/arguments.cpp

@@ -1680,8 +1680,33 @@ static bool verify_serial_gc_flags() {
           UseParallelGC || UseParallelOldGC));
 }
 
+// check if do gclog rotation
+// +UseGCLogFileRotation is a must,
+// no gc log rotation when log file not supplied or
+// NumberOfGCLogFiles is 0, or GCLogFileSize is 0
+void check_gclog_consistency() {
+  if (UseGCLogFileRotation) {
+    if ((Arguments::gc_log_filename() == NULL) ||
+        (NumberOfGCLogFiles == 0)  ||
+        (GCLogFileSize == 0)) {
+      jio_fprintf(defaultStream::output_stream(),
+                  "To enable GC log rotation, use -Xloggc:<filename> -XX:+UseGCLogRotaion -XX:NumberOfGCLogFiles=<num_of_files> -XX:GCLogFileSize=<num_of_size>\n"
+                  "where num_of_file > 0 and num_of_size > 0\n"
+                  "GC log rotation is turned off\n");
+      UseGCLogFileRotation = false;
+    }
+  }
+
+  if (UseGCLogFileRotation && GCLogFileSize < 8*K) {
+        FLAG_SET_CMDLINE(uintx, GCLogFileSize, 8*K);
+        jio_fprintf(defaultStream::output_stream(),
+                    "GCLogFileSize changed to minimum 8K\n");
+  }
+}
+
 // Check consistency of GC selection
 bool Arguments::check_gc_consistency() {
+  check_gclog_consistency();
   bool status = true;
   // Ensure that the user has not selected conflicting sets
   // of collectors. [Note: this check is merely a user convenience;
@@ -2672,6 +2697,7 @@ SOLARIS_ONLY(
       return JNI_ERR;
     }
   }
+
   // Change the default value for flags  which have different default values
   // when working with older JDKs.
   if (JDK_Version::current().compare_major(6) <= 0 &&

src/share/vm/runtime/atomic.cpp

@@ -83,3 +83,13 @@ unsigned Atomic::cmpxchg(unsigned int exchange_value,
   return (unsigned int)Atomic::cmpxchg((jint)exchange_value, (volatile jint*)dest,
                                        (jint)compare_value);
 }
+
+jlong Atomic::add(jlong    add_value, volatile jlong*    dest) {
+  jlong old = load(dest);
+  jlong new_value = old + add_value;
+  while (old != cmpxchg(new_value, dest, old)) {
+    old = load(dest);
+    new_value = old + add_value;
+  }
+  return old;
+}

src/share/vm/runtime/atomic.hpp

@@ -51,6 +51,8 @@ class Atomic : AllStatic {
   static intptr_t add_ptr(intptr_t add_value, volatile intptr_t* dest);
   static void*    add_ptr(intptr_t add_value, volatile void*     dest);
 
+  static jlong    add    (jlong    add_value, volatile jlong*    dest);
+
   // Atomically increment location
   static void inc    (volatile jint*     dest);
   static void inc_ptr(volatile intptr_t* dest);

src/share/vm/runtime/globals.hpp

@@ -2332,6 +2332,20 @@ class CommandLineFlags {
           "Print diagnostic message when GC is stalled"                     \
           "by JNI critical section")                                        \
                                                                             \
+  /* GC log rotation setting */                                             \
+                                                                            \
+  product(bool, UseGCLogFileRotation, false,                                \
+          "Prevent large gclog file for long running app. "                 \
+          "Requires -Xloggc:<filename>")                                    \
+                                                                            \
+  product(uintx, NumberOfGCLogFiles, 0,                                     \
+          "Number of gclog files in rotation, "                             \
+          "Default: 0, no rotation")                                        \
+                                                                            \
+  product(uintx, GCLogFileSize, 0,                                          \
+          "GC log file size, Default: 0 bytes, no rotation "                \
+          "Only valid with UseGCLogFileRotation")                           \
+                                                                            \
   /* JVMTI heap profiling */                                                \
                                                                             \
   diagnostic(bool, TraceJVMTIObjectTagging, false,                          \

src/share/vm/runtime/safepoint.cpp

@@ -511,6 +511,11 @@ void SafepointSynchronize::do_cleanup_tasks() {
 
   TraceTime t4("sweeping nmethods", TraceSafepointCleanupTime);
   NMethodSweeper::scan_stacks();
+
+  // rotate log files?
+  if (UseGCLogFileRotation) {
+    gclog_or_tty->rotate_log();
+  }
 }
 
 

src/share/vm/utilities/ostream.cpp

@@ -377,6 +377,86 @@ void fdStream::write(const char* s, size_t len) {
   update_position(s, len);
 }
 
+rotatingFileStream::~rotatingFileStream() {
+  if (_file != NULL) {
+    if (_need_close) fclose(_file);
+    _file      = NULL;
+    FREE_C_HEAP_ARRAY(char, _file_name);
+    _file_name = NULL;
+  }
+}
+
+rotatingFileStream::rotatingFileStream(const char* file_name) {
+  _cur_file_num = 0;
+  _bytes_writen = 0L;
+  _file_name = NEW_C_HEAP_ARRAY(char, strlen(file_name)+10);
+  jio_snprintf(_file_name, strlen(file_name)+10, "%s.%d", file_name, _cur_file_num);
+  _file = fopen(_file_name, "w");
+  _need_close = true;
+}
+
+rotatingFileStream::rotatingFileStream(const char* file_name, const char* opentype) {
+  _cur_file_num = 0;
+  _bytes_writen = 0L;
+  _file_name = NEW_C_HEAP_ARRAY(char, strlen(file_name)+10);
+  jio_snprintf(_file_name, strlen(file_name)+10, "%s.%d", file_name, _cur_file_num);
+  _file = fopen(_file_name, opentype);
+  _need_close = true;
+}
+
+void rotatingFileStream::write(const char* s, size_t len) {
+  if (_file != NULL)  {
+    // Make an unused local variable to avoid warning from gcc 4.x compiler.
+    size_t count = fwrite(s, 1, len, _file);
+    Atomic::add((jlong)count, &_bytes_writen);
+  }
+  update_position(s, len);
+}
+
+// rotate_log must be called from VMThread at safepoint. In case need change parameters
+// for gc log rotation from thread other than VMThread, a sub type of VM_Operation
+// should be created and be submitted to VMThread's operation queue. DO NOT call this
+// function directly. Currently, it is safe to rotate log at safepoint through VMThread.
+// That is, no mutator threads and concurrent GC threads run parallel with VMThread to
+// write to gc log file at safepoint. If in future, changes made for mutator threads or
+// concurrent GC threads to run parallel with VMThread at safepoint, write and rotate_log
+// must be synchronized.
+void rotatingFileStream::rotate_log() {
+  if (_bytes_writen < (jlong)GCLogFileSize) return;
+#ifdef ASSERT
+  Thread *thread = Thread::current();
+  assert(thread == NULL ||
+         (thread->is_VM_thread() && SafepointSynchronize::is_at_safepoint()),
+         "Must be VMThread at safepoint");
+#endif
+  if (NumberOfGCLogFiles == 1) {
+    // rotate in same file
+    rewind();
+    _bytes_writen = 0L;
+    return;
+  }
+
+  // rotate file in names file.0, file.1, file.2, ..., file.<MaxGCLogFileNumbers-1>
+  // close current file, rotate to next file
+  if (_file != NULL) {
+    _cur_file_num ++;
+    if (_cur_file_num >= NumberOfGCLogFiles) _cur_file_num = 0;
+    jio_snprintf(_file_name, strlen(Arguments::gc_log_filename()) + 10, "%s.%d",
+             Arguments::gc_log_filename(), _cur_file_num);
+    fclose(_file);
+    _file = NULL;
+  }
+  _file = fopen(_file_name, "w");
+  if (_file != NULL) {
+    _bytes_writen = 0L;
+    _need_close = true;
+  } else {
+    tty->print_cr("failed to open rotation log file %s due to %s\n",
+                  _file_name, strerror(errno));
+    _need_close = false;
+  }
+}
+
 defaultStream* defaultStream::instance = NULL;
 int defaultStream::_output_fd = 1;
 int defaultStream::_error_fd  = 2;
@@ -749,14 +829,17 @@ void ostream_init_log() {
 
   gclog_or_tty = tty; // default to tty
   if (Arguments::gc_log_filename() != NULL) {
-    fileStream * gclog = new(ResourceObj::C_HEAP)
+    fileStream * gclog  = UseGCLogFileRotation ?
+                          new(ResourceObj::C_HEAP)
+                             rotatingFileStream(Arguments::gc_log_filename()) :
+                          new(ResourceObj::C_HEAP)
                              fileStream(Arguments::gc_log_filename());
     if (gclog->is_open()) {
       // now we update the time stamp of the GC log to be synced up
       // with tty.
       gclog->time_stamp().update_to(tty->time_stamp().ticks());
-      gclog_or_tty = gclog;
     }
+    gclog_or_tty = gclog;
   }
 
   // If we haven't lazily initialized the logfile yet, do it now,

src/share/vm/utilities/ostream.hpp

@@ -110,6 +110,7 @@ class outputStream : public ResourceObj {
    // flushing
    virtual void flush() {}
    virtual void write(const char* str, size_t len) = 0;
+   virtual void rotate_log() {} // GC log rotation
    virtual ~outputStream() {}   // close properly on deletion
 
    void dec_cr() { dec(); cr(); }
@@ -117,7 +118,7 @@ class outputStream : public ResourceObj {
 };
 
 // standard output
-                                // ANSI C++ name collision
+// ANSI C++ name collision
 extern outputStream* tty;           // tty output
 extern outputStream* gclog_or_tty;  // stream for gc log if -Xloggc:<f>, or tty
 
@@ -176,6 +177,7 @@ class fileStream : public outputStream {
   FILE* _file;
   bool  _need_close;
  public:
+  fileStream() { _file = NULL; _need_close = false; }
   fileStream(const char* file_name);
   fileStream(const char* file_name, const char* opentype);
   fileStream(FILE* file) { _file = file; _need_close = false; }
@@ -210,6 +212,20 @@ class fdStream : public outputStream {
   void flush() {};
 };
 
+class rotatingFileStream : public fileStream {
+ protected:
+  char*  _file_name;
+  jlong  _bytes_writen;
+  uintx  _cur_file_num;             // current logfile rotation number, from 0 to MaxGCLogFileNumbers-1
+ public:
+  rotatingFileStream(const char* file_name);
+  rotatingFileStream(const char* file_name, const char* opentype);
+  rotatingFileStream(FILE* file) : fileStream(file) {}
+  ~rotatingFileStream();
+  virtual void write(const char* c, size_t len);
+  virtual void rotate_log();
+};
+
 void ostream_init();
 void ostream_init_log();
 void ostream_exit();

test/gc/6941923/test6941923.sh

+##
+## @test @(#)test6941923.sh
+## @bug 6941923 
+## @summary test new added flags for gc log rotation 
+## @author yqi 
+## @run shell test6941923.sh
+##
+
+## skip on windows
+OS=`uname -s`
+case "$OS" in
+  SunOS | Linux )
+    NULL=/dev/null
+    PS=":"
+    FS="/"
+    ;;
+  Windows_* )
+    echo "Test skipped for Windows"
+    exit 0 
+    ;;
+  * )
+    echo "Unrecognized system!"
+    exit 1;
+    ;;
+esac
+
+if [ "${JAVA_HOME}" = "" ]
+then
+  echo "JAVA_HOME not set"
+  exit 0
+fi
+
+$JAVA_HOME/bin/java -version > $NULL 2>&1
+
+if [ $? != 0 ]; then
+  echo "Wrong JAVA_HOME? JAVA_HOME: $JAVA_HOME"
+  exit $?
+fi
+
+# create a small test case
+testname="Test"
+if [ -e ${testname}.java ]; then
+  rm -rf ${testname}.*
+fi
+
+cat >> ${testname}.java << __EOF__
+import java.util.Vector;
+
+public class Test implements Runnable
+{
+  private boolean _should_stop = false;
+
+  public static void main(String[] args) throws Exception {
+
+    long limit = Long.parseLong(args[0]) * 60L * 1000L;   // minutes
+    Test t = new Test();
+    t.set_stop(false);
+    Thread thr = new Thread(t);
+    thr.start();
+
+    long time1 = System.currentTimeMillis();
+    long time2 = System.currentTimeMillis();
+    while (time2 - time1 < limit) {
+      try {
+        Thread.sleep(2000); // 2 seconds
+      }
+      catch(Exception e) {}
+      time2 = System.currentTimeMillis();
+      System.out.print("\r... " + (time2 - time1)/1000 + " seconds");
+    }
+    System.out.println();
+    t.set_stop(true);
+  }
+  public void set_stop(boolean value) { _should_stop = value; }
+  public void run() {
+    int cap = 20000;
+    int fix_size = 2048;
+    int loop = 0;
+    Vector< byte[] > v = new Vector< byte[] >(cap);
+    while(!_should_stop) {
+      byte[] g = new byte[fix_size];
+      v.add(g);
+      loop++;
+      if (loop > cap) {
+         v = null;
+         cap *= 2;
+         if (cap > 80000) cap = 80000;
+         v = new Vector< byte[] >(cap);
+      }
+    }
+  }
+}
+__EOF__
+
+msgsuccess="succeeded"
+msgfail="failed"
+gclogsize="16K"
+filesize=$((16*1024))
+$JAVA_HOME/bin/javac ${testname}.java > $NULL 2>&1
+
+if [ $? != 0 ]; then
+  echo "$JAVA_HOME/bin/javac ${testname}.java $fail"
+  exit -1
+fi
+
+# test for 2 minutes, it will complete circulation of gc log rotation
+tts=2
+logfile="test.log"
+hotspotlog="hotspot.log"
+
+if [ -e $logfile  ]; then
+  rm -rf $logfile
+fi
+
+#also delete $hotspotlog if it exists
+if [ -f $hotspotlog ]; then 
+  rm -rf $hotspotlog
+fi
+
+options="-Xloggc:$logfile -XX:+UseConcMarkSweepGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+UseGCLogFileRotation  -XX:NumberOfGCLogFiles=1 -XX:GCLogFileSize=$gclogsize"
+echo "Test gc log rotation in same file, wait for $tts minutes ...."
+$JAVA_HOME/bin/java $options $testname $tts
+if [ $? != 0 ]; then
+  echo "$msgfail"
+  exit -1
+fi
+
+# rotation file will be $logfile.0 
+if [ -f $logfile.0 ]; then
+  outfilesize=`ls -l $logfile.0 | awk '{print $5 }'`
+  if [ $((outfilesize)) -ge $((filesize)) ]; then
+    echo $msgsuccess
+  else
+    echo $msgfail
+  fi
+else 
+  echo $msgfail
+  exit -1
+fi
+
+# delete log file 
+rm -rf $logfile.0
+if [ -f $hotspotlog ]; then
+  rm -rf $hotspotlog
+fi
+
+#multiple log files
+numoffiles=3
+options="-Xloggc:$logfile -XX:+UseConcMarkSweepGC -XX:+PrintGC -XX:+PrintGCDetails -XX:+UseGCLogFileRotation  -XX:NumberOfGCLogFiles=$numoffiles -XX:GCLogFileSize=$gclogsize"
+echo "Test gc log rotation in $numoffiles files, wait for $tts minutes ...."
+$JAVA_HOME/bin/java $options $testname $tts
+if [ $? != 0 ]; then
+  echo "$msgfail"
+  exit -1
+fi
+
+atleast=0    # at least size of numoffile-1 files >= $gclogsize
+tk=0
+while [ $(($tk)) -lt $(($numoffiles)) ]
+do
+  if [ -f $logfile.$tk ]; then
+    outfilesize=`ls -l $logfile.$tk | awk '{ print $5 }'`
+    if [ $(($outfilesize)) -ge $(($filesize)) ]; then
+      atleast=$((atleast+1))
+    fi
+  fi
+  tk=$((tk+1))
+done
+
+rm -rf $logfile.*
+rm -rf $testname.*
+rm -rf $hotspotlog
+
+if [ $(($atleast)) -ge $(($numoffiles-1)) ]; then
+  echo $msgsuccess
+else
+  echo $msgfail
+  exit -1
+fi