--- old/src/share/vm/logging/log.cpp 2016-03-29 15:32:04.879323095 +0200 +++ new/src/share/vm/logging/log.cpp 2016-03-29 15:32:04.739318389 +0200 @@ -47,6 +47,7 @@ #ifndef PRODUCT +#include "gc/shared/gcTraceTime.inline.hpp" #include "logging/log.hpp" #include "logging/logConfiguration.hpp" #include "logging/logOutput.hpp" @@ -374,4 +375,294 @@ Test_logstream_no_rm(); } +void Test_loghandle_on() { + TestLogFile log_file("log_handle"); + TestLogSavedConfig tlsc(log_file.name(), "gc=debug"); + + Log(gc) log; + LogHandle log_handle(log); + + assert(log_handle.is_debug(), "assert"); + + // Try to log trough a LogHandle. + log_handle.debug("%d workers", 3); + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + assert(strstr(output, "3 workers") != NULL, "log line missing"); + } + fclose(fp); +} + +void Test_loghandle_off() { + TestLogFile log_file("log_handle"); + TestLogSavedConfig tlsc(log_file.name(), "gc=info"); + + Log(gc) log; + LogHandle log_handle(log); + + assert(!log_handle.is_debug(), "assert"); + + // Try to log trough a LogHandle. Should fail, since only info is turned on. + log_handle.debug("%d workers", 3); + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + assert(strstr(output, "3 workers") == NULL, "log line missing"); + } + fclose(fp); +} + +void Test_loghandle() { + Test_loghandle_on(); + Test_loghandle_off(); +} + +static void Test_logtargethandle_on() { + TestLogFile log_file("log_handle"); + TestLogSavedConfig tlsc(log_file.name(), "gc=debug"); + + LogTarget(Debug, gc) log; + LogTargetHandle log_handle(log); + + assert(log_handle.is_enabled(), "assert"); + + // Try to log trough a LogHandle. + log_handle.print("%d workers", 3); + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + assert(strstr(output, "3 workers") != NULL, "log line missing"); + } + fclose(fp); +} + +static void Test_logtargethandle_off() { + TestLogFile log_file("log_handle"); + TestLogSavedConfig tlsc(log_file.name(), "gc=info"); + + LogTarget(Debug, gc) log; + LogTargetHandle log_handle(log); + + assert(!log_handle.is_enabled(), "assert"); + + // Try to log trough a LogHandle. Should fail, since only info is turned on. + log_handle.print("%d workers", 3); + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + assert(strstr(output, "3 workers") == NULL, "log line missing"); + } + fclose(fp); +} + +void Test_logtargethandle() { + Test_logtargethandle_on(); + Test_logtargethandle_off(); +} + +static void Test_log_gctracetime_full() { + TestLogFile log_file("log_gctracetime"); + TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); + + LogTarget(Debug, gc) gc_debug; + LogTarget(Debug, gc, start) gc_start_debug; + + assert(gc_debug.is_enabled(), "assert"); + assert(gc_start_debug.is_enabled(), "assert"); + + { + MutexLocker lock(Heap_lock); // Needed to read heap usage + GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, true); + } + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s) + assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); + assert(strstr(output, "s)") != NULL, "Incorrect log line"); + } + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc ] Test GC (Allocation Failure) 59M->59M(502M) (2.975s, 2.975s) 0.026ms + assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (Allocation Failure) ") != NULL, "Incorrect log line"); + assert(strstr(output, "M) (") != NULL, "Incorrect log line"); + assert(strstr(output, "s, ") != NULL, "Incorrect log line"); + assert(strstr(output, "s) ") != NULL, "Incorrect log line"); + assert(strstr(output, "ms") != NULL, "Incorrect log line"); + } + fclose(fp); +} + +static void Test_log_gctracetime_full_multitag() { + TestLogFile log_file("log_gctracetime"); + TestLogSavedConfig tlsc(log_file.name(), "gc+ref=debug,gc+ref+start=debug"); + + LogTarget(Debug, gc, ref) gc_debug; + LogTarget(Debug, gc, ref, start) gc_start_debug; + + assert(gc_debug.is_enabled(), "assert"); + assert(gc_start_debug.is_enabled(), "assert"); + + { + MutexLocker lock(Heap_lock); // Needed to read heap usage + GCTraceTime(Debug, gc, ref) timer("Test GC", NULL, GCCause::_allocation_failure, true); + } + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s) + assert(strstr(output, "[gc,ref,start") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); + assert(strstr(output, "s)") != NULL, "Incorrect log line"); + } + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc ] Test GC (Allocation Failure) 59M->59M(502M) (2.975s, 2.975s) 0.026ms + assert(strstr(output, "[gc,ref ") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (Allocation Failure) ") != NULL, "Incorrect log line"); + assert(strstr(output, "M) (") != NULL, "Incorrect log line"); + assert(strstr(output, "s, ") != NULL, "Incorrect log line"); + assert(strstr(output, "s) ") != NULL, "Incorrect log line"); + assert(strstr(output, "ms") != NULL, "Incorrect log line"); + } + fclose(fp); +} + +static void Test_log_gctracetime_no_heap() { + TestLogFile log_file("log_gctracetime"); + TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); + + LogTarget(Debug, gc) gc_debug; + LogTarget(Debug, gc, start) gc_start_debug; + + assert(gc_debug.is_enabled(), "assert"); + assert(gc_start_debug.is_enabled(), "assert"); + + { + GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, false); + } + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc,start] Test GC (Allocation Failure) (2.975s) + assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); + assert(strstr(output, "s)") != NULL, "Incorrect log line"); + } + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc ] Test GC (Allocation Failure) (2.975s, 2.975s) 0.026ms + assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (Allocation Failure) (") != NULL, "Incorrect log line"); + assert(strstr(output, "M) (") == NULL, "Incorrect log line"); + assert(strstr(output, "s, ") != NULL, "Incorrect log line"); + assert(strstr(output, "s) ") != NULL, "Incorrect log line"); + assert(strstr(output, "ms") != NULL, "Incorrect log line"); + } + fclose(fp); +} + +static void Test_log_gctracetime_no_cause() { + TestLogFile log_file("log_gctracetime"); + TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); + + LogTarget(Debug, gc) gc_debug; + LogTarget(Debug, gc, start) gc_start_debug; + + assert(gc_debug.is_enabled(), "assert"); + assert(gc_start_debug.is_enabled(), "assert"); + + { + MutexLocker lock(Heap_lock); // Needed to read heap usage + GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, true); + } + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc,start] Test GC (2.975s) + assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line"); + assert(strstr(output, "s)") != NULL, "Incorrect log line"); + } + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc ] Test GC 59M->59M(502M) (2.975s, 2.975s) 0.026ms + assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC ") != NULL, "Incorrect log line"); + assert(strstr(output, "M) (") != NULL, "Incorrect log line"); + assert(strstr(output, "s, ") != NULL, "Incorrect log line"); + assert(strstr(output, "s) ") != NULL, "Incorrect log line"); + assert(strstr(output, "ms") != NULL, "Incorrect log line"); + } + fclose(fp); +} + +static void Test_log_gctracetime_no_heap_no_cause() { + TestLogFile log_file("log_gctracetime"); + TestLogSavedConfig tlsc(log_file.name(), "gc=debug,gc+start=debug"); + + LogTarget(Debug, gc) gc_debug; + LogTarget(Debug, gc, start) gc_start_debug; + + assert(gc_debug.is_enabled(), "assert"); + assert(gc_start_debug.is_enabled(), "assert"); + + { + MutexLocker lock(Heap_lock); // Needed to read heap usage + GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, false); + } + + FILE* fp = fopen(log_file.name(), "r"); + assert(fp, "File read error"); + + char output[256 /* Large enough buffer */]; + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc,start] Test GC (2.975s) + assert(strstr(output, "[gc,start") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line"); + assert(strstr(output, "s)") != NULL, "Incorrect log line"); + } + if (fgets(output, sizeof(output), fp) != NULL) { + // [2.975s][debug][gc ] Test GC (2.975s, 2.975s) 0.026ms + assert(strstr(output, "[gc ") != NULL, "Incorrect tag set"); + assert(strstr(output, "] Test GC (") != NULL, "Incorrect log line"); + assert(strstr(output, "M) (") == NULL, "Incorrect log line"); + assert(strstr(output, "s, ") != NULL, "Incorrect log line"); + assert(strstr(output, "s) ") != NULL, "Incorrect log line"); + assert(strstr(output, "ms") != NULL, "Incorrect log line"); + } + fclose(fp); +} + +void Test_log_gctracetime() { + Test_log_gctracetime_full(); + Test_log_gctracetime_full_multitag(); + Test_log_gctracetime_no_heap(); + Test_log_gctracetime_no_cause(); + Test_log_gctracetime_no_heap_no_cause(); +} + #endif // PRODUCT