--- a/hotspot/src/share/vm/logging/log.cpp	Fri Apr 29 15:23:15 2016 +0200
+++ b/hotspot/src/share/vm/logging/log.cpp	Thu Sep 08 15:24:52 2016 +0200
@@ -937,223 +937,6 @@
   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 */];
-
-  char* res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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");
-
-  res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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 */];
-
-  char* res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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");
-
-  res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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 */];
-
-  char* res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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");
-
-  res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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 */];
-
-  char* res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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");
-
-  res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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 */];
-
-  char* res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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");
-
-  res = fgets(output, sizeof(output), fp);
-  assert(res != NULL, "assert");
-
-  // [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();
-}
-
 void Test_invalid_log_file() {
   ResourceMark rm;
   stringStream ss;

--- a/hotspot/src/share/vm/utilities/internalVMTests.cpp	Fri Apr 29 15:23:15 2016 +0200
+++ b/hotspot/src/share/vm/utilities/internalVMTests.cpp	Thu Sep 08 15:24:52 2016 +0200
@@ -64,7 +64,6 @@
   run_unit_test(Test_logstream);
   run_unit_test(Test_loghandle);
   run_unit_test(Test_logtargethandle);
-  run_unit_test(Test_log_gctracetime);
   run_unit_test(Test_configure_stdout);
   run_unit_test(Test_logconfiguration_subscribe);
   run_unit_test(Test_log_prefix);

--- a/hotspot/test/native/logging/logTestUtils.inline.hpp	Fri Apr 29 15:23:15 2016 +0200
+++ b/hotspot/test/native/logging/logTestUtils.inline.hpp	Thu Sep 08 15:24:52 2016 +0200
@@ -21,6 +21,10 @@
  * questions.
  *
  */
+#include "logging/log.hpp"
+#include "logging/logConfiguration.hpp"
+#include "logging/logStream.hpp"
+#include "memory/resourceArea.hpp"
 #include "runtime/os.hpp"
 #include "unittest.hpp"
 
@@ -43,3 +47,54 @@
   EXPECT_TRUE(ret == 0 || errno == ENOENT) << "failed to remove file '" << filename << "': "
       << os::strerror(errno) << " (" << errno << ")";
 }
+
+// Read a complete line from fp and return it as a resource allocated string.
+// Returns NULL on EOF.
+static inline char* read_line(FILE* fp) {
+  assert(fp != NULL, "invalid fp");
+  int buflen = 512;
+  char* buf = NEW_RESOURCE_ARRAY(char, buflen);
+  long pos = ftell(fp);
+
+  char* ret = fgets(buf, buflen, fp);
+  while (ret != NULL && buf[strlen(buf) - 1] != '\n' && !feof(fp)) {
+    // retry with a larger buffer
+    buf = REALLOC_RESOURCE_ARRAY(char, buf, buflen, buflen * 2);
+    buflen *= 2;
+    // rewind to beginning of line
+    fseek(fp, pos, SEEK_SET);
+    // retry read with new buffer
+    ret = fgets(buf, buflen, fp);
+  }
+  return ret;
+}
+
+static bool file_contains_substrings_in_order(const char* filename, const char* substrs[]) {
+  FILE* fp = fopen(filename, "r");
+  assert(fp != NULL, "error opening file %s: %s", filename, strerror(errno));
+
+  size_t idx = 0;
+  while (substrs[idx] != NULL) {
+    ResourceMark rm;
+    char* line = read_line(fp);
+    if (line == NULL) {
+      break;
+    }
+    for (char* match = strstr(line, substrs[idx]); match != NULL;) {
+      size_t match_len = strlen(substrs[idx]);
+      idx++;
+      if (substrs[idx] == NULL) {
+        break;
+      }
+      match = strstr(match + match_len, substrs[idx]);
+    }
+  }
+
+  fclose(fp);
+  return substrs[idx] == NULL;
+}
+
+static inline bool file_contains_substring(const char* filename, const char* substr) {
+  const char* strs[] = {substr, NULL};
+  return file_contains_substrings_in_order(filename, strs);
+}

