Debug flag to print a summary of the inliner's work

Example output below. Note that inlining List.map fails because the
trait forwarder uses `INVOKESPECIAL` for now, will change with pr 5177.

$ cat Test.scala
class C {
  def foo = Map(1 -> 'a', 2 -> 'b')
  def bar(l: List[Int]) = l.map(_ + 1)
}

$ qsc -Yopt-log-inline _ -Yopt:l:classpath Test.scala
Inlining into C.foo (initially 36 instructions, ultimately 72):
  - Inlined scala/Predef$ArrowAssoc$.$minus$greater$extension (8 instructions) 2 times: the callee is annotated `@inline`

Inlining into C.bar (initially 12 instructions, ultimately 12):
  - Failed to inline scala/collection/immutable/List.map (the callee is a higher-order method, the argument for parameter (bf: Function1) is a function literal): The callee scala/collection/immutable/List::map(Lscala/Function1;Lscala/collection/generic/CanBuildFrom;)Ljava/lang/Object; contains the instruction INVOKESPECIAL scala/collection/TraversableLike.map (Lscala/Function1;Lscala/collection/generic/CanBuildFrom;)Ljava/lang/Object;
that would cause an IllegalAccessError when inlined into class C.

6 files changed, 87 insertions, 18 deletions

diff --git a/src/compiler/scala/tools/nsc/backend/jvm/opt/Inliner.scala b/src/compiler/scala/tools/nsc/backend/jvm/opt/Inliner.scala
index f35eaa45e9..4b65a566d3 100644
--- a/src/compiler/scala/tools/nsc/backend/jvm/opt/Inliner.scala
+++ b/src/compiler/scala/tools/nsc/backend/jvm/opt/Inliner.scala
@@ -25,6 +25,9 @@ class Inliner[BT <: BTypes](val btypes: BT) {
   import inlinerHeuristics._
   import backendUtils._
 
+  case class InlineLog(request: InlineRequest, sizeBefore: Int, sizeAfter: Int, sizeInlined: Int, warning: Option[CannotInlineWarning])
+  var inlineLog: List[InlineLog] = Nil
+
   def runInliner(): Unit = {
     for (request <- collectAndOrderInlineRequests) {
       val Right(callee) = request.callsite.callee // collectAndOrderInlineRequests returns callsites with a known callee
@@ -42,6 +45,29 @@ class Inliner[BT <: BTypes](val btypes: BT) {
         }
       }
     }
+
+    if (compilerSettings.YoptLogInline.isSetByUser) {
+      val methodPrefix = { val p = compilerSettings.YoptLogInline.value; if (p == "_") "" else p }
+      val byCallsiteMethod = inlineLog.groupBy(_.request.callsite.callsiteMethod).toList.sortBy(_._2.head.request.callsite.callsiteClass.internalName)
+      for ((m, mLogs) <- byCallsiteMethod) {
+        val initialSize = mLogs.minBy(_.sizeBefore).sizeBefore
+        val firstLog = mLogs.head
+        val methodName = s"${firstLog.request.callsite.callsiteClass.internalName}.${m.name}"
+        if (methodName.startsWith(methodPrefix)) {
+          println(s"Inlining into $methodName (initially $initialSize instructions, ultimately ${m.instructions.size}):")
+          val byCallee = mLogs.groupBy(_.request.callsite.callee.get).toList.sortBy(_._2.length).reverse
+          for ((c, cLogs) <- byCallee) {
+            val first = cLogs.head
+            if (first.warning.isEmpty) {
+              val num = if (cLogs.tail.isEmpty) "" else s" ${cLogs.length} times"
+              println(s"  - Inlined ${c.calleeDeclarationClass.internalName}.${c.callee.name} (${first.sizeInlined} instructions)$num: ${first.request.reason}")
+            } else
+              println(s"  - Failed to inline ${c.calleeDeclarationClass.internalName}.${c.callee.name} (${first.request.reason}): ${first.warning.get}")
+          }
+          println()
+        }
+      }
+    }
   }
 
   /**
@@ -184,7 +210,7 @@ class Inliner[BT <: BTypes](val btypes: BT) {
     def impl(post: InlineRequest, at: Callsite): List[InlineRequest] = {
       post.callsite.inlinedClones.find(_.clonedWhenInlining == at) match {
         case Some(clonedCallsite) =>
-          List(InlineRequest(clonedCallsite.callsite, post.post))
+          List(InlineRequest(clonedCallsite.callsite, post.post, post.reason))
         case None =>
           post.post.flatMap(impl(_, post.callsite)).flatMap(impl(_, at))
       }
@@ -199,9 +225,17 @@ class Inliner[BT <: BTypes](val btypes: BT) {
    * @return An inliner warning for each callsite that could not be inlined.
    */
   def inline(request: InlineRequest): List[CannotInlineWarning] = canInlineBody(request.callsite) match {
-    case Some(w) => List(w)
+    case Some(w) =>
+      if (compilerSettings.YoptLogInline.isSetByUser) {
+        val size = request.callsite.callsiteMethod.instructions.size
+        inlineLog ::= InlineLog(request, size, size, 0, Some(w))
+      }
+      List(w)
     case None =>
+      val sizeBefore = request.callsite.callsiteMethod.instructions.size
       inlineCallsite(request.callsite)
+      if (compilerSettings.YoptLogInline.isSetByUser)
+        inlineLog ::= InlineLog(request, sizeBefore, request.callsite.callsiteMethod.instructions.size, request.callsite.callee.get.callee.instructions.size, None)
       val postRequests = request.post.flatMap(adaptPostRequestForMainCallsite(_, request.callsite))
       postRequests flatMap inline
   }
