changeset 6310:b722c15be816

8005079: fix LogCompilation for incremental inlining Summary: report late inlining as part of the rest of the inlining output Reviewed-by: twisti, kvn
author roland
date Thu, 10 Apr 2014 11:38:12 +0200
parents b9d45b765b60
children ccb19a3a704a
files src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/CallSite.java src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/LogParser.java src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/Method.java src/share/vm/asm/codeBuffer.cpp src/share/vm/ci/ciKlass.cpp src/share/vm/ci/ciKlass.hpp src/share/vm/ci/ciSymbol.cpp src/share/vm/ci/ciSymbol.hpp src/share/vm/compiler/compileLog.cpp src/share/vm/compiler/compileLog.hpp src/share/vm/opto/callGenerator.cpp src/share/vm/opto/callGenerator.hpp src/share/vm/opto/compile.cpp src/share/vm/opto/compile.hpp src/share/vm/opto/doCall.cpp src/share/vm/utilities/xmlstream.cpp
diffstat 16 files changed, 273 insertions(+), 43 deletions(-) [+]
line wrap: on
line diff
--- a/src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/CallSite.java	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/CallSite.java	Thu Apr 10 11:38:12 2014 +0200
@@ -25,6 +25,7 @@
 package com.sun.hotspot.tools.compiler;
 
 import java.io.PrintStream;
+import java.util.ArrayDeque;
 import java.util.ArrayList;
 import java.util.List;
 
@@ -40,6 +41,7 @@
     private int endNodes;
     private int endLiveNodes;
     private double timeStamp;
+    private long inlineId;
 
     CallSite() {
     }
@@ -94,7 +96,7 @@
 
     public void print(PrintStream stream, int indent) {
         emit(stream, indent);
-        String m = getMethod().getHolder().replace('/', '.') + "::" + getMethod().getName();
+        String m = getMethod().getHolder() + "::" + getMethod().getName();
         if (getReason() == null) {
             stream.print("  @ " + getBci() + " " + m + " (" + getMethod().getBytes() + " bytes)");
 
@@ -214,4 +216,45 @@
         return timeStamp;
     }
 
+    private boolean matches(CallSite other) {
+        // Every late inline call site has a unique inline id. If the
+        // call site we're looking for has one then use it other rely
+        // on method name and bci.
+        if (other.inlineId != 0) {
+            return inlineId == other.inlineId;
+        }
+        return method.equals(other.method) && bci == other.bci;
+    }
+
+    public CallSite findCallSite(ArrayDeque<CallSite> sites) {
+        // Locate a late inline call site. Multiple chains of
+        // identical call sites with the same method name/bci are
+        // possible so we have to try them all until we find the late
+        // inline call site that has a matching inline id.
+        CallSite site = sites.pop();
+        for (CallSite c : calls) {
+            if (c.matches(site)) {
+                if (!sites.isEmpty()) {
+                    CallSite res = c.findCallSite(sites);
+                    if (res != null) {
+                        sites.push(site);
+                        return res;
+                    }
+                } else {
+                    sites.push(site);
+                    return c;
+                }
+            }
+        }
+        sites.push(site);
+        return null;
+    }
+
+    public long getInlineId() {
+        return inlineId;
+    }
+
+    public void setInlineId(long inlineId) {
+        this.inlineId = inlineId;
+    }
 }
--- a/src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/LogParser.java	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/LogParser.java	Thu Apr 10 11:38:12 2014 +0200
@@ -31,6 +31,7 @@
 
 import java.io.FileReader;
 import java.io.Reader;
+import java.util.ArrayDeque;
 import java.util.ArrayList;
 import java.util.Collections;
 import java.util.Comparator;
@@ -144,9 +145,12 @@
     private Stack<CallSite> scopes = new Stack<CallSite>();
     private Compilation compile;
     private CallSite site;
+    private CallSite methodHandleSite;
     private Stack<Phase> phaseStack = new Stack<Phase>();
     private UncommonTrapEvent currentTrap;
