changeset 60684:865b2c989ca8

8251093: Improve C1 register allocator logging and debugging support Summary: Various printing and debug improvements to better analyze C1 register allocator problems. Reviewed-by: kvn, thartmann
author chagedorn
date Wed, 26 Aug 2020 13:46:46 +0200
parents 569f413b9754
children fd07cdb26fc7
files src/hotspot/cpu/x86/c1_LinearScan_x86.hpp src/hotspot/share/c1/c1_CFGPrinter.cpp src/hotspot/share/c1/c1_Compilation.cpp src/hotspot/share/c1/c1_Compilation.hpp src/hotspot/share/c1/c1_IR.cpp src/hotspot/share/c1/c1_LinearScan.cpp src/hotspot/share/c1/c1_LinearScan.hpp test/hotspot/jtreg/compiler/c1/TestTraceLinearScanLevel.java
diffstat 8 files changed, 201 insertions(+), 84 deletions(-) [+]
line wrap: on
line diff
--- a/src/hotspot/cpu/x86/c1_LinearScan_x86.hpp	Wed Aug 26 13:41:49 2020 +0200
+++ b/src/hotspot/cpu/x86/c1_LinearScan_x86.hpp	Wed Aug 26 13:46:46 2020 +0200
@@ -78,7 +78,7 @@
       // assume that slow paths are uncommon but it's not clear that
       // would be a good idea.
       if (UseSSE > 0) {
-#ifndef PRODUCT
+#ifdef ASSERT
         if (TraceLinearScanLevel >= 2) {
           tty->print_cr("killing XMMs for trig");
         }
--- a/src/hotspot/share/c1/c1_CFGPrinter.cpp	Wed Aug 26 13:41:49 2020 +0200
+++ b/src/hotspot/share/c1/c1_CFGPrinter.cpp	Wed Aug 26 13:46:46 2020 +0200
@@ -297,8 +297,6 @@
   print_end("block");
 }
 
-
-
 void CFGPrinterOutput::print_cfg(BlockList* blocks, const char* name) {
   print_begin("cfg");
   print("name \"%s\"", name);
@@ -321,16 +319,13 @@
   output()->flush();
 }
 
-
-
-
 void CFGPrinterOutput::print_intervals(IntervalList* intervals, const char* name) {
   print_begin("intervals");
   print("name \"%s\"", name);
 
   for (int i = 0; i < intervals->length(); i++) {
     if (intervals->at(i) != NULL) {
-      intervals->at(i)->print(output());
+      intervals->at(i)->print_on(output());
     }
   }
 
@@ -338,5 +333,4 @@
   output()->flush();
 }
 
-
-#endif
+#endif // NOT PRODUCT
--- a/src/hotspot/share/c1/c1_Compilation.cpp	Wed Aug 26 13:41:49 2020 +0200
+++ b/src/hotspot/share/c1/c1_Compilation.cpp	Wed Aug 26 13:46:46 2020 +0200
@@ -700,7 +700,6 @@
   compile_only_this_scope(&stream, hir()->top_scope());
 }
 
-
 void Compilation::compile_only_this_scope(outputStream* st, IRScope* scope) {
   st->print("CompileOnly=");
   scope->method()->holder()->name()->print_symbol_on(st);
@@ -709,7 +708,6 @@
   st->cr();
 }
 
-
 void Compilation::exclude_this_method() {
   fileStream stream(fopen(".hotspot_compiler", "at"));
   stream.print("exclude ");
@@ -719,4 +717,10 @@
   stream.cr();
   stream.cr();
 }
-#endif
+
+// Called from debugger to get the interval with 'reg_num' during register allocation.
+Interval* find_interval(int reg_num) {
+  return Compilation::current()->allocator()->find_interval_at(reg_num);
+}
+
+#endif // NOT PRODUCT
--- a/src/hotspot/share/c1/c1_Compilation.hpp	Wed Aug 26 13:41:49 2020 +0200
+++ b/src/hotspot/share/c1/c1_Compilation.hpp	Wed Aug 26 13:46:46 2020 +0200
@@ -109,7 +109,6 @@
   ExceptionInfoList* exception_info_list() const { return _exception_info_list; }
   ExceptionHandlerTable* exception_handler_table() { return &_exception_handler_table; }
 
