8167190: Remove confusing timestamps from the gc log
authorehelin
Wed, 05 Oct 2016 16:00:10 +0200
changeset 41723 88393c6dd24e
parent 41715 296ff044b943
child 41724 fa9d08eaaa8a
8167190: Remove confusing timestamps from the gc log Reviewed-by: sjohanss, pliden
hotspot/src/share/vm/gc/shared/gcTraceTime.inline.hpp
hotspot/test/gc/logging/TestPrintReferences.java
hotspot/test/native/logging/test_gcTraceTime.cpp
hotspot/test/serviceability/logging/TestLogRotation.java
--- a/hotspot/src/share/vm/gc/shared/gcTraceTime.inline.hpp	Tue Oct 18 09:43:12 2016 +0200
+++ b/hotspot/src/share/vm/gc/shared/gcTraceTime.inline.hpp	Wed Oct 05 16:00:10 2016 +0200
@@ -35,7 +35,6 @@
 #include "prims/jni_md.h"
 #include "utilities/ticks.hpp"
 
-#define LOG_STOP_TIME_FORMAT "(%.3fs, %.3fs) %.3fms"
 #define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M("  SIZE_FORMAT "M)"
 
 inline void GCTraceTimeImpl::log_start(jlong start_counter) {
@@ -46,7 +45,7 @@
     if (_gc_cause != GCCause::_no_gc) {
       out.print(" (%s)", GCCause::to_string(_gc_cause));
     }
-    out.print_cr(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter));
+    out.cr();
   }
 }
 
@@ -71,7 +70,7 @@
     out.print(" " LOG_STOP_HEAP_FORMAT, used_before_m, used_m, capacity_m);
   }
 
-  out.print_cr(" " LOG_STOP_TIME_FORMAT, start_time_in_secs, stop_time_in_secs, duration_in_ms);
+  out.print_cr(" %.3fms", duration_in_ms);
 }
 
 inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) {
@@ -117,7 +116,7 @@
 GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceConcTimeImpl(const char* title) :
   _enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) {
   if (_enabled) {
-    LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s (%.3fs)", _title, TimeHelper::counter_to_seconds(_start_time));
+    LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s", _title);
   }
 }
 
@@ -125,11 +124,8 @@
 GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceConcTimeImpl() {
   if (_enabled) {
     jlong stop_time = os::elapsed_counter();
-    LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT,
-                                                   _title,
-                                                   TimeHelper::counter_to_seconds(_start_time),
-                                                   TimeHelper::counter_to_seconds(stop_time),
-                                                   TimeHelper::counter_to_millis(stop_time - _start_time));
+    LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s %0.3fms", _title,
+                                                       TimeHelper::counter_to_millis(stop_time - _start_time));
   }
 }
 
--- a/hotspot/test/gc/logging/TestPrintReferences.java	Tue Oct 18 09:43:12 2016 +0200
+++ b/hotspot/test/gc/logging/TestPrintReferences.java	Wed Oct 05 16:00:10 2016 +0200
@@ -41,7 +41,7 @@
     OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start());
 
     String countRegex = "[0-9]+ refs";
-    String timeRegex = "\\([0-9]+[.,][0-9]+s, [0-9]+[.,][0-9]+s\\) [0-9]+[.,][0-9]+ms";
+    String timeRegex = "[0-9]+[.,][0-9]+ms";
 
     output.shouldMatch(".* GC\\([0-9]+\\) SoftReference " + timeRegex + "\n" +
                        ".* GC\\([0-9]+\\) WeakReference " + timeRegex + "\n" +
--- a/hotspot/test/native/logging/test_gcTraceTime.cpp	Tue Oct 18 09:43:12 2016 +0200
+++ b/hotspot/test/native/logging/test_gcTraceTime.cpp	Wed Oct 05 16:00:10 2016 +0200
@@ -48,8 +48,8 @@
   }
 
   const char* expected[] = {
-    "[gc,start", "] Test GC (Allocation Failure) (", "s)",
-    "[gc", "] Test GC (Allocation Failure) ", "M) (", "s, ", "s) ", "ms",
+    "[gc,start", "] Test GC (Allocation Failure)",
+    "[gc", "] Test GC (Allocation Failure) ", "M) ", "ms",
     NULL
   };
   EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