--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/hotspot/test/native/logging/test_gcTraceTime.cpp	Thu Sep 08 15:24:52 2016 +0200
@@ -0,0 +1,162 @@
+/*
+ * Copyright (c) 2015, 2016, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ *
+ */
+#include "precompiled.hpp"
+#include "gc/shared/gcTraceTime.inline.hpp"
+#include "logTestFixture.hpp"
+#include "logTestUtils.inline.hpp"
+#include "logging/log.hpp"
+#include "runtime/interfaceSupport.hpp"
+#include "unittest.hpp"
+
+class GCTraceTimeTest : public LogTestFixture {
+};
+
+TEST_VM_F(GCTraceTimeTest, full) {
+  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
+
+  LogTarget(Debug, gc) gc_debug;
+  LogTarget(Debug, gc, start) gc_start_debug;
+
+  EXPECT_TRUE(gc_debug.is_enabled());
+  EXPECT_TRUE(gc_start_debug.is_enabled());
+
+  {
+    ThreadInVMfromNative tvn(JavaThread::current());
+    MutexLocker lock(Heap_lock); // Needed to read heap usage
+    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, true);
+  }
+
+  const char* expected[] = {
+    "[gc,start", "] Test GC (Allocation Failure) (", "s)",
+    "[gc", "] Test GC (Allocation Failure) ", "M) (", "s, ", "s) ", "ms",
+    NULL
+  };
+  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
+}
+
+TEST_VM_F(GCTraceTimeTest, full_multitag) {
+  set_log_config(TestLogFileName, "gc+ref=debug,gc+ref+start=debug");
+
+  LogTarget(Debug, gc, ref) gc_debug;
+  LogTarget(Debug, gc, ref, start) gc_start_debug;
+
+  EXPECT_TRUE(gc_debug.is_enabled());
+  EXPECT_TRUE(gc_start_debug.is_enabled());
+
+  {
+    ThreadInVMfromNative tvn(JavaThread::current());
+    MutexLocker lock(Heap_lock); // Needed to read heap usage
+    GCTraceTime(Debug, gc, ref) timer("Test GC", NULL, GCCause::_allocation_failure, true);
+  }
+
+  const char* expected[] = {
+    "[gc,ref,start", "] Test GC (Allocation Failure) (", "s)",
+    "[gc,ref", "] Test GC (Allocation Failure) ", "M) (", "s, ", "s) ", "ms",
+    NULL
+  };
+  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
+}
+
+TEST_VM_F(GCTraceTimeTest, no_heap) {
+  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
+
+  LogTarget(Debug, gc) gc_debug;
+  LogTarget(Debug, gc, start) gc_start_debug;
+
+  EXPECT_TRUE(gc_debug.is_enabled());
+  EXPECT_TRUE(gc_start_debug.is_enabled());
+
+  {
+    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, false);
+  }
+
+  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",
+    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",
+  };
+  EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
+}
+
+TEST_VM_F(GCTraceTimeTest, no_cause) {
+  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
+
+  LogTarget(Debug, gc) gc_debug;
+  LogTarget(Debug, gc, start) gc_start_debug;
+
+  EXPECT_TRUE(gc_debug.is_enabled());
+  EXPECT_TRUE(gc_start_debug.is_enabled());
+
+  {
+    ThreadInVMfromNative tvn(JavaThread::current());
+    MutexLocker lock(Heap_lock); // Needed to read heap usage
+    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, true);
+  }
+
+  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",
+    NULL
+  };
+  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
+}
+
+TEST_VM_F(GCTraceTimeTest, no_heap_no_cause) {
+  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
+
+  LogTarget(Debug, gc) gc_debug;
+  LogTarget(Debug, gc, start) gc_start_debug;
+
+  EXPECT_TRUE(gc_debug.is_enabled());
+  EXPECT_TRUE(gc_start_debug.is_enabled());
+
+  {
+    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, false);
+  }
+
+  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",
+    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",
+  };
+  EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
+}