-  LinearScan* allocator()                          { return _allocator;      }
   void        set_allocator(LinearScan* allocator) { _allocator = allocator; }
 
   Instruction*       _current_instruction;       // the instruction currently being processed
@@ -150,6 +149,7 @@
   Arena* arena()                                 { return _arena; }
   bool has_access_indexed()                      { return _has_access_indexed; }
   bool should_install_code()                     { return _install_code && InstallMethods; }
+  LinearScan* allocator()                        { return _allocator; }
 
   // Instruction ids
   int get_next_id()                              { return _next_id++; }
--- a/src/hotspot/share/c1/c1_IR.cpp	Wed Aug 26 13:41:49 2020 +0200
+++ b/src/hotspot/share/c1/c1_IR.cpp	Wed Aug 26 13:46:46 2020 +0200
@@ -440,7 +440,7 @@
 
 
 // helper macro for short definition of trace-output inside code
-#ifndef PRODUCT
+#ifdef ASSERT
   #define TRACE_LINEAR_SCAN(level, code)       \
     if (TraceLinearScanLevel >= level) {       \
       code;                                    \
@@ -509,7 +509,7 @@
   void compute_dominators();
 
   // debug functions
-  NOT_PRODUCT(void print_blocks();)
+  DEBUG_ONLY(void print_blocks();)
   DEBUG_ONLY(void verify();)
 
   Compilation* compilation() const { return _compilation; }
@@ -559,7 +559,7 @@
   compute_order(start_block);
   compute_dominators();
 
-  NOT_PRODUCT(print_blocks());
+  DEBUG_ONLY(print_blocks());
   DEBUG_ONLY(verify());
 }
 
@@ -1047,7 +1047,7 @@
 }
 
 
-#ifndef PRODUCT
+#ifdef ASSERT
 void ComputeLinearScanOrder::print_blocks() {
   if (TraceLinearScanLevel >= 2) {
     tty->print_cr("----- loop information:");
@@ -1104,9 +1104,7 @@
     }
   }
 }
-#endif
 
-#ifdef ASSERT
 void ComputeLinearScanOrder::verify() {
   assert(_linear_scan_order->length() == _num_blocks, "wrong number of blocks in list");
 
@@ -1182,7 +1180,7 @@
     }
   }
 }
-#endif
+#endif // ASSERT
 
 
 void IR::compute_code() {
--- a/src/hotspot/share/c1/c1_LinearScan.cpp	Wed Aug 26 13:41:49 2020 +0200
+++ b/src/hotspot/share/c1/c1_LinearScan.cpp	Wed Aug 26 13:46:46 2020 +0200
@@ -46,17 +46,19 @@
   // helper macro for short definition of timer
   #define TIME_LINEAR_SCAN(timer_name)  TraceTime _block_timer("", _total_timer.timer(LinearScanTimers::timer_name), TimeLinearScan || TimeEachLinearScan, Verbose);
 
+#else
+  #define TIME_LINEAR_SCAN(timer_name)
+#endif
+
+#ifdef ASSERT
+
   // helper macro for short definition of trace-output inside code
   #define TRACE_LINEAR_SCAN(level, code)       \
     if (TraceLinearScanLevel >= level) {       \
       code;                                    \
     }
-
 #else
-
-  #define TIME_LINEAR_SCAN(timer_name)
   #define TRACE_LINEAR_SCAN(level, code)
-
 #endif
 
 // Map BasicType to spill size in 32-bit words, matching VMReg's notion of words
@@ -792,7 +794,7 @@
         live_in.set_union(block->live_gen());
       }
 
-#ifndef PRODUCT
+#ifdef ASSERT
       if (TraceLinearScanLevel >= 4) {
         char c = ' ';
         if (iteration_count == 0 || change_occurred_in_block) {
@@ -3201,7 +3203,47 @@
   }
 }
 
