test/hotspot/gtest/logging/test_gcTraceTime.cpp
changeset 47216 71c04702a3d5
parent 41723 88393c6dd24e
child 49449 ef5d5d343e2a
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/test/hotspot/gtest/logging/test_gcTraceTime.cpp	Tue Sep 12 19:03:39 2017 +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)",
+    "[gc", "] Test GC (Allocation Failure) ", "M) ", "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)",
+    "[gc,ref", "] Test GC (Allocation Failure) ", "M) ", "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)
+    "[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) 0.026ms
+      "[gc", "] Test GC ", "M) ", "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
+    "[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));
+}
+
+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
+    "[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) 0.026ms
+      "[gc", "] Test GC ", "M) ", "ms",
+  };
+  EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
+}