@@ -71,8 +71,8 @@
   }
 
   const char* expected[] = {
-    "[gc,ref,start", "] Test GC (Allocation Failure) (", "s)",
-    "[gc,ref", "] Test GC (Allocation Failure) ", "M) (", "s, ", "s) ", "ms",
+    "[gc,ref,start", "] Test GC (Allocation Failure)",
+    "[gc,ref", "] Test GC (Allocation Failure) ", "M) ", "ms",
     NULL
   };
   EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
@@ -92,17 +92,17 @@
   }
 
   const char* expected[] = {
-    // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s)
-    "[gc,start", "] Test GC (Allocation Failure) (", "s)",
-    // [2.975s][debug][gc      ] Test GC (Allocation Failure) (2.975s, 2.975s) 0.026ms
-    "[gc", "] Test GC (Allocation Failure) ", "(", "s, ", "s) ", "ms",
+    // [2.975s][debug][gc,start] Test GC (Allocation Failure)
+    "[gc,start", "] Test GC (Allocation Failure)",
+    // [2.975s][debug][gc      ] Test GC (Allocation Failure) 0.026ms
+    "[gc", "] Test GC (Allocation Failure) ", "ms",
     NULL
   };
   EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
 
   const char* not_expected[] = {
-      // [2.975s][debug][gc      ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms
-      "[gc", "] Test GC ", "M) (", "s, ", "s) ", "ms",
+      // [2.975s][debug][gc      ] Test GC 59M->59M(502M) 0.026ms
+      "[gc", "] Test GC ", "M) ", "ms",
   };
   EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
 }
@@ -123,10 +123,10 @@
   }
 
   const char* expected[] = {
-    // [2.975s][debug][gc,start] Test GC (2.975s)
-    "[gc,start", "] Test GC ", "s)",
-    // [2.975s][debug][gc      ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms
-    "[gc", "] Test GC ", "M) (", "s, ", "s) ", "ms",
+    // [2.975s][debug][gc,start] Test GC
+    "[gc,start", "] Test GC",
+    // [2.975s][debug][gc      ] Test GC 59M->59M(502M) 0.026ms
+    "[gc", "] Test GC ", "M) ", "ms",
     NULL
   };
   EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
@@ -146,17 +146,17 @@
   }
 
   const char* expected[] = {
-    // [2.975s][debug][gc,start] Test GC (2.975s)
-    "[gc,start", "] Test GC ", "s)",
-    // [2.975s][debug][gc      ] Test GC (2.975s, 2.975s) 0.026ms
-    "[gc", "] Test GC ", "(", "s, ", "s) ", "ms",
+    // [2.975s][debug][gc,start] Test GC
+    "[gc,start", "] Test GC",
+    // [2.975s][debug][gc      ] Test GC 0.026ms
+    "[gc", "] Test GC ", "ms",
     NULL
   };
   EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
 
   const char* not_expected[] = {
-      // [2.975s][debug][gc      ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms
-      "[gc", "] Test GC ", "M) (", "s, ", "s) ", "ms",
+      // [2.975s][debug][gc      ] Test GC 59M->59M(502M) 0.026ms
+      "[gc", "] Test GC ", "M) ", "ms",
   };
   EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
 }
--- a/hotspot/test/serviceability/logging/TestLogRotation.java	Tue Oct 18 09:43:12 2016 +0200
+++ b/hotspot/test/serviceability/logging/TestLogRotation.java	Wed Oct 05 16:00:10 2016 +0200
@@ -41,8 +41,8 @@
     public static void main(String[] args) throws Exception {
 
         long sizeOfLog = Long.parseLong(args[0]);
-        long lines = sizeOfLog / 80;
-        // full.GC generates ad least 1-line which is not shorter then 80 chars
+        long lines = sizeOfLog / 70;
+        // full.GC generates ad least 1-line which is not shorter then 70 chars
         // for some GC 2 shorter lines are generated
         for (long i = 0; i < lines; i++) {
             System.gc();