-#endif //PRODUCT
+void LinearScan::print_reg_num(outputStream* out, int reg_num) {
+  if (reg_num == -1) {
+    out->print("[ANY]");
+    return;
+  } else if (reg_num >= LIR_OprDesc::vreg_base) {
+    out->print("[VREG %d]", reg_num);
+    return;
+  }
+
+  LIR_Opr opr = LIR_OprFact::illegal();
+
+#ifdef X86
+  int last_xmm_reg = pd_last_xmm_reg;
+#ifdef _LP64
+  if (UseAVX < 3) {
+    last_xmm_reg = pd_first_xmm_reg + (pd_nof_xmm_regs_frame_map / 2) - 1;
+  }
+#endif
+#endif
+  if (reg_num >= pd_first_cpu_reg && reg_num <= pd_last_cpu_reg) {
+    opr = LIR_OprFact::single_cpu(reg_num);
+  } else if (reg_num >= pd_first_fpu_reg && reg_num <= pd_last_fpu_reg) {
+    opr = LIR_OprFact::single_fpu(reg_num - pd_first_fpu_reg);
+#ifdef X86
+  } else if (reg_num >= pd_first_xmm_reg && reg_num <= last_xmm_reg) {
+    opr = LIR_OprFact::single_xmm(reg_num - pd_first_xmm_reg);
+#endif
+  } else {
+    assert(false, "unknown register");
+  }
+  opr->print(out);
+}
+
+Interval* LinearScan::find_interval_at(int reg_num) const {
+  if (reg_num < 0 || reg_num >= _intervals.length()) {
+    return NULL;
+  }
+  return interval_at(reg_num);
+}
+
+#endif // PRODUCT
 
 
 // ********** verification functions for allocation
@@ -4556,49 +4598,28 @@
 
 
 #ifndef PRODUCT
-void Interval::print(outputStream* out) const {
+void Interval::print_on(outputStream* out) const {
   const char* SpillState2Name[] = { "no definition", "no spill store", "one spill store", "store at definition", "start in memory", "no optimization" };
   const char* UseKind2Name[] = { "N", "L", "S", "M" };
 
   const char* type_name;
-  LIR_Opr opr = LIR_OprFact::illegal();
   if (reg_num() < LIR_OprDesc::vreg_base) {
     type_name = "fixed";
-    // need a temporary operand for fixed intervals because type() cannot be called
-#ifdef X86
-    int last_xmm_reg = pd_last_xmm_reg;
-#ifdef _LP64
-    if (UseAVX < 3) {
-      last_xmm_reg = pd_first_xmm_reg + (pd_nof_xmm_regs_frame_map / 2) - 1;
-    }
-#endif
-#endif
-    if (assigned_reg() >= pd_first_cpu_reg && assigned_reg() <= pd_last_cpu_reg) {
-      opr = LIR_OprFact::single_cpu(assigned_reg());
-    } else if (assigned_reg() >= pd_first_fpu_reg && assigned_reg() <= pd_last_fpu_reg) {
-      opr = LIR_OprFact::single_fpu(assigned_reg() - pd_first_fpu_reg);
-#ifdef X86
-    } else if (assigned_reg() >= pd_first_xmm_reg && assigned_reg() <= last_xmm_reg) {
-      opr = LIR_OprFact::single_xmm(assigned_reg() - pd_first_xmm_reg);
-#endif
-    } else {
-      ShouldNotReachHere();
-    }
   } else {
     type_name = type2name(type());
-    if (assigned_reg() != -1 &&
-        (LinearScan::num_physical_regs(type()) == 1 || assigned_regHi() != -1)) {
-      opr = LinearScan::calc_operand_for_interval(this);
-    }
   }
 
   out->print("%d %s ", reg_num(), type_name);
-  if (opr->is_valid()) {
-    out->print("\"");
-    opr->print(out);
-    out->print("\" ");
-  }
-  out->print("%d %d ", split_parent()->reg_num(), (register_hint(false) != NULL ? register_hint(false)->reg_num() : -1));
+  if (reg_num() < LIR_OprDesc::vreg_base) {
+    LinearScan::print_reg_num(out, assigned_reg());
+  } else if (assigned_reg() != -1 && (LinearScan::num_physical_regs(type()) == 1 || assigned_regHi() != -1)) {
+    LinearScan::calc_operand_for_interval(this)->print(out);
+  } else {
+    // Virtual register that has no assigned register yet.
+    out->print("[ANY]");
+  }
+
+  out->print(" %d %d ", split_parent()->reg_num(), (register_hint(false) != NULL ? register_hint(false)->reg_num() : -1));
 
   // print ranges
   Range* cur = _first;
@@ -4622,7 +4643,28 @@
   out->print(" \"%s\"", SpillState2Name[spill_state()]);
   out->cr();
 }
-#endif
+
+void Interval::print_parent() const {
+  if (_split_parent != this) {
+    _split_parent->print_on(tty);
+  } else {
+    tty->print_cr("Parent: this");
+  }
+}
+
+void Interval::print_children() const {
+  if (_split_children == NULL) {
+    tty->print_cr("Children: []");
+  } else {
+    tty->print_cr("Children:");
+    for (int i = 0; i < _split_children->length(); i++) {
+      tty->print("%d: ", i);
+      _split_children->at(i)->print_on(tty);
+    }
+  }
+}
+#endif // NOT PRODUCT
+
 
 
 
@@ -4727,7 +4769,7 @@
         if (cur->current_at_end()) {
           // move to handled state (not maintained as a list)
           cur->set_state(handledState);
-          interval_moved(cur, kind, state, handledState);
+          DEBUG_ONLY(interval_moved(cur, kind, state, handledState);)
         } else if (cur->current_from() <= from){
           // sort into active list
           append_sorted(active_first_addr(kind), cur);
@@ -4736,7 +4778,7 @@
             assert(state == activeState, "check");
             prev = cur->next_addr();
           }
-          interval_moved(cur, kind, state, activeState);
+          DEBUG_ONLY(interval_moved(cur, kind, state, activeState);)
         } else {
           // sort into inactive list
           append_sorted(inactive_first_addr(kind), cur);
@@ -4745,7 +4787,7 @@
             assert(state == inactiveState, "check");
             prev = cur->next_addr();
           }