-    private Stack<CallSite> late_inline_scope;
+    private Stack<CallSite> lateInlineScope;
+    private boolean lateInlining;
+
 
     long parseLong(String l) {
         try {
@@ -330,18 +334,61 @@
             }
             methods.put(id, m);
         } else if (qname.equals("call")) {
-            site = new CallSite(bci, method(search(atts, "method")));
+            if (methodHandleSite != null) {
+                methodHandleSite = null;
+            }
+            Method m = method(search(atts, "method"));
+            if (lateInlining && scopes.size() == 0) {
+                // re-attempting already seen call site (late inlining for MH invokes)
+                if (m != site.getMethod()) {
+                    if (bci != site.getBci()) {
+                        System.out.println(m + " bci: " + bci);
+                        System.out.println(site.getMethod() +  " bci: " + site.getBci());
+                        throw new InternalError("bci mismatch after late inlining");
+                    }
+                    site.setMethod(m);
+                }
+            } else {
+                site = new CallSite(bci, m);
+            }
             site.setCount(Integer.parseInt(search(atts, "count", "0")));
             String receiver = atts.getValue("receiver");
             if (receiver != null) {
                 site.setReceiver(type(receiver));
                 site.setReceiver_count(Integer.parseInt(search(atts, "receiver_count")));
             }
-            scopes.peek().add(site);
+            int methodHandle = Integer.parseInt(search(atts, "method_handle_intrinsic", "0"));
+            if (lateInlining && scopes.size() == 0) {
+                // The call was added before this round of late inlining
+            } else if (methodHandle == 0) {
+                scopes.peek().add(site);
+            } else {
+                // method handle call site can be followed by another
+                // call (in case it is inlined). If that happens we
+                // discard the method handle call site. So we keep
+                // track of it but don't add it to the list yet.
+                methodHandleSite = site;
+            }
         } else if (qname.equals("regalloc")) {
             compile.setAttempts(Integer.parseInt(search(atts, "attempts")));
         } else if (qname.equals("inline_fail")) {
-            scopes.peek().last().setReason(search(atts, "reason"));
+            if (methodHandleSite != null) {
+                scopes.peek().add(methodHandleSite);
+                methodHandleSite = null;
+            }
+            if (lateInlining && scopes.size() == 0) {
+                site.setReason(search(atts, "reason"));
+                lateInlining = false;
+            } else {
+                scopes.peek().last().setReason(search(atts, "reason"));
+            }
+        } else if (qname.equals("inline_success")) {
+            if (methodHandleSite != null) {
+                throw new InternalError("method handle site should have been replaced");
+            }
+            if (lateInlining && scopes.size() == 0) {
+                site.setReason(null);
+            }
         } else if (qname.equals("failure")) {
             failureReason = search(atts, "reason");
         } else if (qname.equals("task_done")) {
@@ -371,22 +418,30 @@
                 // ignore for now
             }
         } else if (qname.equals("late_inline")) {
-            late_inline_scope = new Stack<CallSite>();
+            long inlineId = Long.parseLong(search(atts, "inline_id"));
+            lateInlineScope = new Stack<CallSite>();
             site = new CallSite(-999, method(search(atts, "method")));
-            late_inline_scope.push(site);
+            site.setInlineId(inlineId);
+            lateInlineScope.push(site);
         } else if (qname.equals("jvms")) {
             // <jvms bci='4' method='java/io/DataInputStream readChar ()C' bytes='40' count='5815' iicount='20815'/>
             if (currentTrap != null) {
                 currentTrap.addJVMS(atts.getValue("method"), Integer.parseInt(atts.getValue("bci")));
-            } else if (late_inline_scope != null) {
+            } else if (lateInlineScope != null) {
                 bci = Integer.parseInt(search(atts, "bci"));
                 site = new CallSite(bci, method(search(atts, "method")));
-                late_inline_scope.push(site);
+                lateInlineScope.push(site);
             } else {
                 // Ignore <eliminate_allocation type='667'>,
                 //        <eliminate_lock lock='1'>,
                 //        <replace_string_concat arguments='2' string_alloc='0' multiple='0'>
             }
+        } else if (qname.equals("inline_id")) {
+            if (methodHandleSite != null) {
+                throw new InternalError("method handle site should have been replaced");
+            }
+            long id = Long.parseLong(search(atts, "id"));
+            site.setInlineId(id);
         } else if (qname.equals("nmethod")) {
             String id = makeId(atts);
             NMethod nm = new NMethod(Double.parseDouble(search(atts, "stamp")),
@@ -396,8 +451,18 @@
             nmethods.put(id, nm);
             events.add(nm);
         } else if (qname.equals("parse")) {
+            if (methodHandleSite != null) {
+                throw new InternalError("method handle site should have been replaced");
+            }
             Method m = method(search(atts, "method"));
-            if (scopes.size() == 0) {
+            if (lateInlining && scopes.size() == 0) {
+                if (site.getMethod() != m) {
+                    System.out.println(site.getMethod());
+                    System.out.println(m);
+                    throw new InternalError("Unexpected method mismatch during late inlining");
+                }
+            }
+            if (scopes.size() == 0 && !lateInlining) {
                 compile.setMethod(m);
                 scopes.push(site);
             } else {
@@ -427,14 +492,19 @@
         if (qname.equals("parse")) {
             indent -= 2;
             scopes.pop();
+            if (scopes.size() == 0) {
+                lateInlining = false;
+            }
         } else if (qname.equals("uncommon_trap")) {
             currentTrap = null;
         } else if (qname.equals("late_inline")) {
             // Populate late inlining info.
-
-            // late_inline scopes are specified in reverse order:
+            if (scopes.size() != 0) {
+                throw new InternalError("scopes should be empty for late inline");
+            }
+            // late inline scopes are specified in reverse order:
             // compiled method should be on top of stack.
-            CallSite caller = late_inline_scope.pop();
+            CallSite caller = lateInlineScope.pop();
             Method m = compile.getMethod();
             if (m != caller.getMethod()) {
                 System.out.println(m);
@@ -444,28 +514,42 @@
 
             // late_inline contains caller+bci info, convert it
             // to bci+callee info used by LogCompilation.
-            site = compile.getLateInlineCall();
+            CallSite lateInlineSite = compile.getLateInlineCall();
+            ArrayDeque<CallSite> thisCallScopes = new ArrayDeque<CallSite>();
             do {
                 bci = caller.getBci();
                 // Next inlined call.
-                caller = late_inline_scope.pop();
+                caller = lateInlineScope.pop();
                 CallSite callee =  new CallSite(bci, caller.getMethod());
-                site.add(callee);
-                site = callee;
-            } while (!late_inline_scope.empty());
+                callee.setInlineId(caller.getInlineId());
+                thisCallScopes.addLast(callee);
+                lateInlineSite.add(callee);
+                lateInlineSite = callee;
+            } while (!lateInlineScope.empty());
+
+            site = compile.getCall().findCallSite(thisCallScopes);
+            if (site == null) {
+                System.out.println(caller.getMethod() + " bci: " + bci);
+                throw new InternalError("couldn't find call site");
+            }
+            lateInlining = true;
 
             if (caller.getBci() != -999) {
                 System.out.println(caller.getMethod());
                 throw new InternalError("broken late_inline info");
             }
             if (site.getMethod() != caller.getMethod()) {
-                System.out.println(site.getMethod());
-                System.out.println(caller.getMethod());
-                throw new InternalError("call site and late_inline info don't match");
+                if (site.getInlineId() == caller.getInlineId()) {
+                    site.setMethod(caller.getMethod());
+                } else {
+                    System.out.println(site.getMethod());
+                    System.out.println(caller.getMethod());
+                    throw new InternalError("call site and late_inline info don't match");
+                }
             }
             // late_inline is followed by parse with scopes.size() == 0,
             // 'site' will be pushed to scopes.
-            late_inline_scope = null;
+            lateInlineScope = null;
         } else if (qname.equals("task")) {
             types.clear();
             methods.clear();
--- a/src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/Method.java	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/tools/LogCompilation/src/com/sun/hotspot/tools/compiler/Method.java	Thu Apr 10 11:38:12 2014 +0200
@@ -51,15 +51,15 @@
 
     String format(int osr_bci) {
         if (osr_bci >= 0) {
-            return getHolder().replace('/', '.') + "::" + getName() + " @ " + osr_bci + " (" + getBytes() + " bytes)";
+            return getHolder() + "::" + getName() + " @ " + osr_bci + " (" + getBytes() + " bytes)";
         } else {
-            return getHolder().replace('/', '.') + "::" + getName() + " (" + getBytes() + " bytes)";
+            return getHolder() + "::" + getName() + " (" + getBytes() + " bytes)";
         }
     }
 
     @Override
     public String toString() {
-        return getHolder().replace('/', '.') + "::" + getName() + " (" + getBytes() + " bytes)";
+        return getHolder() + "::" + getName() + " (" + getBytes() + " bytes)";
     }
 
     public String getHolder() {
@@ -117,4 +117,14 @@
     public void setFlags(String flags) {
         this.flags = flags;
     }
+
+    @Override
+    public boolean equals(Object o) {
+        if (o instanceof Method) {
+            Method other = (Method)o;
+            return holder.equals(other.holder) && name.equals(other.name) &&
+                arguments.equals(other.arguments) && returnType.equals(other.returnType);
+        }
+        return false;
+    }
 }
--- a/src/share/vm/asm/codeBuffer.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/asm/codeBuffer.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -968,6 +968,7 @@
 
 void CodeBuffer::log_section_sizes(const char* name) {
   if (xtty != NULL) {
+    ttyLocker ttyl;
     // log info about buffer usage
     xtty->print_cr("<blob name='%s' size='%d'>", name, _total_size);
     for (int n = (int) CodeBuffer::SECT_FIRST; n < (int) CodeBuffer::SECT_LIMIT; n++) {
--- a/src/share/vm/ci/ciKlass.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/ci/ciKlass.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -237,3 +237,9 @@
 void ciKlass::print_name_on(outputStream* st) {
   name()->print_symbol_on(st);
 }
+
+const char* ciKlass::external_name() const {
+  GUARDED_VM_ENTRY(
+    return get_Klass()->external_name();
+  )
+}
--- a/src/share/vm/ci/ciKlass.hpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/ci/ciKlass.hpp	Thu Apr 10 11:38:12 2014 +0200
@@ -125,6 +125,8 @@
   virtual ciKlass* exact_klass() = 0;
 
   void print_name_on(outputStream* st);
+
+  const char* external_name() const;
 };
 
 #endif // SHARE_VM_CI_CIKLASS_HPP
--- a/src/share/vm/ci/ciSymbol.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/ci/ciSymbol.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -123,6 +123,10 @@
   GUARDED_VM_ENTRY(get_symbol()->print_symbol_on(st);)
 }
 
+const char* ciSymbol::as_klass_external_name() const {
+  GUARDED_VM_ENTRY(return get_symbol()->as_klass_external_name(););
+}
+
 // ------------------------------------------------------------------
 // ciSymbol::make_impl
 //
--- a/src/share/vm/ci/ciSymbol.hpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/ci/ciSymbol.hpp	Thu Apr 10 11:38:12 2014 +0200
@@ -90,6 +90,7 @@
   void print_symbol() {
     print_symbol_on(tty);
   }
+  const char* as_klass_external_name() const;
 
   // Make a ciSymbol from a C string.
   // Consider adding to vmSymbols.hpp instead of using this constructor.
--- a/src/share/vm/compiler/compileLog.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/compiler/compileLog.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -106,7 +106,7 @@
     if (mobj->is_klass()) {
       ciKlass* klass = mobj->as_klass();
       begin_elem("klass id='%d'", id);
-      name(klass->name());
+      name(klass);
       if (!klass->is_loaded()) {
         print(" unloaded='1'");
       } else {
@@ -171,6 +171,15 @@
   print("'");
 }
 
+void CompileLog::name(ciKlass* k) {
+  print(" name='");
+  if (!k->is_loaded()) {
+    text()->print(k->name()->as_klass_external_name());
+  } else {
+    text()->print(k->external_name());
+  }
+  print("'");
+}
 
 // ------------------------------------------------------------------
 // CompileLog::clear_identities
--- a/src/share/vm/compiler/compileLog.hpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/compiler/compileLog.hpp	Thu Apr 10 11:38:12 2014 +0200
@@ -28,6 +28,7 @@
 #include "utilities/xmlstream.hpp"
 
 class ciBaseObject;
+class ciKlass;
 class ciObject;
 class ciMetadata;
 class ciSymbol;
@@ -72,6 +73,7 @@
 
   void          name(ciSymbol* s);               // name='s'
   void          name(Symbol* s)                  { xmlStream::name(s); }
+  void          name(ciKlass* k);
 
   // Output an object description, return obj->ident().
   int           identify(ciBaseObject* obj);
--- a/src/share/vm/opto/callGenerator.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/opto/callGenerator.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -266,14 +266,17 @@
 
 // Allow inlining decisions to be delayed
 class LateInlineCallGenerator : public DirectCallGenerator {
+ private:
+  // unique id for log compilation
+  jlong _unique_id;
+
  protected:
   CallGenerator* _inline_cg;
-
   virtual bool do_late_inline_check(JVMState* jvms) { return true; }
 
  public:
   LateInlineCallGenerator(ciMethod* method, CallGenerator* inline_cg) :
-    DirectCallGenerator(method, true), _inline_cg(inline_cg) {}
+    DirectCallGenerator(method, true), _inline_cg(inline_cg), _unique_id(0) {}
 
   virtual bool is_late_inline() const { return true; }
 
@@ -283,6 +286,8 @@
   virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
     Compile *C = Compile::current();
 
+    C->log_inline_id(this);
+
     // Record that this call site should be revisited once the main
     // parse is finished.
     if (!is_mh_late_inline()) {
@@ -304,6 +309,14 @@
     C->print_inlining_move_to(this);
     C->print_inlining_update_delayed(this);
   }
+
+  virtual void set_unique_id(jlong id) {
+    _unique_id = id;
+  }
+
+  virtual jlong unique_id() const {
+    return _unique_id;
+  }
 };
 
 void LateInlineCallGenerator::do_late_inline() {
@@ -368,6 +381,8 @@
 
   C->print_inlining_move_to(this);
 
+  C->log_late_inline(this);
+
   // This check is done here because for_method_handle_inline() method
   // needs jvms for inlined state.
   if (!do_late_inline_check(jvms)) {
@@ -375,17 +390,6 @@
     return;
   }
 
-  CompileLog* log = C->log();
-  if (log != NULL) {
-    log->head("late_inline method='%d'", log->identify(method()));
-    JVMState* p = jvms;
-    while (p != NULL) {
-      log->elem("jvms bci='%d' method='%d'", p->bci(), log->identify(p->method()));
-      p = p->caller();
-    }
-    log->tail("late_inline");
-  }
-
   // Setup default node notes to be picked up by the inlining
   Node_Notes* old_nn = C->default_node_notes();
   if (old_nn != NULL) {
@@ -438,11 +442,12 @@
   virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
     JVMState* new_jvms = LateInlineCallGenerator::generate(jvms, parent_parser);
 
+    Compile* C = Compile::current();
     if (_input_not_const) {
       // inlining won't be possible so no need to enqueue right now.
       call_node()->set_generator(this);
     } else {
-      Compile::current()->add_late_inline(this);
+      C->add_late_inline(this);
     }
     return new_jvms;
   }
@@ -483,6 +488,9 @@
 
   virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
     Compile *C = Compile::current();
+
+    C->log_inline_id(this);
+
     C->add_string_late_inline(this);
 
     JVMState* new_jvms =  DirectCallGenerator::generate(jvms, parent_parser);
@@ -505,6 +513,8 @@
   virtual JVMState* generate(JVMState* jvms, Parse* parent_parser) {
     Compile *C = Compile::current();
 
+    C->log_inline_id(this);
+
     C->add_boxing_late_inline(this);
 
     JVMState* new_jvms =  DirectCallGenerator::generate(jvms, parent_parser);
@@ -786,6 +796,7 @@
       } else {
         const char* msg = "receiver not constant";
         if (PrintInlining)  C->print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
+        C->log_inline_failure(msg);
       }
     }
     break;
@@ -858,6 +869,7 @@
       } else {
         const char* msg = "member_name not constant";
         if (PrintInlining)  C->print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
+        C->log_inline_failure(msg);
       }
     }
     break;
--- a/src/share/vm/opto/callGenerator.hpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/opto/callGenerator.hpp	Thu Apr 10 11:38:12 2014 +0200
@@ -84,6 +84,9 @@
 
   virtual CallStaticJavaNode* call_node() const { ShouldNotReachHere(); return NULL; }
 
+  virtual void set_unique_id(jlong id)          { fatal("unique id only for late inlines"); };
+  virtual jlong unique_id() const               { fatal("unique id only for late inlines"); return 0; };
+
   // Note:  It is possible for a CG to be both inline and virtual.
   // (The hashCode intrinsic does a vtable check and an inlined fast path.)
 
--- a/src/share/vm/opto/compile.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/opto/compile.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -3851,7 +3851,7 @@
 
 void Compile::dump_inlining() {
   bool do_print_inlining = print_inlining() || print_intrinsics();
-  if (do_print_inlining) {
+  if (do_print_inlining || log() != NULL) {
     // Print inlining message for candidates that we couldn't inline
     // for lack of space
     for (int i = 0; i < _late_inlines.length(); i++) {
@@ -3861,6 +3861,7 @@
         if (do_print_inlining) {
           cg->print_inlining_late(msg);
         }
+        log_late_inline_failure(cg, msg);
       }
     }
   }
@@ -3871,6 +3872,48 @@
   }
 }
 
+void Compile::log_late_inline(CallGenerator* cg) {
+  if (log() != NULL) {
+    log()->head("late_inline method='%d'  inline_id='" JLONG_FORMAT "'", log()->identify(cg->method()),
+                cg->unique_id());
+    JVMState* p = cg->call_node()->jvms();
+    while (p != NULL) {
+      log()->elem("jvms bci='%d' method='%d'", p->bci(), log()->identify(p->method()));
+      p = p->caller();
+    }
+    log()->tail("late_inline");
+  }
+}
+
+void Compile::log_late_inline_failure(CallGenerator* cg, const char* msg) {
+  log_late_inline(cg);
+  if (log() != NULL) {
+    log()->inline_fail(msg);
+  }
+}
+
+void Compile::log_inline_id(CallGenerator* cg) {
+  if (log() != NULL) {
+    // The LogCompilation tool needs a unique way to identify late
+    // inline call sites. This id must be unique for this call site in
+    // this compilation. Try to have it unique across compilations as
+    // well because it can be convenient when grepping through the log
+    // file.
+    // Distinguish OSR compilations from others in case CICountOSR is
+    // on.
+    jlong id = ((jlong)unique()) + (((jlong)compile_id()) << 33) + (CICountOSR && is_osr_compilation() ? ((jlong)1) << 32 : 0);
+    cg->set_unique_id(id);
+    log()->elem("inline_id id='" JLONG_FORMAT "'", id);
+  }
+}
+
+void Compile::log_inline_failure(const char* msg) {
+  if (C->log() != NULL) {
+    C->log()->inline_fail(msg);
+  }
+}
+
+
 // Dump inlining replay data to the stream.
 // Don't change thread state and acquire any locks.
 void Compile::dump_inline_data(outputStream* out) {
--- a/src/share/vm/opto/compile.hpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/opto/compile.hpp	Thu Apr 10 11:38:12 2014 +0200
@@ -440,6 +440,8 @@
   void print_inlining_push();
   PrintInliningBuffer& print_inlining_current();
 
+  void log_late_inline_failure(CallGenerator* cg, const char* msg);
+
  public:
 
   outputStream* print_inlining_stream() const {
@@ -459,6 +461,10 @@
     print_inlining_stream()->print(ss.as_string());
   }
 
+  void log_late_inline(CallGenerator* cg);
+  void log_inline_id(CallGenerator* cg);
+  void log_inline_failure(const char* msg);
+
   void* replay_inline_data() const { return _replay_inline_data; }
 
   // Dump inlining replay data to the stream.
--- a/src/share/vm/opto/doCall.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/opto/doCall.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -104,6 +104,9 @@
         log->print(" receiver2='%d' receiver2_count='%d'", r2id, profile.receiver_count(1));
       }
     }
+    if (callee->is_method_handle_intrinsic()) {
+      log->print(" method_handle_intrinsic='1'");
+    }
     log->end_elem();
   }
 
@@ -296,6 +299,7 @@
   if (call_does_dispatch) {
     const char* msg = "virtual call";
     if (PrintInlining) print_inlining(callee, jvms->depth() - 1, jvms->bci(), msg);
+    C->log_inline_failure(msg);
     return CallGenerator::for_virtual_call(callee, vtable_index);
   } else {
     // Class Hierarchy Analysis or Type Profile reveals a unique target,
--- a/src/share/vm/utilities/xmlstream.cpp	Thu Apr 10 09:26:24 2014 +0200
+++ b/src/share/vm/utilities/xmlstream.cpp	Thu Apr 10 11:38:12 2014 +0200
@@ -396,10 +396,10 @@
 }
 
 void xmlStream::method_text(methodHandle method) {
+  ResourceMark rm;
   assert_if_no_error(inside_attrs(), "printing attributes");
   if (method.is_null())  return;
-  //method->print_short_name(text());
-  method->method_holder()->name()->print_symbol_on(text());
+  text()->print(method->method_holder()->external_name());
   print_raw(" ");  // " " is easier for tools to parse than "::"
   method->name()->print_symbol_on(text());
   print_raw(" ");  // separator