diff --git a/src/compiler/scala/tools/nsc/backend/jvm/opt/InlinerHeuristics.scala b/src/compiler/scala/tools/nsc/backend/jvm/opt/InlinerHeuristics.scala
index 6aaf9734d3..fd65b71762 100644
--- a/src/compiler/scala/tools/nsc/backend/jvm/opt/InlinerHeuristics.scala
+++ b/src/compiler/scala/tools/nsc/backend/jvm/opt/InlinerHeuristics.scala
@@ -17,7 +17,7 @@ class InlinerHeuristics[BT <: BTypes](val bTypes: BT) {
   import inliner._
   import callGraph._
 
-  case class InlineRequest(callsite: Callsite, post: List[InlineRequest]) {
+  case class InlineRequest(callsite: Callsite, post: List[InlineRequest], reason: String) {
     // invariant: all post inline requests denote callsites in the callee of the main callsite
     for (pr <- post) assert(pr.callsite.callsiteMethod == callsite.callee.get.callee, s"Callsite method mismatch: main $callsite - post ${pr.callsite}")
   }
@@ -40,7 +40,7 @@ class InlinerHeuristics[BT <: BTypes](val bTypes: BT) {
       var requests = Set.empty[InlineRequest]
       callGraph.callsites(methodNode).valuesIterator foreach {
         case callsite @ Callsite(_, _, _, Right(Callee(callee, calleeDeclClass, safeToInline, canInlineFromSource, calleeAnnotatedInline, _, _, callsiteWarning)), _, _, _, pos, _, _) =>
-          inlineRequest(callsite) match {
+          inlineRequest(callsite, requests) match {
             case Some(Right(req)) => requests += req
             case Some(Left(w))    =>
               if ((calleeAnnotatedInline && bTypes.compilerSettings.YoptWarningEmitAtInlineFailed) || w.emitWarning(compilerSettings)) {
@@ -87,20 +87,29 @@ class InlinerHeuristics[BT <: BTypes](val bTypes: BT) {
    *           InlineRequest for the original callsite? new subclass of OptimizerWarning.
    *         `Some(Right)` if the callsite should be and can be inlined
    */
-  def inlineRequest(callsite: Callsite): Option[Either[OptimizerWarning, InlineRequest]] = {
+  def inlineRequest(callsite: Callsite, selectedRequestsForCallee: Set[InlineRequest]): Option[Either[OptimizerWarning, InlineRequest]] = {
     val callee = callsite.callee.get
-    def requestIfCanInline(callsite: Callsite): Either[OptimizerWarning, InlineRequest] = inliner.earlyCanInlineCheck(callsite) match {
+    def requestIfCanInline(callsite: Callsite, reason: String): Either[OptimizerWarning, InlineRequest] = inliner.earlyCanInlineCheck(callsite) match {
       case Some(w) => Left(w)
-      case None => Right(InlineRequest(callsite, Nil))
+      case None => Right(InlineRequest(callsite, Nil, reason))
     }
 
     compilerSettings.YoptInlineHeuristics.value match {
       case "everything" =>
-        if (callee.safeToInline) Some(requestIfCanInline(callsite))
+        if (callee.safeToInline) {
+          val reason = if (compilerSettings.YoptLogInline.isSetByUser) "the inline strategy is \"everything\"" else null
+          Some(requestIfCanInline(callsite, reason))
+        }
         else None
 
       case "at-inline-annotated" =>
-        if (callee.safeToInline && callee.annotatedInline) Some(requestIfCanInline(callsite))
+        if (callee.safeToInline && callee.annotatedInline) {
+          val reason = if (compilerSettings.YoptLogInline.isSetByUser) {
+            val what = if (callee.safeToInline) "callee" else "callsite"
+            s"the $what is annotated `@inline`"
+          } else null
+          Some(requestIfCanInline(callsite, reason))
+        }
         else None
 
       case "default" =>
@@ -108,7 +117,30 @@ class InlinerHeuristics[BT <: BTypes](val bTypes: BT) {
           def shouldInlineHO = callee.samParamTypes.nonEmpty && (callee.samParamTypes exists {
             case (index, _) => callsite.argInfos.contains(index)
           })
-          if (callee.annotatedInline || callsite.annotatedInline || shouldInlineHO) Some(requestIfCanInline(callsite))
+          if (callee.annotatedInline || callsite.annotatedInline || shouldInlineHO) {
+            val reason = if (compilerSettings.YoptLogInline.isSetByUser) {
+              if (callee.annotatedInline || callsite.annotatedInline) {
+                val what = if (callee.safeToInline) "callee" else "callsite"
+                s"the $what is annotated `@inline`"
+              } else {
+                val paramNames = Option(callee.callee.parameters).map(_.asScala.map(_.name).toVector)
+                def param(i: Int) = {
+                  def syn = s"<param $i>"
+                  paramNames.fold(syn)(v => v.applyOrElse(i, (_: Int) => syn))
+                }
+                def samInfo(i: Int, sam: String, arg: String) = s"the argument for parameter (${param(i)}: $sam) is a $arg"
+                val argInfos = for ((i, sam) <- callee.samParamTypes; info <- callsite.argInfos.get(i)) yield {
+                  val argKind = info match {
+                    case FunctionLiteral => "function literal"
+                    case ForwardedParam(_) => "parameter of the callsite method"
+                  }
+                  samInfo(i, sam.internalName.split('/').last, argKind)
+                }
+                s"the callee is a higher-order method, ${argInfos.mkString(", ")}"
+              }
+            } else null
+            Some(requestIfCanInline(callsite, reason))
+          }
           else None
         } else None
     }
diff --git a/src/compiler/scala/tools/nsc/backend/jvm/opt/LocalOpt.scala b/src/compiler/scala/tools/nsc/backend/jvm/opt/LocalOpt.scala
index 4e1349257e..4972a49bb4 100644
--- a/src/compiler/scala/tools/nsc/backend/jvm/opt/LocalOpt.scala
+++ b/src/compiler/scala/tools/nsc/backend/jvm/opt/LocalOpt.scala
@@ -231,7 +231,8 @@ class LocalOpt[BT <: BTypes](val btypes: BT) {
     // for local variables in dead blocks. Maybe that's a bug in the ASM framework.
 
     var currentTrace: String = null
-    val doTrace = compilerSettings.YoptTrace.isSetByUser && compilerSettings.YoptTrace.value == ownerClassName + "." + method.name
+    val methodPrefix = {val p = compilerSettings.YoptTrace.value; if (p == "_") "" else p }
+    val doTrace = compilerSettings.YoptTrace.isSetByUser && s"$ownerClassName.${method.name}".startsWith(methodPrefix)
     def traceIfChanged(optName: String): Unit = if (doTrace) {
       val after = AsmUtils.textify(method)
       if (currentTrace != after) {
diff --git a/src/compiler/scala/tools/nsc/settings/ScalaSettings.scala b/src/compiler/scala/tools/nsc/settings/ScalaSettings.scala
index 9a0d86a94d..aa43772dd7 100644
--- a/src/compiler/scala/tools/nsc/settings/ScalaSettings.scala
+++ b/src/compiler/scala/tools/nsc/settings/ScalaSettings.scala
@@ -302,7 +302,9 @@ trait ScalaSettings extends AbsScalaSettings
   def YoptWarningNoInlineMissingBytecode            = YoptWarnings.contains(YoptWarningsChoices.noInlineMissingBytecode)
   def YoptWarningNoInlineMissingScalaInlineInfoAttr = YoptWarnings.contains(YoptWarningsChoices.noInlineMissingScalaInlineInfoAttr)
 
-  val YoptTrace = StringSetting("-Yopt-trace", "package/Class.method", "Trace the optimizer progress for a specific method.", "")
+  val YoptTrace = StringSetting("-Yopt-trace", "package/Class.method", "Trace the optimizer progress for methods; `_` to print all, prefix match to select.", "")
+
+  val YoptLogInline = StringSetting("-Yopt-log-inline", "package/Class.method", "Print a summary of inliner activity; `_` to print all, prefix match to select.", "")
 
   private def removalIn212 = "This flag is scheduled for removal in 2.12. If you have a case where you need this flag then please report a bug."
 
diff --git a/src/compiler/scala/tools/nsc/util/StackTracing.scala b/src/compiler/scala/tools/nsc/util/StackTracing.scala
index fa4fe29f28..0765bb923f 100644
--- a/src/compiler/scala/tools/nsc/util/StackTracing.scala
+++ b/src/compiler/scala/tools/nsc/util/StackTracing.scala
@@ -19,7 +19,7 @@ private[util] trait StackTracing extends Any {
   def stackTracePrefixString(e: Throwable)(p: StackTraceElement => Boolean): String = {
     import collection.mutable.{ ArrayBuffer, ListBuffer }
     import compat.Platform.EOL
-    import util.Properties.isJavaAtLeast
+    import scala.util.Properties.isJavaAtLeast
 
     val sb = ListBuffer.empty[String]
 
diff --git a/test/junit/scala/tools/nsc/backend/jvm/opt/InlinerTest.scala b/test/junit/scala/tools/nsc/backend/jvm/opt/InlinerTest.scala
index fd020c7d93..fb708c4f29 100644
--- a/test/junit/scala/tools/nsc/backend/jvm/opt/InlinerTest.scala
+++ b/test/junit/scala/tools/nsc/backend/jvm/opt/InlinerTest.scala
@@ -72,7 +72,7 @@ class InlinerTest extends BytecodeTesting {
 
   def inlineTest(code: String, mod: ClassNode => Unit = _ => ()): MethodNode = {
     val (gMethod, fCall) = gMethAndFCallsite(code, mod)
-    inliner.inline(InlineRequest(fCall, Nil))
+    inliner.inline(InlineRequest(fCall, Nil, null))
     gMethod
   }
 
@@ -343,7 +343,7 @@ class InlinerTest extends BytecodeTesting {
     val warning = inliner.canInlineBody(call)
     assert(warning.isEmpty, warning)
 
-    inliner.inline(InlineRequest(call, Nil))
+    inliner.inline(InlineRequest(call, Nil, null))
     val ins = instructionsFromMethod(fMeth)
 
     // no invocations, lowestOneBit is inlined
@@ -976,7 +976,7 @@ class InlinerTest extends BytecodeTesting {
 
     inliner.inline(InlineRequest(hCall,
       post = List(InlineRequest(gCall,
-        post = List(InlineRequest(fCall, Nil))))))
+        post = List(InlineRequest(fCall, Nil, null)), null)), null))
     assertNoInvoke(convertMethod(iMeth)) // no invoke in i: first h is inlined, then the inlined call to g is also inlined, etc for f
     assertInvoke(convertMethod(gMeth), "C", "f") // g itself still has the call to f
   }
@@ -998,11 +998,11 @@ class InlinerTest extends BytecodeTesting {
     val bCall = getCallsite(c, "b")
     val cCall = getCallsite(d, "c")
 
-    inliner.inline(InlineRequest(bCall, Nil))
+    inliner.inline(InlineRequest(bCall, Nil, null))
 
     val req = InlineRequest(cCall,
       List(InlineRequest(bCall,
-        List(InlineRequest(aCall, Nil)))))
+        List(InlineRequest(aCall, Nil, null)), null)), null)
     inliner.inline(req)
 
     assertNoInvoke(convertMethod(d))