-          interval_moved(cur, kind, state, inactiveState);
+          DEBUG_ONLY(interval_moved(cur, kind, state, inactiveState);)
         }
       } else {
         prev = cur->next_addr();
@@ -4801,7 +4843,7 @@
       current()->set_state(activeState);
       if (activate_current()) {
         append_sorted(active_first_addr(current_kind()), current());
-        interval_moved(current(), current_kind(), unhandledState, activeState);
+        DEBUG_ONLY(interval_moved(current(), current_kind(), unhandledState, activeState);)
       }
 
       next_interval();
@@ -4811,8 +4853,8 @@
   }
 }
 
+#ifdef ASSERT
 void IntervalWalker::interval_moved(Interval* interval, IntervalKind kind, IntervalState from, IntervalState to) {
-#ifndef PRODUCT
   if (TraceLinearScanLevel >= 4) {
     #define print_state(state) \
     switch(state) {\
@@ -4829,10 +4871,8 @@
 
     #undef print_state
   }
-#endif
-}
-
-
+}
+#endif // ASSERT
 
 // **** Implementation of LinearScanWalker **************************
 
@@ -5305,7 +5345,6 @@
   }
 }
 
-
 int LinearScanWalker::find_free_reg(int reg_needed_until, int interval_to, int hint_reg, int ignore_reg, bool* need_split) {
   int min_full_reg = any_reg;
   int max_partial_reg = any_reg;
@@ -5367,7 +5406,6 @@
   }
 }
 
