1 /*
2 * Copyright (c) 2002, 2025, 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
25 #include "code/nmethod.hpp"
26 #include "memory/allocation.hpp"
27 #include "memory/allocation.inline.hpp"
28 #include "memory/resourceArea.hpp"
29 #include "oops/methodData.hpp"
30 #include "oops/method.inline.hpp"
31 #include "oops/oop.inline.hpp"
32 #include "runtime/deoptimization.hpp"
33 #include "runtime/handles.inline.hpp"
34 #include "runtime/osThread.hpp"
35 #include "runtime/vmOperations.hpp"
36 #include "runtime/vmThread.hpp"
37 #include "utilities/vmError.hpp"
38 #include "utilities/xmlstream.hpp"
39
40 // The XML stream is the contents of the LogFile (default hotspot_%p.log).
41 // It is a superset of whatever might be displayed on the tty.
42 // You can get to it by calls of the form xtty->...
43 // Normal calls to tty->... just embed plain text among any markup
44 // produced via the xtty API.
45 // The xtty has sub-streams called xtty->text() and xtty->log_long().
46 // These are ordinary output streams for writing unstructured text.
47 // The format of this log file is both unstructured and constrained.
48 //
49 // Apart from possible race conditions, every line in the log file
50 // is either an XML element (<tag ...>, or </tag>, or <tag .../>)
51 // or is unstructured text.
52 //
53 // On any given line, if the first character is '<', then the last
54 // character is '>' and the line consists of a single XML element,
55 // which uses single quote '\'' to delimit any attribute values.
56 // (The double-quote character '"' never appears, ever.)
57 //
58 // All other lines consist of unstructured text which is completely
59 // free of the following characters: '<', '>', '&', '\'', '"'. If
60 // those characters are written to the tty (or to any other text
61 // stream underlying the xtty), those characters, and no other
62 // characters, are written as XML entities: "<", ">", "&",
63 // "&apos", """. There is no other use of the character '&'.
64 //
65 // The net effect is that you may select a range of tools to process
66 // the marked-up logs, including XML parsers and simple line-oriented
67 // Java or Unix tools. The main concession you have to make to XML
68 // is to convert the above five XML entities to single ASCII chars,
69 // as you process attribute strings or unstructured text.
70 //
71 // It would be wise to ignore any XML tags that you do not recognize.
72 // This can be done with grep, if you choose, because the log file
73 // is line-structured.
74 //
75 // The log file collects the output from many contributing threads.
76 // You should expect that an element of the form <writer thread='NNN'>
77 // could appear almost anywhere, as the lines interleave.
78 // It is straightforward to write a script to tease the log file
79 // into thread-specific substreams.
80
81 // Do not assert this condition if there's already another error reported.
82 #define assert_if_no_error(cond, msg) \
83 vmassert((cond) || VMError::is_error_reported(), msg)
84 bool xmlStream::inside_attrs_or_error() {
85 return inside_attrs() || VMError::is_error_reported();
86 }
87
88 void xmlStream::initialize(outputStream* out) {
89 _out = out;
90 _last_flush = 0;
91 _markup_state = BODY;
92 _text_init._outer_xmlStream = this;
93 _text = &_text_init;
94 _log_only = _text;
95
96 #ifdef ASSERT
97 _element_depth = 0;
98 int init_len = 100;
99 char* init_buf = NEW_C_HEAP_ARRAY(char, init_len, mtInternal);
100 _element_close_stack_low = init_buf;
101 _element_close_stack_high = init_buf + init_len;
102 _element_close_stack_ptr = init_buf + init_len - 1;
103 _element_close_stack_ptr[0] = '\0';
104 #endif
105
106 // Make sure each log uses the same base for time stamps.
107 if (is_open()) {
108 _out->time_stamp().update_to(1);
109 }
110 }
111
112 #ifdef ASSERT
113 xmlStream::~xmlStream() {
114 FREE_C_HEAP_ARRAY(char, _element_close_stack_low);
115 }
116 #endif
117
118 // Pass the given chars directly to _out.
119 void xmlStream::write(const char* s, size_t len) {
120 if (!is_open()) return;
121
122 out()->write(s, len);
123 update_position(s, len);
124 }
125
126
127 // Pass the given chars directly to _out, except that
128 // we watch for special "<&>" chars.
129 // This is suitable for either attribute text or for body text.
130 // We don't fool with "<![CDATA[" quotes, just single-character entities.
131 // This makes it easier for dumb tools to parse the output.
132 void xmlStream::write_text(const char* s, size_t len) {
133 if (!is_open()) return;
134
135 size_t written = 0;
136 // All normally printed material goes inside XML quotes.
137 // This leaves the output free to include markup also.
138 // Scan the string looking for inadvertent "<&>" chars
139 for (size_t i = 0; i < len; i++) {
140 char ch = s[i];
141 // Escape special chars.
142 const char* esc = nullptr;
143 switch (ch) {
144 // These are important only in attrs, but we do them always:
145 case '\'': esc = "'"; break;
146 case '"': esc = """; break;
147 case '<': esc = "<"; break;
148 case '&': esc = "&"; break;
149 // This is a freebie.
150 case '>': esc = ">"; break;
151 }
152 if (esc != nullptr) {
153 if (written < i) {
154 out()->write(&s[written], i - written);
155 written = i;
156 }
157 out()->print_raw(esc);
158 written++;
159 }
160 }
161
162 // Print the clean remainder. Usually, it is all of s.
163 if (written < len) {
164 out()->write(&s[written], len - written);
165 }
166 }
167
168 // ------------------------------------------------------------------
169 // Outputs XML text, with special characters quoted.
170 void xmlStream::text(const char* format, ...) {
171 va_list ap;
172 va_start(ap, format);
173 va_text(format, ap);
174 va_end(ap);
175 }
176
177 // ------------------------------------------------------------------
178 // Outputs XML attribute, with quotes and special characters quoted.
179 void xmlStream::attr(const char* attr, const char* format, ...) {
180 va_list ap;
181 va_start(ap, format);
182 va_attr(attr, format, ap);
183 va_end(ap);
184 }
185
186 #define BUFLEN 2*K /* max size of output of individual print methods */
187
188 // ------------------------------------------------------------------
189 void xmlStream::va_tag(bool push, const char* format, va_list ap) {
190 assert_if_no_error(!inside_attrs(), "cannot print tag inside attrs");
191 char buffer[BUFLEN];
192 size_t len;
193 const char* kind = do_vsnprintf(buffer, BUFLEN, format, ap, false, len);
194 see_tag(kind, push);
195 // make sure all opening and/or closing tags begin in the first column
196 if (out()->position() > 0) print_raw("\n");
197 print_raw("<");
198 write(kind, len);
199 _markup_state = (push ? HEAD : ELEM);
200 }
201
202 #ifdef ASSERT
203 /// Debugging goo to make sure element tags nest properly.
204
205 // ------------------------------------------------------------------
206 void xmlStream::see_tag(const char* tag, bool push) {
207 assert_if_no_error(!inside_attrs(), "cannot start new element inside attrs");
208 if (!push) return;
209
210 // tag goes up until either null or space:
211 const char* tag_end = strchr(tag, ' ');
212 size_t tag_len = (tag_end == nullptr) ? strlen(tag) : tag_end - tag;
213 assert(tag_len > 0, "tag must not be empty");
214 // push the tag onto the stack, pulling down the pointer
215 char* old_ptr = _element_close_stack_ptr;
216 char* old_low = _element_close_stack_low;
217 char* push_ptr = old_ptr - (tag_len+1);
218 if (push_ptr < old_low) {
219 int old_len = pointer_delta_as_int(_element_close_stack_high, old_ptr);
220 int new_len = old_len * 2;
221 if (new_len < 100) new_len = 100;
222 char* new_low = NEW_C_HEAP_ARRAY(char, new_len, mtInternal);
223 char* new_high = new_low + new_len;
224 char* new_ptr = new_high - old_len;
225 memcpy(new_ptr, old_ptr, old_len);
226 _element_close_stack_high = new_high;
227 _element_close_stack_low = new_low;
228 _element_close_stack_ptr = new_ptr;
229 FREE_C_HEAP_ARRAY(char, old_low);
230 push_ptr = new_ptr - (tag_len+1);
231 }
232 assert(push_ptr >= _element_close_stack_low, "in range");
233 memcpy(push_ptr, tag, tag_len);
234 push_ptr[tag_len] = 0;
235 _element_close_stack_ptr = push_ptr;
236 _element_depth += 1;
237 }
238
239 // ------------------------------------------------------------------
240 void xmlStream::pop_tag(const char* tag) {
241 assert_if_no_error(!inside_attrs(), "cannot close element inside attrs");
242 assert(_element_depth > 0, "must be in an element to close");
243 assert(*tag != 0, "tag must not be empty");
244 char* cur_tag = _element_close_stack_ptr;
245 bool bad_tag = false;
246 while (*cur_tag != 0 && strcmp(cur_tag, tag) != 0) {
247 this->print_cr("</%s> <!-- missing closing tag -->", cur_tag);
248 _element_close_stack_ptr = (cur_tag += strlen(cur_tag) + 1);
249 _element_depth -= 1;
250 bad_tag = true;
251 }
252 if (*cur_tag == 0) {
253 bad_tag = true;
254 } else {
255 // Pop the stack, by skipping over the tag and its null.
256 _element_close_stack_ptr = cur_tag + strlen(cur_tag) + 1;
257 _element_depth -= 1;
258 }
259 if (bad_tag && !VMThread::should_terminate() && !VM_Exit::vm_exited() &&
260 !VMError::is_error_reported())
261 {
262 assert(false, "bad tag in log");
263 }
264 }
265 #endif
266
267
268 // ------------------------------------------------------------------
269 // First word in formatted string is element kind, and any subsequent
270 // words must be XML attributes. Outputs "<kind .../>".
271 void xmlStream::elem(const char* format, ...) {
272 va_list ap;
273 va_start(ap, format);
274 va_elem(format, ap);
275 va_end(ap);
276 }
277
278 // ------------------------------------------------------------------
279 void xmlStream::va_elem(const char* format, va_list ap) {
280 va_begin_elem(format, ap);
281 end_elem();
282 }
283
284
285 // ------------------------------------------------------------------
286 // First word in formatted string is element kind, and any subsequent
287 // words must be XML attributes. Outputs "<kind ...", not including "/>".
288 void xmlStream::begin_elem(const char* format, ...) {
289 va_list ap;
290 va_start(ap, format);
291 va_tag(false, format, ap);
292 va_end(ap);
293 }
294
295 // ------------------------------------------------------------------
296 void xmlStream::va_begin_elem(const char* format, va_list ap) {
297 va_tag(false, format, ap);
298 }
299
300 // ------------------------------------------------------------------
301 // Outputs "/>".
302 void xmlStream::end_elem() {
303 assert(_markup_state == ELEM, "misplaced end_elem");
304 print_raw("/>\n");
305 _markup_state = BODY;
306 }
307
308 // ------------------------------------------------------------------
309 // Outputs formatted text, followed by "/>".
310 void xmlStream::end_elem(const char* format, ...) {
311 va_list ap;
312 va_start(ap, format);
313 out()->vprint(format, ap);
314 va_end(ap);
315 end_elem();
316 }
317
318
319 // ------------------------------------------------------------------
320 // First word in formatted string is element kind, and any subsequent
321 // words must be XML attributes. Outputs "<kind ...>".
322 void xmlStream::head(const char* format, ...) {
323 va_list ap;
324 va_start(ap, format);
325 va_head(format, ap);
326 va_end(ap);
327 }
328
329 // ------------------------------------------------------------------
330 void xmlStream::va_head(const char* format, va_list ap) {
331 va_begin_head(format, ap);
332 end_head();
333 }
334
335 // ------------------------------------------------------------------
336 // First word in formatted string is element kind, and any subsequent
337 // words must be XML attributes. Outputs "<kind ...", not including ">".
338 void xmlStream::begin_head(const char* format, ...) {
339 va_list ap;
340 va_start(ap, format);
341 va_tag(true, format, ap);
342 va_end(ap);
343 }
344
345 // ------------------------------------------------------------------
346 void xmlStream::va_begin_head(const char* format, va_list ap) {
347 va_tag(true, format, ap);
348 }
349
350 // ------------------------------------------------------------------
351 // Outputs ">".
352 void xmlStream::end_head() {
353 assert(_markup_state == HEAD, "misplaced end_head");
354 print_raw(">\n");
355 _markup_state = BODY;
356 }
357
358
359 // ------------------------------------------------------------------
360 // Outputs formatted text, followed by ">".
361 void xmlStream::end_head(const char* format, ...) {
362 va_list ap;
363 va_start(ap, format);
364 out()->vprint(format, ap);
365 va_end(ap);
366 end_head();
367 }
368
369
370 // ------------------------------------------------------------------
371 // Outputs "</kind>".
372 void xmlStream::tail(const char* kind) {
373 pop_tag(kind);
374 // make sure all opening and/or closing tags begin in the first column
375 if (out()->position() > 0) print_raw("\n");
376 print_raw("</");
377 print_raw(kind);
378 print_raw(">\n");
379 }
380
381 // ------------------------------------------------------------------
382 // Outputs "<kind_done ... stamp='D.DD'/> </kind>".
383 void xmlStream::done(const char* format, ...) {
384 va_list ap;
385 va_start(ap, format);
386 va_done(format, ap);
387 va_end(ap);
388 }
389
390 // ------------------------------------------------------------------
391 // Outputs "<kind_done stamp='D.DD'/> </kind>".
392 // Because done_raw() doesn't need to format strings, it's simpler than
393 // done(), and can be called safely by fatal error handler.
394 void xmlStream::done_raw(const char* kind) {
395 print_raw("<");
396 print_raw(kind);
397 print_raw("_done stamp='");
398 out()->stamp();
399 print_raw_cr("'/>");
400 print_raw("</");
401 print_raw(kind);
402 print_raw_cr(">");
403 }
404
405 // If you remove the PRAGMA, this fails to compile with clang-503.0.40.
406 PRAGMA_DIAG_PUSH
407 PRAGMA_FORMAT_NONLITERAL_IGNORED
408 // ------------------------------------------------------------------
409 void xmlStream::va_done(const char* format, va_list ap) {
410 char buffer[200];
411 size_t format_len = strlen(format);
412 guarantee(format_len + 10 < sizeof(buffer), "bigger format buffer");
413 const char* kind = format;
414 const char* kind_end = strchr(kind, ' ');
415 size_t kind_len;
416 if (kind_end != nullptr) {
417 kind_len = kind_end - kind;
418 int n = os::snprintf(buffer, sizeof(buffer), "%.*s_done%s", (int)kind_len, kind, kind + kind_len);
419 assert((size_t)n < sizeof(buffer), "Unexpected number of characters in string");
420 } else {
421 kind_len = format_len;
422 int n = os::snprintf(buffer, sizeof(buffer), "%s_done", kind);
423 assert((size_t)n < sizeof(buffer), "Unexpected number of characters in string");
424 }
425 // Output the trailing event with the timestamp.
426 va_begin_elem(buffer, ap);
427 stamp();
428 end_elem();
429 // Output the tail-tag of the enclosing element.
430 buffer[kind_len] = 0;
431 tail(buffer);
432 }
433 PRAGMA_DIAG_POP
434
435 // Output a timestamp attribute.
436 void xmlStream::stamp() {
437 assert(inside_attrs_or_error(), "stamp must be an attribute");
438 print_raw(" stamp='");
439 out()->stamp();
440 print_raw("'");
441 }
442
443
444 // ------------------------------------------------------------------
445 // Output a method attribute, in the form " method='pkg/cls name sig'".
446 // This is used only when there is no ciMethod available.
447 void xmlStream::method(Method* method, const char* pfx) {
448 assert(inside_attrs_or_error(), "printing attributes");
449 if (method == nullptr) return;
450 if (*pfx) {
451 print(" %smethod='", pfx);
452 method_text(method);
453 print_raw("'");
454 return;
455 }
456 print(" method='");
457 method_text(method);
458 print("' bytes='%d'", method->code_size());
459 print(" count='%d'", method->invocation_count());
460 if (RecordTraining) {
461 // print stuff about this method's compilation history
462 print(" highest_comp_level='%d'", method->highest_comp_level());
463 nmethod* nm = method->code();
464 if (nm != nullptr) print(" last_compile_id='%d'", nm->compile_id());
465 }
466 int bec = method->backedge_count();
467 if (bec != 0) print(" backedge_count='%d'", bec);
468 print(" iicount='%d'", method->interpreter_invocation_count());
469 int throwouts = method->interpreter_throwout_count();
470 if (throwouts != 0) print(" throwouts='%d'", throwouts);
471 MethodData* mdo = method->method_data();
472 if (mdo != nullptr) {
473 uint cnt;
474 cnt = mdo->decompile_count();
475 if (cnt != 0) print(" decompiles='%d'", cnt);
476 for (uint reason = 0; reason < mdo->trap_reason_limit(); reason++) {
477 cnt = mdo->trap_count(reason);
478 if (cnt != 0) print(" %s_traps='%d'", Deoptimization::trap_reason_name(reason), cnt);
479 }
480 cnt = mdo->overflow_trap_count();
481 if (cnt != 0) print(" overflow_traps='%d'", cnt);
482 cnt = mdo->overflow_recompile_count();
483 if (cnt != 0) print(" overflow_recompiles='%d'", cnt);
484 }
485 }
486
487 void xmlStream::method_text(Method* method) {
488 ResourceMark rm;
489 assert(inside_attrs_or_error(), "printing attributes");
490 if (method == nullptr) return;
491 text()->print("%s", method->method_holder()->external_name());
492 print_raw(" "); // " " is easier for tools to parse than "::"
493 method->name()->print_symbol_on(text());
494 print_raw(" "); // separator
495 method->signature()->print_symbol_on(text());
496 }
497
498
499 // ------------------------------------------------------------------
500 // Output a klass attribute, in the form " klass='pkg/cls'".
501 // This is used only when there is no ciKlass available.
502 void xmlStream::klass(Klass* klass, const char* pfx) {
503 assert(inside_attrs_or_error(), "printing attributes");
504 if (klass == nullptr) return;
505 print(" %sklass='", pfx);
506 klass_text(klass);
507 print_raw("'");
508 if (klass->class_loader() != nullptr) {
509 loader(klass->class_loader(), pfx);
510 }
511 }
512
513 void xmlStream::klass_text(Klass* klass) {
514 assert(inside_attrs_or_error(), "printing attributes");
515 if (klass == nullptr) return;
516 //klass->print_short_name(log->out());
517 klass->name()->print_symbol_on(out());
518 if (klass->is_hidden()) {
519 out()->print(" //hidden");
520 // FIXME: maybe hash the contents of its classfile
521 }
522 }
523
524 void xmlStream::loader(oop cl, const char* pfx) {
525 assert(inside_attrs_or_error(), "printing attributes");
526 if (cl == nullptr) return;
527 print(" %sloader='", pfx);
528 loader_text(cl);
529 print_raw("'");
530 }
531
532 void xmlStream::loader_text(oop cl) {
533 assert(inside_attrs_or_error(), "printing attributes");
534 if (cl == nullptr) return;
535 oop id = java_lang_ClassLoader::nameAndId(cl);
536 if (id != nullptr) string_text(id);
537 }
538
539 void xmlStream::name(const Symbol* name, const char* pfx) {
540 assert(inside_attrs_or_error(), "printing attributes");
541 if (name == nullptr) return;
542 print(" %sname='", pfx);
543 symbol_text(name);
544 print_raw("'");
545 }
546
547 void xmlStream::signature(const Symbol* sig, const char* pfx) {
548 assert(inside_attrs_or_error(), "printing attributes");
549 if (sig == nullptr) return;
550 print(" %ssignature='", pfx);
551 symbol_text(sig);
552 print_raw("'");
553 }
554
555 void xmlStream::symbol_text(const Symbol* name) {
556 assert(inside_attrs_or_error(), "printing attributes");
557 if (name == nullptr) return;
558 //name->print_short_name(text());
559 //name->print_symbol_on(text()); // this has odd escapes in it (\\x%04x)
560 const char* base = (const char*) name->base();
561 int len = name->utf8_length();
562 log_only()->write(base, len);
563 }
564
565 void xmlStream::string_text(oop str) {
566 assert(inside_attrs_or_error(), "printing attributes");
567 if (str == nullptr) return;
568 if (!java_lang_String::is_instance(str)) {
569 print("*** not a string*** ");
570 str->print_value_on(log_only());
571 return;
572 }
573 ResourceMark rm;
574 log_only()->print_raw(java_lang_String::as_utf8_string(str));
575 }
576
577 void xmlStream::thread(Thread* t, const char* pfx) {
578 assert(inside_attrs_or_error(), "printing attributes");
579 intx tid = t == nullptr ? os::current_thread_id() : t->osthread()->thread_id();
580 guarantee(tid == (t == nullptr ? Thread::current() : t)->osthread()->thread_id(), "");
581 print(" %sthread=%zd", pfx, tid);
582 }
583
584 void xmlStream::object(const char* attr, Handle x) {
585 assert(inside_attrs_or_error(), "printing attributes");
586 if (x == nullptr) return;
587 print_raw(" ");
588 print_raw(attr);
589 print_raw("='");
590 object_text(x);
591 print_raw("'");
592 }
593
594 void xmlStream::object_text(Handle x) {
595 assert(inside_attrs_or_error(), "printing attributes");
596 if (x.is_null()) return;
597 if (java_lang_ClassLoader::is_instance(x())) {
598 print_raw("loader:");
599 loader_text(x());
600 return;
601 }
602 if (java_lang_String::is_instance(x())) {
603 print_raw("string:");
604 string_text(x());
605 return;
606 }
607 x->print_value_on(log_only());
608 }
609
610
611 void xmlStream::object(const char* attr, Metadata* x) {
612 assert(inside_attrs_or_error(), "printing attributes");
613 if (x == nullptr) return;
614 print_raw(" ");
615 print_raw(attr);
616 print_raw("='");
617 object_text(x);
618 print_raw("'");
619 }
620
621 void xmlStream::object_text(Metadata* x) {
622 assert(inside_attrs_or_error(), "printing attributes");
623 if (x == nullptr) return;
624 //x->print_value_on(text());
625 if (x->is_method())
626 method_text((Method*)x);
627 else if (x->is_klass())
628 klass_text((Klass*)x);
629 else
630 ShouldNotReachHere(); // Add impl if this is reached.
631 }
632
633
634 void xmlStream::flush() {
635 out()->flush();
636 _last_flush = count();
637 }
638
639 void xmlTextStream::flush() {
640 if (_outer_xmlStream == nullptr) return;
641 _outer_xmlStream->flush();
642 }
643
644 void xmlTextStream::write(const char* str, size_t len) {
645 if (_outer_xmlStream == nullptr) return;
646 _outer_xmlStream->write_text(str, len);
647 update_position(str, len);
648 }