This commit is contained in:
Erik Helin 2016-10-18 16:21:43 +02:00
commit 719abe462c
4 changed files with 28 additions and 32 deletions

View File

@ -35,7 +35,6 @@
#include "prims/jni_md.h" #include "prims/jni_md.h"
#include "utilities/ticks.hpp" #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)" #define LOG_STOP_HEAP_FORMAT SIZE_FORMAT "M->" SIZE_FORMAT "M(" SIZE_FORMAT "M)"
inline void GCTraceTimeImpl::log_start(jlong start_counter) { inline void GCTraceTimeImpl::log_start(jlong start_counter) {
@ -46,7 +45,7 @@ inline void GCTraceTimeImpl::log_start(jlong start_counter) {
if (_gc_cause != GCCause::_no_gc) { if (_gc_cause != GCCause::_no_gc) {
out.print(" (%s)", GCCause::to_string(_gc_cause)); out.print(" (%s)", GCCause::to_string(_gc_cause));
} }
out.print_cr(" (%.3fs)", TimeHelper::counter_to_seconds(start_counter)); out.cr();
} }
} }
@ -71,7 +70,7 @@ inline void GCTraceTimeImpl::log_stop(jlong start_counter, jlong stop_counter) {
out.print(" " LOG_STOP_HEAP_FORMAT, used_before_m, used_m, capacity_m); 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) { inline void GCTraceTimeImpl::time_stamp(Ticks& ticks) {
@ -117,7 +116,7 @@ template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTa
GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::GCTraceConcTimeImpl(const char* title) : 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) { _enabled(LogImpl<T0, T1, T2, T3, T4, GuardTag>::is_level(Level)), _start_time(os::elapsed_counter()), _title(title) {
if (_enabled) { 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 @@ template <LogLevelType Level, LogTagType T0, LogTagType T1, LogTagType T2, LogTa
GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceConcTimeImpl() { GCTraceConcTimeImpl<Level, T0, T1, T2, T3, T4, GuardTag>::~GCTraceConcTimeImpl() {
if (_enabled) { if (_enabled) {
jlong stop_time = os::elapsed_counter(); jlong stop_time = os::elapsed_counter();
LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s " LOG_STOP_TIME_FORMAT, LogImpl<T0, T1, T2, T3, T4>::template write<Level>("%s %0.3fms", _title,
_title, TimeHelper::counter_to_millis(stop_time - _start_time));
TimeHelper::counter_to_seconds(_start_time),
TimeHelper::counter_to_seconds(stop_time),
TimeHelper::counter_to_millis(stop_time - _start_time));
} }
} }

View File

@ -41,7 +41,7 @@ public class TestPrintReferences {
OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start()); OutputAnalyzer output = new OutputAnalyzer(pb_enabled.start());
String countRegex = "[0-9]+ refs"; 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" + output.shouldMatch(".* GC\\([0-9]+\\) SoftReference " + timeRegex + "\n" +
".* GC\\([0-9]+\\) WeakReference " + timeRegex + "\n" + ".* GC\\([0-9]+\\) WeakReference " + timeRegex + "\n" +

View File

@ -48,8 +48,8 @@ TEST_VM_F(GCTraceTimeTest, full) {
} }
const char* expected[] = { const char* expected[] = {
"[gc,start", "] Test GC (Allocation Failure) (", "s)", "[gc,start", "] Test GC (Allocation Failure)",
"[gc", "] Test GC (Allocation Failure) ", "M) (", "s, ", "s) ", "ms", "[gc", "] Test GC (Allocation Failure) ", "M) ", "ms",
NULL NULL
}; };
EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
@ -71,8 +71,8 @@ TEST_VM_F(GCTraceTimeTest, full_multitag) {
} }
const char* expected[] = { const char* expected[] = {
"[gc,ref,start", "] Test GC (Allocation Failure) (", "s)", "[gc,ref,start", "] Test GC (Allocation Failure)",
"[gc,ref", "] Test GC (Allocation Failure) ", "M) (", "s, ", "s) ", "ms", "[gc,ref", "] Test GC (Allocation Failure) ", "M) ", "ms",
NULL NULL
}; };
EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
@ -92,17 +92,17 @@ TEST_VM_F(GCTraceTimeTest, no_heap) {
} }
const char* expected[] = { const char* expected[] = {
// [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s) // [2.975s][debug][gc,start] Test GC (Allocation Failure)
"[gc,start", "] Test GC (Allocation Failure) (", "s)", "[gc,start", "] Test GC (Allocation Failure)",
// [2.975s][debug][gc ] Test GC (Allocation Failure) (2.975s, 2.975s) 0.026ms // [2.975s][debug][gc ] Test GC (Allocation Failure) 0.026ms
"[gc", "] Test GC (Allocation Failure) ", "(", "s, ", "s) ", "ms", "[gc", "] Test GC (Allocation Failure) ", "ms",
NULL NULL
}; };
EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
const char* not_expected[] = { const char* not_expected[] = {
// [2.975s][debug][gc ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms // [2.975s][debug][gc ] Test GC 59M->59M(502M) 0.026ms
"[gc", "] Test GC ", "M) (", "s, ", "s) ", "ms", "[gc", "] Test GC ", "M) ", "ms",
}; };
EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected)); EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
} }
@ -123,10 +123,10 @@ TEST_VM_F(GCTraceTimeTest, no_cause) {
} }
const char* expected[] = { const char* expected[] = {
// [2.975s][debug][gc,start] Test GC (2.975s) // [2.975s][debug][gc,start] Test GC
"[gc,start", "] Test GC ", "s)", "[gc,start", "] Test GC",
// [2.975s][debug][gc ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms // [2.975s][debug][gc ] Test GC 59M->59M(502M) 0.026ms
"[gc", "] Test GC ", "M) (", "s, ", "s) ", "ms", "[gc", "] Test GC ", "M) ", "ms",
NULL NULL
}; };
EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
@ -146,17 +146,17 @@ TEST_VM_F(GCTraceTimeTest, no_heap_no_cause) {
} }
const char* expected[] = { const char* expected[] = {
// [2.975s][debug][gc,start] Test GC (2.975s) // [2.975s][debug][gc,start] Test GC
"[gc,start", "] Test GC ", "s)", "[gc,start", "] Test GC",
// [2.975s][debug][gc ] Test GC (2.975s, 2.975s) 0.026ms // [2.975s][debug][gc ] Test GC 0.026ms
"[gc", "] Test GC ", "(", "s, ", "s) ", "ms", "[gc", "] Test GC ", "ms",
NULL NULL
}; };
EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected)); EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
const char* not_expected[] = { const char* not_expected[] = {
// [2.975s][debug][gc ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms // [2.975s][debug][gc ] Test GC 59M->59M(502M) 0.026ms
"[gc", "] Test GC ", "M) (", "s, ", "s) ", "ms", "[gc", "] Test GC ", "M) ", "ms",
}; };
EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected)); EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
} }

View File

@ -41,8 +41,8 @@ class GCLoggingGenerator {
public static void main(String[] args) throws Exception { public static void main(String[] args) throws Exception {
long sizeOfLog = Long.parseLong(args[0]); long sizeOfLog = Long.parseLong(args[0]);
long lines = sizeOfLog / 80; long lines = sizeOfLog / 70;
// full.GC generates ad least 1-line which is not shorter then 80 chars // full.GC generates ad least 1-line which is not shorter then 70 chars
// for some GC 2 shorter lines are generated // for some GC 2 shorter lines are generated
for (long i = 0; i < lines; i++) { for (long i = 0; i < lines; i++) {
System.gc(); System.gc();