1/*
2 * Copyright (c) 2015, 2016, Oracle and/or its affiliates. All rights reserved.
3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 *
5 * This code is free software; you can redistribute it and/or modify it
6 * under the terms of the GNU General Public License version 2 only, as
7 * published by the Free Software Foundation.
8 *
9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
12 * version 2 for more details (a copy is included in the LICENSE file that
13 * accompanied this code).
14 *
15 * You should have received a copy of the GNU General Public License version
16 * 2 along with this work; if not, write to the Free Software Foundation,
17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 *
19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 * or visit www.oracle.com if you need additional information or have any
21 * questions.
22 *
23 */
24#include "precompiled.hpp"
25#include "gc/shared/gcTraceTime.inline.hpp"
26#include "logTestFixture.hpp"
27#include "logTestUtils.inline.hpp"
28#include "logging/log.hpp"
29#include "runtime/interfaceSupport.hpp"
30#include "unittest.hpp"
31
32class GCTraceTimeTest : public LogTestFixture {
33};
34
35TEST_VM_F(GCTraceTimeTest, full) {
36  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
37
38  LogTarget(Debug, gc) gc_debug;
39  LogTarget(Debug, gc, start) gc_start_debug;
40
41  EXPECT_TRUE(gc_debug.is_enabled());
42  EXPECT_TRUE(gc_start_debug.is_enabled());
43
44  {
45    ThreadInVMfromNative tvn(JavaThread::current());
46    MutexLocker lock(Heap_lock); // Needed to read heap usage
47    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, true);
48  }
49
50  const char* expected[] = {
51    "[gc,start", "] Test GC (Allocation Failure)",
52    "[gc", "] Test GC (Allocation Failure) ", "M) ", "ms",
53    NULL
54  };
55  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
56}
57
58TEST_VM_F(GCTraceTimeTest, full_multitag) {
59  set_log_config(TestLogFileName, "gc+ref=debug,gc+ref+start=debug");
60
61  LogTarget(Debug, gc, ref) gc_debug;
62  LogTarget(Debug, gc, ref, start) gc_start_debug;
63
64  EXPECT_TRUE(gc_debug.is_enabled());
65  EXPECT_TRUE(gc_start_debug.is_enabled());
66
67  {
68    ThreadInVMfromNative tvn(JavaThread::current());
69    MutexLocker lock(Heap_lock); // Needed to read heap usage
70    GCTraceTime(Debug, gc, ref) timer("Test GC", NULL, GCCause::_allocation_failure, true);
71  }
72
73  const char* expected[] = {
74    "[gc,ref,start", "] Test GC (Allocation Failure)",
75    "[gc,ref", "] Test GC (Allocation Failure) ", "M) ", "ms",
76    NULL
77  };
78  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
79}
80
81TEST_VM_F(GCTraceTimeTest, no_heap) {
82  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
83
84  LogTarget(Debug, gc) gc_debug;
85  LogTarget(Debug, gc, start) gc_start_debug;
86
87  EXPECT_TRUE(gc_debug.is_enabled());
88  EXPECT_TRUE(gc_start_debug.is_enabled());
89
90  {
91    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_allocation_failure, false);
92  }
93
94  const char* expected[] = {
95    // [2.975s][debug][gc,start] Test GC (Allocation Failure)
96    "[gc,start", "] Test GC (Allocation Failure)",
97    // [2.975s][debug][gc      ] Test GC (Allocation Failure) 0.026ms
98    "[gc", "] Test GC (Allocation Failure) ", "ms",
99    NULL
100  };
101  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
102
103  const char* not_expected[] = {
104      // [2.975s][debug][gc      ] Test GC 59M->59M(502M) 0.026ms
105      "[gc", "] Test GC ", "M) ", "ms",
106  };
107  EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
108}
109
110TEST_VM_F(GCTraceTimeTest, no_cause) {
111  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
112
113  LogTarget(Debug, gc) gc_debug;
114  LogTarget(Debug, gc, start) gc_start_debug;
115
116  EXPECT_TRUE(gc_debug.is_enabled());
117  EXPECT_TRUE(gc_start_debug.is_enabled());
118
119  {
120    ThreadInVMfromNative tvn(JavaThread::current());
121    MutexLocker lock(Heap_lock); // Needed to read heap usage
122    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, true);
123  }
124
125  const char* expected[] = {
126    // [2.975s][debug][gc,start] Test GC
127    "[gc,start", "] Test GC",
128    // [2.975s][debug][gc      ] Test GC 59M->59M(502M) 0.026ms
129    "[gc", "] Test GC ", "M) ", "ms",
130    NULL
131  };
132  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
133}
134
135TEST_VM_F(GCTraceTimeTest, no_heap_no_cause) {
136  set_log_config(TestLogFileName, "gc=debug,gc+start=debug");
137
138  LogTarget(Debug, gc) gc_debug;
139  LogTarget(Debug, gc, start) gc_start_debug;
140
141  EXPECT_TRUE(gc_debug.is_enabled());
142  EXPECT_TRUE(gc_start_debug.is_enabled());
143
144  {
145    GCTraceTime(Debug, gc) timer("Test GC", NULL, GCCause::_no_gc, false);
146  }
147
148  const char* expected[] = {
149    // [2.975s][debug][gc,start] Test GC
150    "[gc,start", "] Test GC",
151    // [2.975s][debug][gc      ] Test GC 0.026ms
152    "[gc", "] Test GC ", "ms",
153    NULL
154  };
155  EXPECT_TRUE(file_contains_substrings_in_order(TestLogFileName, expected));
156
157  const char* not_expected[] = {
158      // [2.975s][debug][gc      ] Test GC 59M->59M(502M) 0.026ms
159      "[gc", "] Test GC ", "M) ", "ms",
160  };
161  EXPECT_FALSE(file_contains_substrings_in_order(TestLogFileName, not_expected));
162}
163