Print this page
rev 3856 : 8004170: G1: Verbose GC output is not getting flushed to log file using JDK 8
Summary: Add flushes to G1CollectedHeap::log_gc_footer() and TraceCPUTime destructor.
Reviewed-by:
| Split |
Close |
| Expand all |
| Collapse all |
--- old/src/share/vm/runtime/timer.cpp
+++ new/src/share/vm/runtime/timer.cpp
1 1 /*
2 2 * Copyright (c) 1997, 2012, Oracle and/or its affiliates. All rights reserved.
3 3 * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
4 4 *
5 5 * This code is free software; you can redistribute it and/or modify it
6 6 * under the terms of the GNU General Public License version 2 only, as
7 7 * published by the Free Software Foundation.
8 8 *
9 9 * This code is distributed in the hope that it will be useful, but WITHOUT
10 10 * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
11 11 * FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License
12 12 * version 2 for more details (a copy is included in the LICENSE file that
13 13 * accompanied this code).
14 14 *
15 15 * You should have received a copy of the GNU General Public License version
16 16 * 2 along with this work; if not, write to the Free Software Foundation,
17 17 * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
18 18 *
19 19 * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
20 20 * or visit www.oracle.com if you need additional information or have any
21 21 * questions.
22 22 *
23 23 */
24 24
25 25 #include "precompiled.hpp"
26 26 #include "oops/oop.inline.hpp"
27 27 #include "runtime/timer.hpp"
28 28 #include "utilities/ostream.hpp"
29 29 #ifdef TARGET_OS_FAMILY_linux
30 30 # include "os_linux.inline.hpp"
31 31 #endif
32 32 #ifdef TARGET_OS_FAMILY_solaris
33 33 # include "os_solaris.inline.hpp"
34 34 #endif
35 35 #ifdef TARGET_OS_FAMILY_windows
36 36 # include "os_windows.inline.hpp"
37 37 #endif
38 38 #ifdef TARGET_OS_FAMILY_bsd
39 39 # include "os_bsd.inline.hpp"
40 40 #endif
41 41
42 42
43 43 void elapsedTimer::add(elapsedTimer t) {
44 44 _counter += t._counter;
45 45 }
46 46
47 47 void elapsedTimer::start() {
48 48 if (!_active) {
49 49 _active = true;
50 50 _start_counter = os::elapsed_counter();
51 51 }
52 52 }
53 53
54 54 void elapsedTimer::stop() {
55 55 if (_active) {
56 56 _counter += os::elapsed_counter() - _start_counter;
57 57 _active = false;
58 58 }
59 59 }
60 60
61 61 double elapsedTimer::seconds() const {
62 62 double count = (double) _counter;
63 63 double freq = (double) os::elapsed_frequency();
64 64 return count/freq;
65 65 }
66 66
67 67 jlong elapsedTimer::milliseconds() const {
68 68 jlong ticks_per_ms = os::elapsed_frequency() / 1000;
69 69 return _counter / ticks_per_ms;
70 70 }
71 71
72 72 jlong elapsedTimer::active_ticks() const {
73 73 if (!_active) {
74 74 return ticks();
75 75 }
76 76 jlong counter = _counter + os::elapsed_counter() - _start_counter;
77 77 return counter;
78 78 }
79 79
80 80 void TimeStamp::update_to(jlong ticks) {
81 81 _counter = ticks;
82 82 if (_counter == 0) _counter = 1;
83 83 assert(is_updated(), "must not look clear");
84 84 }
85 85
86 86 void TimeStamp::update() {
87 87 update_to(os::elapsed_counter());
88 88 }
89 89
90 90 double TimeStamp::seconds() const {
91 91 assert(is_updated(), "must not be clear");
92 92 jlong new_count = os::elapsed_counter();
93 93 double count = (double) new_count - _counter;
94 94 double freq = (double) os::elapsed_frequency();
95 95 return count/freq;
96 96 }
97 97
98 98 jlong TimeStamp::milliseconds() const {
99 99 assert(is_updated(), "must not be clear");
100 100
101 101 jlong new_count = os::elapsed_counter();
102 102 jlong count = new_count - _counter;
103 103 jlong ticks_per_ms = os::elapsed_frequency() / 1000;
104 104 return count / ticks_per_ms;
105 105 }
106 106
107 107 jlong TimeStamp::ticks_since_update() const {
108 108 assert(is_updated(), "must not be clear");
109 109 return os::elapsed_counter() - _counter;
110 110 }
111 111
112 112 TraceTime::TraceTime(const char* title,
113 113 bool doit,
114 114 bool print_cr,
115 115 outputStream* logfile) {
116 116 _active = doit;
117 117 _verbose = true;
118 118 _print_cr = print_cr;
119 119 _logfile = (logfile != NULL) ? logfile : tty;
120 120
121 121 if (_active) {
122 122 _accum = NULL;
123 123 _logfile->stamp(PrintGCTimeStamps);
124 124 _logfile->print("[%s", title);
125 125 _logfile->flush();
126 126 _t.start();
127 127 }
128 128 }
129 129
130 130 TraceTime::TraceTime(const char* title,
131 131 elapsedTimer* accumulator,
132 132 bool doit,
133 133 bool verbose,
134 134 outputStream* logfile) {
135 135 _active = doit;
136 136 _verbose = verbose;
137 137 _print_cr = true;
138 138 _logfile = (logfile != NULL) ? logfile : tty;
139 139 if (_active) {
140 140 if (_verbose) {
141 141 _logfile->stamp(PrintGCTimeStamps);
142 142 _logfile->print("[%s", title);
143 143 _logfile->flush();
144 144 }
145 145 _accum = accumulator;
146 146 _t.start();
147 147 }
148 148 }
149 149
150 150 TraceTime::~TraceTime() {
151 151 if (_active) {
152 152 _t.stop();
153 153 if (_accum!=NULL) _accum->add(_t);
154 154 if (_verbose) {
155 155 if (_print_cr) {
156 156 _logfile->print_cr(", %3.7f secs]", _t.seconds());
157 157 } else {
158 158 _logfile->print(", %3.7f secs]", _t.seconds());
159 159 }
160 160 _logfile->flush();
161 161 }
162 162 }
163 163 }
164 164
165 165 TraceCPUTime::TraceCPUTime(bool doit,
166 166 bool print_cr,
167 167 outputStream *logfile) :
168 168 _active(doit),
169 169 _print_cr(print_cr),
170 170 _starting_user_time(0.0),
171 171 _starting_system_time(0.0),
172 172 _starting_real_time(0.0),
173 173 _logfile(logfile),
174 174 _error(false) {
175 175 if (_active) {
176 176 if (logfile != NULL) {
177 177 _logfile = logfile;
178 178 } else {
179 179 _logfile = tty;
180 180 }
181 181
182 182 _error = !os::getTimesSecs(&_starting_real_time,
183 183 &_starting_user_time,
184 184 &_starting_system_time);
185 185 }
186 186 }
187 187
188 188 TraceCPUTime::~TraceCPUTime() {
189 189 if (_active) {
190 190 bool valid = false;
191 191 if (!_error) {
192 192 double real_secs; // walk clock time
193 193 double system_secs; // system time
194 194 double user_secs; // user time for all threads
195 195
196 196 double real_time, user_time, system_time;
197 197 valid = os::getTimesSecs(&real_time, &user_time, &system_time);
198 198 if (valid) {
199 199
200 200 user_secs = user_time - _starting_user_time;
201 201 system_secs = system_time - _starting_system_time;
202 202 real_secs = real_time - _starting_real_time;
|
↓ open down ↓ |
202 lines elided |
↑ open up ↑ |
203 203
204 204 _logfile->print(" [Times: user=%3.2f sys=%3.2f, real=%3.2f secs] ",
205 205 user_secs, system_secs, real_secs);
206 206
207 207 } else {
208 208 _logfile->print("[Invalid result in TraceCPUTime]");
209 209 }
210 210 } else {
211 211 _logfile->print("[Error in TraceCPUTime]");
212 212 }
213 - if (_print_cr) {
213 + if (_print_cr) {
214 214 _logfile->print_cr("");
215 215 }
216 + _logfile->flush();
216 217 }
217 218 }
XXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXXX