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.inline.hpp"
30 #include "unittest.hpp"
31
32 class GCTraceTimeTest : public LogTestFixture {
33 };
34
35 TEST_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
58 TEST_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
81 TEST_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
110 TEST_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
135 TEST_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 }