performance counters for macros expansions

2 files changed, 183 insertions, 171 deletions

diff --git a/src/compiler/scala/tools/nsc/typechecker/Macros.scala b/src/compiler/scala/tools/nsc/typechecker/Macros.scala
index 9608108a0d..be7db9a920 100644
--- a/src/compiler/scala/tools/nsc/typechecker/Macros.scala
+++ b/src/compiler/scala/tools/nsc/typechecker/Macros.scala
@@ -9,6 +9,7 @@ import scala.collection.mutable.ListBuffer
 import scala.compat.Platform.EOL
 import scala.reflect.makro.runtime.{Context => MacroContext}
 import scala.reflect.runtime.Mirror
+import util.Statistics._
 
 /**
  *  Code to deal with macros, namely with:
@@ -1002,159 +1003,165 @@ trait Macros { self: Analyzer =>
         delayed += expandee -> (typer.context, undetparams)
         Delay(expandee)
       } else {
-        val macroDef = expandee.symbol
-        macroRuntime(macroDef) match {
-          case Some(runtime) =>
-            val savedInfolevel = nodePrinters.infolevel
-            try {
-              // InfoLevel.Verbose examines and prints out infos of symbols
-              // by the means of this'es these symbols can climb up the lexical scope
-              // when these symbols will be examined by a node printer
-              // they will enumerate and analyze their children (ask for infos and tpes)
-              // if one of those children involves macro expansion, things might get nasty
-              // that's why I'm temporarily turning this behavior off
-              nodePrinters.infolevel = nodePrinters.InfoLevel.Quiet
-              val args = macroArgs(typer, expandee)
-              args match {
-                case Some(args) =>
-                  // adding stuff to openMacros is easy, but removing it is a nightmare
-                  // it needs to be sprinkled over several different code locations
-                  val (context: MacroContext) :: _ = args
-                  openMacros = context :: openMacros
-                  val expanded: MacroExpansionResult = try {
-                    val prevNumErrors = reporter.ERROR.count
-                    val expanded = runtime(args)
-                    val currNumErrors = reporter.ERROR.count
-                    if (currNumErrors != prevNumErrors) {
-                      fail(typer, expandee) // errors have been reported by the macro itself
-                    } else {
-                      expanded match {
-                        case expanded: Expr[_] =>
-                          if (macroDebug || macroCopypaste) {
-                            if (macroDebug) println("original:")
-                            println(expanded.tree)
-                            println(showRaw(expanded.tree))
-                          }
-
-                          freeTerms(expanded.tree) foreach (fte => typer.context.error(expandee.pos,
-                              ("macro expansion contains free term variable %s %s. "+
-                              "have you forgot to use eval when splicing this variable into a reifee? " +
-                              "if you have troubles tracking free term variables, consider using -Xlog-free-terms").format(fte.name, fte.origin)))
-                          freeTypes(expanded.tree) foreach (fty => typer.context.error(expandee.pos,
-                              ("macro expansion contains free type variable %s %s. "+
-                              "have you forgot to use c.TypeTag annotation for this type parameter? " +
-                              "if you have troubles tracking free type variables, consider using -Xlog-free-types").format(fty.name, fty.origin)))
-
-                          val currNumErrors = reporter.ERROR.count
-                          if (currNumErrors != prevNumErrors) {
-                            fail(typer, expandee)
-                          } else {
-                            // inherit the position from the first position-ful expandee in macro callstack
-                            // this is essential for sane error messages
-                            var tree = expanded.tree
-                            var position = openMacros.find(c => c.expandee.pos != NoPosition).map(_.expandee.pos).getOrElse(NoPosition)
-                            tree = atPos(position.focus)(tree)
-
-                            // now macro expansion gets typechecked against the macro definition return type
-                            // however, this happens in macroExpand, not here in macroExpand1
-                            Success(tree)
-                          }
-                        case expanded if expanded.isInstanceOf[Expr[_]] =>
-                          val msg = "macro must return a compiler-specific expr; returned value is Expr, but it doesn't belong to this compiler's universe"
-                          fail(typer, expandee, msg)
-                        case expanded =>
-                          val msg = "macro must return a compiler-specific expr; returned value is of class: %s".format(expanded.getClass)
-                          fail(typer, expandee, msg)
+        val start = startTimer(macroExpandNanos)
+        incCounter(macroExpandCount)
+        try {
+          val macroDef = expandee.symbol
+          macroRuntime(macroDef) match {
+            case Some(runtime) =>
+              val savedInfolevel = nodePrinters.infolevel
+              try {
+                // InfoLevel.Verbose examines and prints out infos of symbols
+                // by the means of this'es these symbols can climb up the lexical scope
+                // when these symbols will be examined by a node printer
+                // they will enumerate and analyze their children (ask for infos and tpes)
+                // if one of those children involves macro expansion, things might get nasty
+                // that's why I'm temporarily turning this behavior off
+                nodePrinters.infolevel = nodePrinters.InfoLevel.Quiet
+                val args = macroArgs(typer, expandee)
+                args match {
+                  case Some(args) =>
+                    // adding stuff to openMacros is easy, but removing it is a nightmare
+                    // it needs to be sprinkled over several different code locations
+                    val (context: MacroContext) :: _ = args
+                    openMacros = context :: openMacros
+                    val expanded: MacroExpansionResult = try {
+                      val prevNumErrors = reporter.ERROR.count
+                      val expanded = runtime(args)
+                      val currNumErrors = reporter.ERROR.count
+                      if (currNumErrors != prevNumErrors) {
+                        fail(typer, expandee) // errors have been reported by the macro itself
+                      } else {
+                        expanded match {
+                          case expanded: Expr[_] =>
+                            if (macroDebug || macroCopypaste) {
+                              if (macroDebug) println("original:")
+                              println(expanded.tree)
+                              println(showRaw(expanded.tree))
+                            }
+
+                            freeTerms(expanded.tree) foreach (fte => typer.context.error(expandee.pos,
+                                ("macro expansion contains free term variable %s %s. "+
+                                "have you forgot to use eval when splicing this variable into a reifee? " +
+                                "if you have troubles tracking free term variables, consider using -Xlog-free-terms").format(fte.name, fte.origin)))
+                            freeTypes(expanded.tree) foreach (fty => typer.context.error(expandee.pos,
+                                ("macro expansion contains free type variable %s %s. "+
+                                "have you forgot to use c.TypeTag annotation for this type parameter? " +
+                                "if you have troubles tracking free type variables, consider using -Xlog-free-types").format(fty.name, fty.origin)))
+
+                            val currNumErrors = reporter.ERROR.count
+                            if (currNumErrors != prevNumErrors) {
+                              fail(typer, expandee)
+                            } else {
+                              // inherit the position from the first position-ful expandee in macro callstack
+                              // this is essential for sane error messages
+                              var tree = expanded.tree
+                              var position = openMacros.find(c => c.expandee.pos != NoPosition).map(_.expandee.pos).getOrElse(NoPosition)
+                              tree = atPos(position.focus)(tree)
+
+                              // now macro expansion gets typechecked against the macro definition return type
+                              // however, this happens in macroExpand, not here in macroExpand1
+                              Success(tree)
+                            }
+                          case expanded if expanded.isInstanceOf[Expr[_]] =>
+                            val msg = "macro must return a compiler-specific expr; returned value is Expr, but it doesn't belong to this compiler's universe"
+                            fail(typer, expandee, msg)
+                          case expanded =>
+                            val msg = "macro must return a compiler-specific expr; returned value is of class: %s".format(expanded.getClass)
+                            fail(typer, expandee, msg)
+                        }
                       }
+                    } catch {
+                      case ex: Throwable =>
+                        openMacros = openMacros.tail
+                        throw ex
                     }
-                  } catch {
-                    case ex: Throwable =>
-                      openMacros = openMacros.tail
-                      throw ex
+                    if (!expanded.isInstanceOf[Success]) openMacros = openMacros.tail
+                    expanded
+                  case None =>
+                    fail(typer, expandee) // error has been reported by macroArgs
+                }
+              } catch {
+                case ex =>
+                  // [Eugene] any ideas about how to improve this one?
+                  val realex = ReflectionUtils.unwrapThrowable(ex)
+                  realex match {
+                    case realex: reflect.makro.runtime.AbortMacroException =>
+                      if (macroDebug || macroCopypaste) println("macro expansion has failed: %s".format(realex.msg))
+                      fail(typer, expandee) // error has been reported by abort
+                    case _ =>
+                      val message = {
+                        try {
+                          // the most reliable way of obtaining currently executing method
+                          // http://stackoverflow.com/questions/442747/getting-the-name-of-the-current-executing-method
+                          val currentMethodName = new Object(){}.getClass().getEnclosingMethod().getName
+                          val relevancyThreshold = realex.getStackTrace().indexWhere(este => este.getMethodName == currentMethodName)
+                          if (relevancyThreshold == -1) None
+                          else {
+                            var relevantElements = realex.getStackTrace().take(relevancyThreshold + 1)
+                            var framesTillReflectiveInvocationOfMacroImpl = relevantElements.reverse.indexWhere(_.isNativeMethod) + 1
+                            relevantElements = relevantElements dropRight framesTillReflectiveInvocationOfMacroImpl
+
+                            realex.setStackTrace(relevantElements)
+                            val message = new java.io.StringWriter()
+                            realex.printStackTrace(new java.io.PrintWriter(message))
+                            Some(EOL + message)
+                          }
+                        } catch {
+                          // if the magic above goes boom, just fall back to uninformative, but better than nothing, getMessage
+                          case ex: Throwable =>
+                            None
+                        }
+                      } getOrElse realex.getMessage
+                      fail(typer, expandee, "exception during macro expansion: " + message)
                   }
-                  if (!expanded.isInstanceOf[Success]) openMacros = openMacros.tail
-                  expanded
-                case None =>
-                  fail(typer, expandee) // error has been reported by macroArgs
+              } finally {
+                nodePrinters.infolevel = savedInfolevel
+              }
+            case None =>
+              def notFound() = {
+                typer.context.error(expandee.pos, "macro implementation not found: " + macroDef.name + " " +
+                  "(the most common reason for that is that you cannot use macro implementations in the same compilation run that defines them)\n" +
+                  "if you do need to define macro implementations along with the rest of your program, consider two-phase compilation with -Xmacro-fallback-classpath " +
+                  "in the second phase pointing to the output of the first phase")
+                None
               }
-            } catch {
-              case ex =>
-                // [Eugene] any ideas about how to improve this one?
-                val realex = ReflectionUtils.unwrapThrowable(ex)
-                realex match {
-                  case realex: reflect.makro.runtime.AbortMacroException =>
-                    if (macroDebug || macroCopypaste) println("macro expansion has failed: %s".format(realex.msg))
-                    fail(typer, expandee) // error has been reported by abort
+              def fallBackToOverridden(tree: Tree): Option[Tree] = {
+                tree match {
+                  case Select(qual, name) if (macroDef.isTermMacro) =>
+                    macroDef.allOverriddenSymbols match {
+                      case first :: _ =>
+                        Some(Select(qual, name) setPos tree.pos setSymbol first)
+                      case _ =>
+                        macroTrace("macro is not overridden: ")(tree)
+                        notFound()
+                    }
+                  case Apply(fn, args) =>
+                    fallBackToOverridden(fn) match {
+                      case Some(fn1) => Some(Apply(fn1, args) setPos tree.pos)
+                      case _         => None
+                    }
+                  case TypeApply(fn, args) =>
+                    fallBackToOverridden(fn) match {
+                      case Some(fn1) => Some(TypeApply(fn1, args) setPos tree.pos)
+                      case _         => None
+                    }
                   case _ =>
-                    val message = {
-                      try {
-                        // the most reliable way of obtaining currently executing method
-                        // http://stackoverflow.com/questions/442747/getting-the-name-of-the-current-executing-method
-                        val currentMethodName = new Object(){}.getClass().getEnclosingMethod().getName
-                        val relevancyThreshold = realex.getStackTrace().indexWhere(este => este.getMethodName == currentMethodName)
-                        if (relevancyThreshold == -1) None
-                        else {
-                          var relevantElements = realex.getStackTrace().take(relevancyThreshold + 1)
-                          var framesTillReflectiveInvocationOfMacroImpl = relevantElements.reverse.indexWhere(_.isNativeMethod) + 1
-                          relevantElements = relevantElements dropRight framesTillReflectiveInvocationOfMacroImpl
-
-                          realex.setStackTrace(relevantElements)
-                          val message = new java.io.StringWriter()
-                          realex.printStackTrace(new java.io.PrintWriter(message))
-                          Some(EOL + message)
-                        }
-                      } catch {
-                        // if the magic above goes boom, just fall back to uninformative, but better than nothing, getMessage
-                        case ex: Throwable =>
-                          None
-                      }
-                    } getOrElse realex.getMessage
-                    fail(typer, expandee, "exception during macro expansion: " + message)
+                    macroTrace("unexpected tree in fallback: ")(tree)
+                    notFound()
                 }
-            } finally {
-              nodePrinters.infolevel = savedInfolevel
-            }
-          case None =>
-            def notFound() = {
-              typer.context.error(expandee.pos, "macro implementation not found: " + macroDef.name + " " +
-                "(the most common reason for that is that you cannot use macro implementations in the same compilation run that defines them)\n" +
-                "if you do need to define macro implementations along with the rest of your program, consider two-phase compilation with -Xmacro-fallback-classpath " +
-                "in the second phase pointing to the output of the first phase")
-              None
-            }
-            def fallBackToOverridden(tree: Tree): Option[Tree] = {
-              tree match {
-                case Select(qual, name) if (macroDef.isTermMacro) =>
-                  macroDef.allOverriddenSymbols match {
-                    case first :: _ =>
-                      Some(Select(qual, name) setPos tree.pos setSymbol first)
-                    case _ =>
-                      macroTrace("macro is not overridden: ")(tree)
-                      notFound()
-                  }
-                case Apply(fn, args) =>
-                  fallBackToOverridden(fn) match {
-                    case Some(fn1) => Some(Apply(fn1, args) setPos tree.pos)
-                    case _         => None
-                  }
-                case TypeApply(fn, args) =>
-                  fallBackToOverridden(fn) match {
-                    case Some(fn1) => Some(TypeApply(fn1, args) setPos tree.pos)
-                    case _         => None
-                  }
-                case _ =>
-                  macroTrace("unexpected tree in fallback: ")(tree)
-                  notFound()
               }
-            }
-            fallBackToOverridden(expandee) match {
-              case Some(tree1) =>
-                macroTrace("falling back to ")(tree1)
-                currentRun.macroExpansionFailed = true
-                Fallback(tree1)
-              case None =>
-                fail(typer, expandee)
-            }
+              fallBackToOverridden(expandee) match {
+                case Some(tree1) =>
+                  macroTrace("falling back to ")(tree1)
+                  currentRun.macroExpansionFailed = true
+                  Fallback(tree1)
+                case None =>
+                  fail(typer, expandee)
+              }
+          }
+        } finally {
+          stopTimer(macroExpandNanos, start)
         }
       }
     } else {
diff --git a/src/compiler/scala/tools/nsc/util/Statistics.scala b/src/compiler/scala/tools/nsc/util/Statistics.scala
index d1cdd30dd8..61c7695911 100644
--- a/src/compiler/scala/tools/nsc/util/Statistics.scala
+++ b/src/compiler/scala/tools/nsc/util/Statistics.scala
@@ -57,6 +57,9 @@ class Statistics extends scala.reflect.internal.util.Statistics {
   val counter2: SubCounter = new SubCounter(subtypeCount)
   val timer1: Timer = new Timer
   val timer2: Timer = new Timer
+
+  val macroExpandCount = new Counter
+  val macroExpandNanos = new Timer
 }
 
 object Statistics extends Statistics
@@ -125,34 +128,36 @@ abstract class StatisticsInfo {
       inform("ms type-flow-analysis: " + analysis.timer.millis)
 
       if (phase.name == "typer") {
-        inform("time spent typechecking  : "+showRelTyper(typerNanos))
-        inform("time classfilereading    : "+showRelTyper(classReadNanos))
-        inform("time spent in implicits  : "+showRelTyper(implicitNanos))
-        inform("    successful in scope  : "+showRelTyper(inscopeSucceedNanos))
-        inform("        failed in scope  : "+showRelTyper(inscopeFailNanos))
-        inform("     successful of type  : "+showRelTyper(oftypeSucceedNanos))
-        inform("         failed of type  : "+showRelTyper(oftypeFailNanos))
-        inform("       assembling parts  : "+showRelTyper(subtypeETNanos))
-        inform("              matchesPT  : "+showRelTyper(matchesPtNanos))
-        inform("implicit cache hits      : "+showRelative(implicitCacheHits.value + implicitCacheMisses.value)(implicitCacheHits.value))
-        inform("time spent in failed     : "+showRelTyper(failedSilentNanos))
-        inform("       failed apply      : "+showRelTyper(failedApplyNanos))
-        inform("       failed op=        : "+showRelTyper(failedOpEqNanos))
-        inform("time spent ref scanning  : "+showRelTyper(isReferencedNanos))
-        inform("micros by tree node      : "+showCounts(microsByType))
-        inform("#visits by tree node     : "+showCounts(visitsByType))
+        inform("time spent typechecking    : " + showRelTyper(typerNanos))
+        inform("time classfilereading      : " + showRelTyper(classReadNanos))
+        inform("time spent in implicits    : " + showRelTyper(implicitNanos))
+        inform("    successful in scope    : " + showRelTyper(inscopeSucceedNanos))
+        inform("        failed in scope    : " + showRelTyper(inscopeFailNanos))
+        inform("     successful of type    : " + showRelTyper(oftypeSucceedNanos))
+        inform("         failed of type    : " + showRelTyper(oftypeFailNanos))
+        inform("       assembling parts    : " + showRelTyper(subtypeETNanos))
+        inform("              matchesPT    : " + showRelTyper(matchesPtNanos))
+        inform("implicit cache hits        : " + showRelative(implicitCacheHits.value + implicitCacheMisses.value)(implicitCacheHits.value))
+        inform("time spent in failed       : " + showRelTyper(failedSilentNanos))
+        inform("       failed apply        : " + showRelTyper(failedApplyNanos))
+        inform("       failed op=          : " + showRelTyper(failedOpEqNanos))
+        inform("time spent ref scanning    : " + showRelTyper(isReferencedNanos))
+        inform("micros by tree node        : " + showCounts(microsByType))
+        inform("#visits by tree node       : " + showCounts(visitsByType))
         val average = new ClassCounts
         for (c <- microsByType.keysIterator) average(c) = microsByType(c)/visitsByType(c)
-        inform("avg micros by tree node  : "+showCounts(average))
-        inform("time spent in <:<        : "+showRelTyper(subtypeNanos))
-        inform("time spent in findmember : "+showRelTyper(findMemberNanos))
-        inform("time spent in asSeenFrom : "+showRelTyper(asSeenFromNanos))
-        inform("#implicit searches       : " + implicitSearchCount)
+        inform("avg micros by tree node    : " + showCounts(average))
+        inform("time spent in <:<          : " + showRelTyper(subtypeNanos))
+        inform("time spent in findmember   : " + showRelTyper(findMemberNanos))
+        inform("time spent in asSeenFrom   : " + showRelTyper(asSeenFromNanos))
+        inform("#implicit searches         : " + implicitSearchCount)
         inform("#tried, plausible, matching, typed, found implicits: "+triedImplicits+", "+plausiblyCompatibleImplicits+", "+matchingImplicits+", "+typedImplicits+", "+foundImplicits)
-        inform("#implicit improves tests : " + improvesCount)
-        inform("#implicit improves cached: " + improvesCachedCount)
-        inform("#implicit inscope hits   : " + inscopeImplicitHits)
-        inform("#implicit oftype hits    : " + oftypeImplicitHits)
+        inform("#implicit improves tests   : " + improvesCount)
+        inform("#implicit improves cached  : " + improvesCachedCount)
+        inform("#implicit inscope hits     : " + inscopeImplicitHits)
+        inform("#implicit oftype hits      : " + oftypeImplicitHits)
+        inform("#macro expansions          : " + macroExpandCount)
+        inform("#time spent in macroExpand : " + showRelTyper(macroExpandNanos))
       }
 
       if (ctr1 != null)     inform("#ctr1                    : " + ctr1)