--- a/hotspot/src/share/vm/gc/shared/gcTraceTime.inline.hpp Tue Oct 18 12:26:04 2016 +0000
+++ b/hotspot/src/share/vm/gc/shared/gcTraceTime.inline.hpp Tue Oct 18 16:21:43 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/native/logging/test_gcTraceTime.cpp Tue Oct 18 12:26:04 2016 +0000
+++ b/hotspot/test/native/logging/test_gcTraceTime.cpp Tue Oct 18 16:21:43 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));
}