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: "&lt;", "&gt;", "&amp;",
 64 // "&apos", "&quot".  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 = "&apos;"; break;
147     case '"':  esc = "&quot;"; break;
148     case '<':  esc = "&lt;";   break;
149     case '&':  esc = "&amp;";  break;
150       // This is a freebie.
151     case '>':  esc = "&gt;";   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     CompiledMethod* cm = method->code();
465     if (cm != nullptr)  print(" last_compile_id='%d'", cm->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 }