-
 bool LinearScanWalker::alloc_free_reg(Interval* cur) {
   TRACE_LINEAR_SCAN(2, tty->print("trying to find free register for "); cur->print());
 
@@ -5381,8 +5419,16 @@
   // _use_pos contains the start of the next interval that has this register assigned
   // (either as a fixed register or a normal allocated register in the past)
   // only intervals overlapping with cur are processed, non-overlapping invervals can be ignored safely
-  TRACE_LINEAR_SCAN(4, tty->print_cr("      state of registers:"));
-  TRACE_LINEAR_SCAN(4, for (int i = _first_reg; i <= _last_reg; i++) tty->print_cr("      reg %d: use_pos: %d", i, _use_pos[i]));
+#ifdef ASSERT
+  if (TraceLinearScanLevel >= 4) {
+    tty->print_cr("      state of registers:");
+    for (int i = _first_reg; i <= _last_reg; i++) {
+      tty->print("      reg %d (", i);
+      LinearScan::print_reg_num(i);
+      tty->print_cr("): use_pos: %d", _use_pos[i]);
+    }
+  }
+#endif
 
   int hint_reg, hint_regHi;
   Interval* register_hint = cur->register_hint();
@@ -5394,8 +5440,16 @@
       assert(hint_reg != any_reg && hint_regHi == any_reg, "must be for fixed intervals");
       hint_regHi = hint_reg + 1;  // connect e.g. eax-edx
     }
-    TRACE_LINEAR_SCAN(4, tty->print("      hint registers %d, %d from interval ", hint_reg, hint_regHi); register_hint->print());
-
+#ifdef ASSERT
+    if (TraceLinearScanLevel >= 4) {
+      tty->print("      hint registers %d (", hint_reg);
+      LinearScan::print_reg_num(hint_reg);
+      tty->print("), %d (", hint_regHi);
+      LinearScan::print_reg_num(hint_regHi);
+      tty->print(") from interval ");
+      register_hint->print();
+    }
+#endif
   } else {
     hint_reg = any_reg;
     hint_regHi = any_reg;
@@ -5450,8 +5504,15 @@
   }
 
   cur->assign_reg(reg, regHi);
