8382430: Extend output format of -XX:+PrintCompilation2 diagnostic flag

Reviewed-by: vlivanov, aseoane

Author: Vladimir Kozlov

src/hotspot/share/compiler/compileBroker.cpp

@@ -345,6 +345,8 @@ void CompileQueue::add(CompileTask* task) {
   // Mark the method as being in the compile queue.
   task->method()->set_queued_for_compilation();
 
+  task->mark_queued(os::elapsed_counter());
+
   if (CIPrintCompileQueue) {
     print_tty();
   }
@@ -2402,23 +2404,19 @@ void CompileBroker::invoke_compiler_on_method(CompileTask* task) {
     }
   }
 
-  DirectivesStack::release(directive);
+  task->mark_finished(os::elapsed_counter());
 
   methodHandle method(thread, task->method());
 
   DTRACE_METHOD_COMPILE_END_PROBE(method, compiler_name(task_level), task->is_success());
 
   collect_statistics(thread, time, task);
 
-  if (PrintCompilation && PrintCompilation2) {
-    tty->print("%7d ", (int) tty->time_stamp().milliseconds());  // print timestamp
-    tty->print("%4d ", compile_id);    // print compilation number
-    tty->print("%s ", (is_osr ? "%" : " "));
-    if (task->is_success()) {
-      tty->print("size: %d(%d) ", task->nm_total_size(), task->nm_insts_size());
-    }
-    tty->print_cr("time: %d inlined: %d bytes", (int)time.milliseconds(), task->num_inlined_bytecodes());
+  if (PrintCompilation2 || directive->PrintCompilation2Option) {
+    ResourceMark rm;
+    task->print_post(tty);
   }
+  DirectivesStack::release(directive);
 
   Log(compilation, codecache) log;
   if (log.is_debug()) {
@@ -2614,7 +2612,7 @@ void CompileBroker::collect_statistics(CompilerThread* thread, elapsedTimer time
       }
 
       // Collect statistic per compiler
-      AbstractCompiler* comp = compiler(comp_level);
+      AbstractCompiler* comp = task->compiler();
       if (comp) {
         CompilerStatistics* stats = comp->stats();
         if (is_osr) {

src/hotspot/share/compiler/compileTask.cpp

@@ -51,26 +51,31 @@ CompileTask::CompileTask(int compile_id,
   _method_holder = JNIHandles::make_weak_global(Handle(thread, method->method_holder()->klass_holder()));
   _osr_bci = osr_bci;
   _is_blocking = is_blocking;
-  JVMCI_ONLY(_has_waiter = CompileBroker::compiler(comp_level)->is_jvmci();)
-  JVMCI_ONLY(_blocking_jvmci_compile_state = nullptr;)
   _comp_level = comp_level;
   _num_inlined_bytecodes = 0;
 
   _is_complete = false;
   _is_success = false;
 
   _hot_count = hot_count;
-  _time_queued = os::elapsed_counter();
+  _time_created = os::elapsed_counter();
+  _time_queued = 0;
   _time_started = 0;
+  _time_finished = 0;
   _compile_reason = compile_reason;
   _nm_content_size = 0;
-  AbstractCompiler* comp = compiler();
-  _directive = DirectivesStack::getMatchingDirective(method, comp);
   _nm_insts_size = 0;
   _nm_total_size = 0;
   _failure_reason = nullptr;
   _failure_reason_on_C_heap = false;
   _training_data = nullptr;
+
+  AbstractCompiler* comp = CompileBroker::compiler(comp_level);
+  _compiler = comp;
+  _directive = DirectivesStack::getMatchingDirective(method, comp);
+
+  JVMCI_ONLY(_has_waiter = comp->is_jvmci();)
+  JVMCI_ONLY(_blocking_jvmci_compile_state = nullptr;)
   _arena_bytes = 0;
 
   _next = nullptr;
@@ -108,7 +113,8 @@ void CompileTask::wait_for_no_active_tasks() {
  * Returns the compiler for this task.
  */
 AbstractCompiler* CompileTask::compiler() const {
-  return CompileBroker::compiler(_comp_level);
+  assert(_compiler != nullptr, "should be set");
+  return _compiler;
 }
 
 // Replace weak handles by strong handles to avoid unloading during compilation.
@@ -157,7 +163,7 @@ void CompileTask::metadata_do(MetadataClosure* f) {
 //
 void CompileTask::print_line_on_error(outputStream* st, char* buf, int buflen) {
   // print compiler name
-  st->print("%s:", CompileBroker::compiler_name(comp_level()));
+  st->print("%s:", compiler()->name());
   print(st);
 }
 
@@ -168,29 +174,71 @@ void CompileTask::print_tty() {
   print(tty);
 }
 
+void CompileTask::print_post(outputStream* st) {
+  bool is_osr_method = osr_bci() != InvocationEntryBci;
+  print_impl(st, is_unloaded() ? nullptr : method(), compile_id(), comp_level(),
+             is_osr_method, osr_bci(), is_blocking(),
+             compiler()->name(), nullptr, false /* short_form */, true /* cr */,
+             true /* after_compile_details */,
+             _num_inlined_bytecodes, _nm_total_size, _nm_insts_size,
+             _time_created, _time_queued, _time_started, _time_finished);
+}
+
 // ------------------------------------------------------------------
 // CompileTask::print_impl
 void CompileTask::print_impl(outputStream* st, Method* method, int compile_id, int comp_level,
                              bool is_osr_method, int osr_bci, bool is_blocking,
-                             const char* msg, bool short_form, bool cr,
-                             jlong time_queued, jlong time_started) {
-  if (!short_form) {
+                             const char* compiler_name,
+                             const char* msg, bool short_form, bool cr, bool after_compile_details,
+                             int inlined_bytecodes, int nm_total_size, int nm_insts_size,
+                             jlong time_created, jlong time_queued, jlong time_started, jlong time_finished) {
+  // Use stringStream to avoid breaking the line
+  stringStream sst;
+  if (after_compile_details) {
+    { // Print current time
+      stringStream ss;
+      ss.print(UINT64_FORMAT, (uint64_t) tty->time_stamp().milliseconds());
+      sst.print("%7s ", ss.freeze());
+    }
+    { // Time waiting to be put on queue
+      stringStream ss;
+      if (time_created != 0 && time_queued != 0) {
+        ss.print("W%.1f", TimeHelper::counter_to_millis(time_queued - time_created));
+      }
+      sst.print("%7s ", ss.freeze());
+    }
+    { // Time in queue
+      stringStream ss;
+      if (time_queued != 0 && time_started != 0) {
+        ss.print("Q%.1f", TimeHelper::counter_to_millis(time_started - time_queued));
+      }
+      sst.print("%7s ", ss.freeze());
+    }
+    { // Time in compilation
+      stringStream ss;
+      if (time_started != 0 && time_finished != 0) {
+        ss.print("C%.1f", TimeHelper::counter_to_millis(time_finished - time_started));
+      }
+      sst.print("%7s ", ss.freeze());
+    }
+  } else if (!short_form) {
     // Print current time
-    st->print(UINT64_FORMAT " ", (uint64_t) tty->time_stamp().milliseconds());
+    sst.print(UINT64_FORMAT " ", (uint64_t) tty->time_stamp().milliseconds());
     if (Verbose && time_queued != 0) {
       // Print time in queue and time being processed by compiler thread
       jlong now = os::elapsed_counter();
-      st->print("%.0f ", TimeHelper::counter_to_millis(now-time_queued));
+      sst.print("%.0f ", TimeHelper::counter_to_millis(now-time_queued));
       if (time_started != 0) {
-        st->print("%.0f ", TimeHelper::counter_to_millis(now-time_started));
+        sst.print("%.0f ", TimeHelper::counter_to_millis(now-time_started));
       }
     }
   }
+
   // print compiler name if requested
   if (CIPrintCompilerName) {
-    st->print("%s:", CompileBroker::compiler_name(comp_level));
+    sst.print("%s:", compiler_name);
   }
-  st->print("%4d ", compile_id);    // print compilation number
+  sst.print("%4d ", compile_id);    // print compilation number
 
   bool is_synchronized = false;
   bool has_exception_handler = false;
@@ -208,40 +256,52 @@ void CompileTask::print_impl(outputStream* st, Method* method, int compile_id, i
   const char native_char    = is_native                       ? 'n' : ' ';
 
   // print method attributes
-  st->print("%c%c%c%c%c ", compile_type, sync_char, exception_char, blocking_char, native_char);
+  sst.print("%c%c%c%c%c ", compile_type, sync_char, exception_char, blocking_char, native_char);
 
   if (TieredCompilation) {
-    if (comp_level != -1)  st->print("%d ", comp_level);
-    else                   st->print("- ");
+    if (comp_level != -1)  sst.print("%d ", comp_level);
+    else                   sst.print("- ");
   }
-  st->print("     ");  // more indent
+  sst.print("     ");  // more indent
 
   if (method == nullptr) {
-    st->print("(method)");
+    sst.print("(method)");
   } else {
-    method->print_short_name(st);
+    if (after_compile_details) {
+      sst.print("%s", method->name_and_sig_as_C_string(true /* use_double_colon */));
+    } else {
+      method->print_short_name(&sst);
+    }
     if (is_osr_method) {
-      st->print(" @ %d", osr_bci);
+      sst.print(" @ %d", osr_bci);
     }
-    if (method->is_native())
-      st->print(" (native)");
-    else
-      st->print(" (%d bytes)", method->code_size());
+    if (method->is_native()) {
+      sst.print(" (native)");
+    } else {
+      sst.print(" (%d bytes)", method->code_size());
+    }
+  }
+  if (after_compile_details) {
+    sst.print(" (inlined %d)", inlined_bytecodes);
+    sst.print(" (size %d/%d)", nm_total_size, nm_insts_size);
   }
 
   if (msg != nullptr) {
-    st->print("   %s", msg);
+    sst.print("   %s", msg);
   }
   if (cr) {
-    st->cr();
+    sst.cr();
   }
+  st->print("%s",sst.freeze());
 }
 
 // ------------------------------------------------------------------
 // CompileTask::print_compilation
 void CompileTask::print(outputStream* st, const char* msg, bool short_form, bool cr) {
   bool is_osr_method = osr_bci() != InvocationEntryBci;
-  print_impl(st, is_unloaded() ? nullptr : method(), compile_id(), comp_level(), is_osr_method, osr_bci(), is_blocking(), msg, short_form, cr, _time_queued, _time_started);
+  print_impl(st, is_unloaded() ? nullptr : method(), compile_id(), comp_level(),
+             is_osr_method, osr_bci(), is_blocking(),
+             compiler()->name(), msg, short_form, cr);
 }
 
 // ------------------------------------------------------------------
@@ -435,6 +495,7 @@ void CompileTask::print_ul(const nmethod* nm, const char* msg) {
                nm->comp_level(), nm->is_osr_method(),
                nm->is_osr_method() ? nm->osr_entry_bci() : -1,
                /*is_blocking*/ false,
+               nm->compiler_name(),
                msg, /* short form */ true, /* cr */ true);
   }
 }

src/hotspot/share/compiler/compileTask.hpp

@@ -93,7 +93,8 @@ class CompileTask : public CHeapObj<mtCompiler> {
   CodeSection::csize_t _nm_content_size;
   CodeSection::csize_t _nm_total_size;
   CodeSection::csize_t _nm_insts_size;
-  DirectiveSet*  _directive;
+  DirectiveSet*        _directive;
+  AbstractCompiler*    _compiler;
 #if INCLUDE_JVMCI
   bool                 _has_waiter;
   // Compilation state for a blocking JVMCI compilation
@@ -104,8 +105,10 @@ class CompileTask : public CHeapObj<mtCompiler> {
   CompileTask*         _next;
   CompileTask*         _prev;
   // Fields used for logging why the compilation was initiated:
+  jlong                _time_created; // time when task was created
   jlong                _time_queued;  // time when task was enqueued
   jlong                _time_started; // time when compilation started
+  jlong                _time_finished; // time when compilation finished
   int                  _hot_count;    // information about its invocation counter
   CompileReason        _compile_reason;      // more info about the task
   const char*          _failure_reason;
@@ -118,6 +121,7 @@ class CompileTask : public CHeapObj<mtCompiler> {
   CompileTask(int compile_id, const methodHandle& method, int osr_bci, int comp_level,
               int hot_count, CompileReason compile_reason, bool is_blocking);
   ~CompileTask();
+
   static void wait_for_no_active_tasks();
 
   int          compile_id() const                { return _compile_id; }
@@ -127,6 +131,7 @@ class CompileTask : public CHeapObj<mtCompiler> {
   bool         is_blocking() const               { return _is_blocking; }
   bool         is_success() const                { return _is_success; }
   DirectiveSet* directive() const                { return _directive; }
+  CompileReason compile_reason() const           { return _compile_reason; }
   CodeSection::csize_t nm_content_size() { return _nm_content_size; }
   void         set_nm_content_size(CodeSection::csize_t size) { _nm_content_size = size; }
   CodeSection::csize_t nm_insts_size() { return _nm_insts_size; }
@@ -166,8 +171,9 @@ class CompileTask : public CHeapObj<mtCompiler> {
 
   void         mark_complete()                   { _is_complete = true; }
   void         mark_success()                    { _is_success = true; }
+  void         mark_queued(jlong time)           { _time_queued = time; }
   void         mark_started(jlong time)          { _time_started = time; }
-
+  void         mark_finished(jlong time)         { _time_finished = time; }
   int          comp_level()                      { return _comp_level;}
   void         set_comp_level(int comp_level)    { _comp_level = comp_level;}
 
@@ -198,16 +204,20 @@ class CompileTask : public CHeapObj<mtCompiler> {
 private:
   static void  print_impl(outputStream* st, Method* method, int compile_id, int comp_level,
                                       bool is_osr_method = false, int osr_bci = -1, bool is_blocking = false,
+                                      const char* compiler_name = nullptr,
                                       const char* msg = nullptr, bool short_form = false, bool cr = true,
-                                      jlong time_queued = 0, jlong time_started = 0);
+                                      bool after_compile_details = false,
+                                      int inlined_bytecodes = 0, int nm_total_size = 0, int nm_insts_size = 0,
+                                      jlong time_created = 0, jlong time_queued = 0,
+                                      jlong time_started = 0, jlong time_finished = 0);
 
 public:
   void         print(outputStream* st = tty, const char* msg = nullptr, bool short_form = false, bool cr = true);
   void         print_ul(const char* msg = nullptr);
   static void  print(outputStream* st, const nmethod* nm, const char* msg = nullptr, bool short_form = false, bool cr = true) {
     print_impl(st, nm->method(), nm->compile_id(), nm->comp_level(),
-                           nm->is_osr_method(), nm->is_osr_method() ? nm->osr_entry_bci() : -1, /*is_blocking*/ false,
-                           msg, short_form, cr);
+               nm->is_osr_method(), nm->is_osr_method() ? nm->osr_entry_bci() : -1, /*is_blocking*/ false,
+               nm->compiler_name(), msg, short_form, cr);
   }
   static void  print_ul(const nmethod* nm, const char* msg = nullptr);
 
@@ -217,6 +227,7 @@ class CompileTask : public CHeapObj<mtCompiler> {
   static void  print_inline_indent(int inline_level, outputStream* st = tty);
 
   void         print_tty();
+  void         print_post(outputStream* st);
   void         print_line_on_error(outputStream* st, char* buf, int buflen);
 
   void         log_task(xmlStream* log);

src/hotspot/share/compiler/compilerDirectives.hpp

@@ -44,6 +44,7 @@
     cflags(MemStat,                 uintx, 0, MemStat) \
     cflags(PrintAssembly,           bool, PrintAssembly, PrintAssembly) \
     cflags(PrintCompilation,        bool, PrintCompilation, PrintCompilation) \
+    cflags(PrintCompilation2,       bool, PrintCompilation2, PrintCompilation2) \
     cflags(PrintInlining,           bool, PrintInlining, PrintInlining) \
     cflags(PrintNMethods,           bool, PrintNMethods, PrintNMethods) \
     cflags(BackgroundCompilation,   bool, BackgroundCompilation, BackgroundCompilation) \

src/hotspot/share/compiler/compilerOracle.hpp

@@ -63,6 +63,7 @@ class methodHandle;
   option(MemStat, "MemStat", Uintx) \
   option(PrintAssembly, "PrintAssembly", Bool) \
   option(PrintCompilation, "PrintCompilation", Bool) \
+  option(PrintCompilation2, "PrintCompilation2", Bool) \
   option(PrintInlining, "PrintInlining", Bool) \
   option(PrintIntrinsics, "PrintIntrinsics", Bool) \
   option(PrintNMethods, "PrintNMethods", Bool)   \

src/hotspot/share/oops/method.cpp

@@ -184,24 +184,30 @@ address Method::get_c2i_no_clinit_check_entry() {
   return adapter()->get_c2i_no_clinit_check_entry();
 }
 
-char* Method::name_and_sig_as_C_string() const {
-  return name_and_sig_as_C_string(constants()->pool_holder(), name(), signature());
+char* Method::name_and_sig_as_C_string(bool use_double_colon) const {
+  return name_and_sig_as_C_string(constants()->pool_holder(), name(), signature(), use_double_colon);
 }
 
 char* Method::name_and_sig_as_C_string(char* buf, int size) const {
   return name_and_sig_as_C_string(constants()->pool_holder(), name(), signature(), buf, size);
 }
 
-char* Method::name_and_sig_as_C_string(Klass* klass, Symbol* method_name, Symbol* signature) {
+char* Method::name_and_sig_as_C_string(Klass* klass, Symbol* method_name, Symbol* signature, bool use_double_colon) {
   const char* klass_name = klass->external_name();
   int klass_name_len  = (int)strlen(klass_name);
   int method_name_len = method_name->utf8_length();
-  int len             = klass_name_len + 1 + method_name_len + signature->utf8_length();
+  int separator_len   = use_double_colon ? 2 : 1;
+  int len             = klass_name_len + separator_len + method_name_len + signature->utf8_length();
   char* dest          = NEW_RESOURCE_ARRAY(char, len + 1);
   strcpy(dest, klass_name);
-  dest[klass_name_len] = '.';
-  strcpy(&dest[klass_name_len + 1], method_name->as_C_string());
-  strcpy(&dest[klass_name_len + 1 + method_name_len], signature->as_C_string());
+  if (use_double_colon) {
+    dest[klass_name_len + 0] = ':';
+    dest[klass_name_len + 1] = ':';
+  } else {
+    dest[klass_name_len] = '.';
+  }
+  strcpy(&dest[klass_name_len + separator_len], method_name->as_C_string());
+  strcpy(&dest[klass_name_len + separator_len + method_name_len], signature->as_C_string());
   dest[len] = 0;
   return dest;
 }