8311976: Inconsistency in usage of CITimeVerbose to generate compilation logs

Reviewed-by: kvn, thartmann

Author: ashu-mehra

src/hotspot/share/c1/c1_Compilation.cpp

@@ -54,7 +54,7 @@ typedef enum {
     _t_codeemit,
     _t_codeinstall,
   max_phase_timers
-} TimerName;
+} TimerId;
 
 static const char * timer_name[] = {
   "compile",
@@ -78,27 +78,29 @@ static int totalInstructionNodes = 0;
 class PhaseTraceTime: public TraceTime {
  private:
   CompileLog* _log;
-  TimerName _timer;
+  TimerId _timer_id;
+  bool _dolog;
 
  public:
-  PhaseTraceTime(TimerName timer)
-  : TraceTime("", &timers[timer], CITime || CITimeEach, Verbose),
-    _log(nullptr), _timer(timer)
+  PhaseTraceTime(TimerId timer_id)
+  : TraceTime(timer_name[timer_id], &timers[timer_id], CITime, CITimeVerbose),
+    _log(nullptr), _timer_id(timer_id), _dolog(CITimeVerbose)
   {
-    if (Compilation::current() != nullptr) {
+    if (_dolog) {
+      assert(Compilation::current() != nullptr, "sanity check");
       _log = Compilation::current()->log();
     }
 
     if (_log != nullptr) {
-      _log->begin_head("phase name='%s'", timer_name[_timer]);
+      _log->begin_head("phase name='%s'", timer_name[_timer_id]);
       _log->stamp();
       _log->end_head();
     }
   }
 
   ~PhaseTraceTime() {
     if (_log != nullptr)
-      _log->done("phase name='%s'", timer_name[_timer]);
+      _log->done("phase name='%s'", timer_name[_timer_id]);
   }
 };
 
@@ -587,11 +589,11 @@ Compilation::Compilation(AbstractCompiler* compiler, ciEnv* env, ciMethod* metho
 , _cfg_printer_output(nullptr)
 #endif // PRODUCT
 {
-  PhaseTraceTime timeit(_t_compile);
   _arena = Thread::current()->resource_area();
   _env->set_compiler_data(this);
   _exception_info_list = new ExceptionInfoList();
   _implicit_exception_table.set_size(0);
+  PhaseTraceTime timeit(_t_compile);
 #ifndef PRODUCT
   if (PrintCFGToFile) {
     _cfg_printer_output = new CFGPrinterOutput(this);

src/hotspot/share/opto/compile.cpp

@@ -673,13 +673,6 @@ Compile::Compile( ciEnv* ci_env, ciMethod* target, int osr_bci,
   C = this;
   CompileWrapper cw(this);
 
-  if (CITimeVerbose) {
-    tty->print(" ");
-    target->holder()->name()->print();
-    tty->print(".");
-    target->print_short_name();
-    tty->print("  ");
-  }
   TraceTime t1("Total compilation time", &_t_totalCompilation, CITime, CITimeVerbose);
   TraceTime t2(nullptr, &_t_methodCompilation, CITime, false);
 
@@ -4339,35 +4332,24 @@ void Compile::record_failure(const char* reason) {
 
 Compile::TracePhase::TracePhase(const char* name, elapsedTimer* accumulator)
   : TraceTime(name, accumulator, CITime, CITimeVerbose),
-    _phase_name(name), _dolog(CITimeVerbose)
+    _compile(nullptr), _log(nullptr), _phase_name(name), _dolog(CITimeVerbose)
 {
   if (_dolog) {
-    C = Compile::current();
-    _log = C->log();
-  } else {
-    C = nullptr;
-    _log = nullptr;
+    _compile = Compile::current();
+    _log = _compile->log();
   }
   if (_log != nullptr) {
-    _log->begin_head("phase name='%s' nodes='%d' live='%d'", _phase_name, C->unique(), C->live_nodes());
+    _log->begin_head("phase name='%s' nodes='%d' live='%d'", _phase_name, _compile->unique(), _compile->live_nodes());
     _log->stamp();
     _log->end_head();
   }
 }
 
 Compile::TracePhase::~TracePhase() {
-
-  C = Compile::current();
-  if (_dolog) {
-    _log = C->log();
-  } else {
-    _log = nullptr;
-  }
-
 #ifdef ASSERT
   if (PrintIdealNodeCount) {
     tty->print_cr("phase name='%s' nodes='%d' live='%d' live_graph_walk='%d'",
-                  _phase_name, C->unique(), C->live_nodes(), C->count_live_nodes_by_graph_walk());
+                  _phase_name, _compile->unique(), _compile->live_nodes(), _compile->count_live_nodes_by_graph_walk());
   }
 
   if (VerifyIdealNodeCount) {
@@ -4376,7 +4358,7 @@ Compile::TracePhase::~TracePhase() {
 #endif
 
   if (_log != nullptr) {
-    _log->done("phase name='%s' nodes='%d' live='%d'", _phase_name, C->unique(), C->live_nodes());
+    _log->done("phase name='%s' nodes='%d' live='%d'", _phase_name, _compile->unique(), _compile->live_nodes());
   }
 }
 

src/hotspot/share/opto/compile.hpp

@@ -228,7 +228,7 @@ class Compile : public Phase {
   // (The time collection itself is always conditionalized on CITime.)
   class TracePhase : public TraceTime {
    private:
-    Compile*    C;
+    Compile*    _compile;
     CompileLog* _log;
     const char* _phase_name;
     bool _dolog;

src/hotspot/share/utilities/xmlstream.cpp

@@ -357,11 +357,11 @@ void xmlStream::va_done(const char* format, va_list ap) {
   size_t kind_len;
   if (kind_end != nullptr) {
     kind_len = kind_end - kind;
-    int n = os::snprintf(buffer, sizeof(buffer), "%.*s_done", (int)kind_len, kind);
+    int n = os::snprintf(buffer, sizeof(buffer), "%.*s_done%s", (int)kind_len, kind, kind + kind_len);
     assert((size_t)n < sizeof(buffer), "Unexpected number of characters in string");
   } else {
     kind_len = format_len;
-    int n = os::snprintf(buffer, sizeof(buffer), "%s_done%s", kind, kind + kind_len);
+    int n = os::snprintf(buffer, sizeof(buffer), "%s_done", kind);
     assert((size_t)n < sizeof(buffer), "Unexpected number of characters in string");
   }
   // Output the trailing event with the timestamp.