-  TRACE_LINEAR_SCAN(2, tty->print_cr("selected register %d, %d", reg, regHi));
-
+#ifdef ASSERT
+  if (TraceLinearScanLevel >= 2) {
+    tty->print("      selected registers %d (", reg);
+    LinearScan::print_reg_num(reg);
+    tty->print("), %d (", regHi);
+    LinearScan::print_reg_num(regHi);
+    tty->print_cr(")");
+  }
+#endif
   assert(split_pos > 0, "invalid split_pos");
   if (need_split) {
     // register not available for full interval, so split it
@@ -5539,11 +5600,13 @@
   spill_collect_active_any();
   spill_collect_inactive_any(cur);
 
-#ifndef PRODUCT
+#ifdef ASSERT
   if (TraceLinearScanLevel >= 4) {
     tty->print_cr("      state of registers:");
     for (int i = _first_reg; i <= _last_reg; i++) {
-      tty->print("      reg %d: use_pos: %d, block_pos: %d, intervals: ", i, _use_pos[i], _block_pos[i]);
+      tty->print("      reg %d(", i);
+      LinearScan::print_reg_num(i);
+      tty->print("): use_pos: %d, block_pos: %d, intervals: ", _use_pos[i], _block_pos[i]);
       for (int j = 0; j < _spill_intervals[i]->length(); j++) {
         tty->print("%d ", _spill_intervals[i]->at(j)->reg_num());
       }
@@ -5613,7 +5676,15 @@
 
     split_and_spill_interval(cur);
   } else {
-    TRACE_LINEAR_SCAN(4, tty->print_cr("decided to use register %d, %d", reg, regHi));
+#ifdef ASSERT
+    if (TraceLinearScanLevel >= 4) {
+      tty->print("decided to use register %d (", reg);
+      LinearScan::print_reg_num(reg);
+      tty->print("), %d (", regHi);
+      LinearScan::print_reg_num(regHi);
+      tty->print_cr(")");
+    }
+#endif
     assert(reg != any_reg && (_num_phys_regs == 1 || regHi != any_reg), "no register found");
     assert(split_pos > 0, "invalid split_pos");
     assert(need_split == false || split_pos > cur->from(), "splitting interval at from");
--- a/src/hotspot/share/c1/c1_LinearScan.hpp	Wed Aug 26 13:41:49 2020 +0200
+++ b/src/hotspot/share/c1/c1_LinearScan.hpp	Wed Aug 26 13:46:46 2020 +0200
@@ -367,6 +367,8 @@
   static void print_bitmap(BitMap& bitmap);
   void        print_intervals(const char* label);
   void        print_lir(int level, const char* label, bool hir_valid = true);
+  static void print_reg_num(int reg_num) { print_reg_num(tty, reg_num); }
+  static void print_reg_num(outputStream* out, int reg_num);
 #endif
 
 #ifdef ASSERT
@@ -390,10 +392,13 @@
   int         max_spills()  const { return _max_spills; }
   int         num_calls() const   { assert(_num_calls >= 0, "not set"); return _num_calls; }
 
+#ifndef PRODUCT
   // entry functions for printing
-#ifndef PRODUCT
   static void print_statistics();
   static void print_timers(double total);
+
+  // Used for debugging
+  Interval* find_interval_at(int reg_num) const;
 #endif
 };
 
@@ -626,7 +631,15 @@
   int    current_intersects_at(Interval* it)     { return _current->intersects_at(it->_current); };
 
   // printing
-  void print(outputStream* out = tty) const      PRODUCT_RETURN;
+#ifndef PRODUCT
+  void print() const { print_on(tty); }
+  void print_on(outputStream* out) const;
+
+  // Used for debugging
+  void print_parent() const;
+  void print_children() const;
+#endif
+
 };
 
 
@@ -674,9 +687,9 @@
   // It is safe to append current to any interval list but the unhandled list.
   virtual bool activate_current() { return true; }
 
-  // interval_moved() is called whenever an interval moves from one interval list to another.
-  // In the implementation of this method it is prohibited to move the interval to any list.
-  virtual void interval_moved(Interval* interval, IntervalKind kind, IntervalState from, IntervalState to);
+  // This method is called whenever an interval moves from one interval list to another to print some
+  // information about it and its state change if TraceLinearScanLevel is set appropriately.
+  DEBUG_ONLY(void interval_moved(Interval* interval, IntervalKind kind, IntervalState from, IntervalState to);)
 
  public:
   IntervalWalker(LinearScan* allocator, Interval* unhandled_fixed_first, Interval* unhandled_any_first);
--- /dev/null	Thu Jan 01 00:00:00 1970 +0000
+++ b/test/hotspot/jtreg/compiler/c1/TestTraceLinearScanLevel.java	Wed Aug 26 13:46:46 2020 +0200
@@ -0,0 +1,37 @@
+/*
+ * Copyright (c) 2020, Oracle and/or its affiliates. All rights reserved.
+ * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
+ *
+ * This code is free software; you can redistribute it and/or modify it
+ * under the terms of the GNU General Public License version 2 only, as
+ * published by the Free Software Foundation.
+ *
+ * This code is distributed in the hope that it will be useful, but WITHOUT
+ * ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or
+ * FITNESS FOR A PARTICULAR PURPOSE.  See the GNU General Public License
+ * version 2 for more details (a copy is included in the LICENSE file that
+ * accompanied this code).
+ *
+ * You should have received a copy of the GNU General Public License version
+ * 2 along with this work; if not, write to the Free Software Foundation,
+ * Inc., 51 Franklin St, Fifth Floor, Boston, MA 02110-1301 USA.
+ *
+ * Please contact Oracle, 500 Oracle Parkway, Redwood Shores, CA 94065 USA
+ * or visit www.oracle.com if you need additional information or have any
+ * questions.
+ */
+
+/*
+ * @test
+ * @bug 8251093
+ * @summary Sanity check the flag TraceLinearScanLevel with the highest level in a silent HelloWorld program.
+ *
+ * @run main/othervm -XX:TraceLinearScanLevel=4 compiler.c1.TestTraceLinearScanLevel
+ */
+package compiler.c1;
+
+public class TestTraceLinearScanLevel {
+    public static void main(String[] strArr) {
+    }
+}
+