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