From 6c50a85f93a4d3c61e9f4d5c5fec09614e151b82 Mon Sep 17 00:00:00 2001 From: Ethan Atkins Date: Wed, 29 Jul 2020 14:55:19 -0700 Subject: [PATCH] Use a macro to create StringTypeTag instances Using the scala reflect library always introduces significant classloading overhead. We can eliminate the classloading overhead by generating StringTypeTags at compile time instead. This sped up average project loading time by a few hundred milliseconds on my computer. The ManagedLoggedReporter in zinc is still using the type tag based apis but after the next sbt release, we can upgrade the zinc apis. We also could consider breaking binary compatibility. --- build.sbt | 4 +- .../util/appmacro/StringTypeTag.scala | 27 ++++++++++ .../sbt/internal/util/ManagedLogger.scala | 50 ++++++++++++++----- .../sbt/internal/util/StringTypeTag.scala | 6 +++ .../src/main/scala/sbt/util/LogExchange.scala | 13 +++-- .../src/test/scala/LogExchangeSpec.scala | 14 ++++-- .../src/test/scala/ManagedLoggerSpec.scala | 2 +- .../sbt/internal/XMainConfiguration.scala | 2 - .../internal/server/BuildServerReporter.scala | 14 ++++-- 9 files changed, 102 insertions(+), 30 deletions(-) create mode 100644 core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala diff --git a/build.sbt b/build.sbt index 0e84f284a..11c3cf8d6 100644 --- a/build.sbt +++ b/build.sbt @@ -359,7 +359,7 @@ lazy val utilPosition = (project in file("internal") / "util-position") lazy val utilLogging = (project in file("internal") / "util-logging") .enablePlugins(ContrabandPlugin, JsonCodecPlugin) - .dependsOn(utilInterface, collectionProj) + .dependsOn(utilInterface, collectionProj, coreMacrosProj) .settings( utilCommonSettings, name := "Util Logging", @@ -781,7 +781,7 @@ lazy val commandProj = (project in file("main-command")) lazy val coreMacrosProj = (project in file("core-macros")) .dependsOn(collectionProj) .settings( - baseSettings, + baseSettings :+ (crossScalaVersions := (scala212 :: scala213 :: Nil)), name := "Core Macros", libraryDependencies += "org.scala-lang" % "scala-compiler" % scalaVersion.value, mimaSettings, diff --git a/core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala b/core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala new file mode 100644 index 000000000..faeda9245 --- /dev/null +++ b/core-macros/src/main/scala/sbt/internal/util/appmacro/StringTypeTag.scala @@ -0,0 +1,27 @@ +/* + * sbt + * Copyright 2011 - 2018, Lightbend, Inc. + * Copyright 2008 - 2010, Mark Harrah + * Licensed under Apache License 2.0 (see LICENSE) + */ + +package sbt.internal.util.appmacro + +import scala.reflect.macros.blackbox + +object StringTypeTag { + def impl[A: c.WeakTypeTag](c: blackbox.Context): c.Tree = { + import c.universe._ + val tpe = weakTypeOf[A] + def typeToString(tpe: Type): String = tpe match { + case TypeRef(_, sym, args) if args.nonEmpty => + val typeCon = tpe.typeSymbol.fullName + val typeArgs = args map typeToString + s"""$typeCon[${typeArgs.mkString(",")}]""" + case _ => tpe.toString + } + + val key = Literal(Constant(typeToString(tpe))) + q"new sbt.internal.util.StringTypeTag[$tpe]($key)" + } +} diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala b/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala index 9bb00524f..67aefeb52 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/ManagedLogger.scala @@ -7,12 +7,12 @@ package sbt.internal.util -import sbt.util._ import org.apache.logging.log4j.{ Logger => XLogger } import org.apache.logging.log4j.message.ObjectMessage -import sjsonnew.JsonFormat -import scala.reflect.runtime.universe.TypeTag import sbt.internal.util.codec.JsonProtocol._ +import sbt.util._ +import scala.reflect.runtime.universe.TypeTag +import sjsonnew.JsonFormat /** * Delegates log events to the associated LogExchange. @@ -35,29 +35,53 @@ class ManagedLogger( ) } - private lazy val SuccessEventTag = scala.reflect.runtime.universe.typeTag[SuccessEvent] // send special event for success since it's not a real log level override def success(message: => String): Unit = { if (terminal.fold(true)(_.isSuccessEnabled)) { infoEvent[SuccessEvent](SuccessEvent(message))( implicitly[JsonFormat[SuccessEvent]], - SuccessEventTag + StringTypeTag.fast[SuccessEvent], ) } } - def registerStringCodec[A: ShowLines: TypeTag]: Unit = { + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + def registerStringCodec[A]( + s: ShowLines[A], + tt: scala.reflect.runtime.universe.TypeTag[A] + ): Unit = { + LogExchange.registerStringCodec[A](s, tt) + } + def registerStringCodec[A: ShowLines: StringTypeTag]: Unit = { LogExchange.registerStringCodec[A] } - final def debugEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Debug, event) - final def infoEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Info, event) - final def warnEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Warn, event) - final def errorEvent[A: JsonFormat: TypeTag](event: => A): Unit = logEvent(Level.Error, event) - def logEvent[A: JsonFormat: TypeTag](level: Level.Value, event: => A): Unit = { + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def debugEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + debugEvent(event)(f, StringTypeTag.apply(t)) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def infoEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + infoEvent(event)(f, StringTypeTag.apply(t)) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def warnEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + warnEvent(event)(f, StringTypeTag.apply(t)) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + final def errorEvent[A](event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + errorEvent(event)(f, StringTypeTag.apply(t)) + + final def debugEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = + logEvent(Level.Debug, event) + final def infoEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = logEvent(Level.Info, event) + final def warnEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = logEvent(Level.Warn, event) + final def errorEvent[A: JsonFormat: StringTypeTag](event: => A): Unit = + logEvent(Level.Error, event) + @deprecated("Use macro-powered StringTypeTag.fast instead", "1.4.0") + def logEvent[A](level: Level.Value, event: => A, f: JsonFormat[A], t: TypeTag[A]): Unit = + logEvent(level, event)(f, StringTypeTag.apply(t)) + def logEvent[A: JsonFormat](level: Level.Value, event: => A)( + implicit tag: StringTypeTag[A] + ): Unit = { val v: A = event - val tag = StringTypeTag[A] - LogExchange.getOrElseUpdateJsonCodec(tag.key, implicitly[JsonFormat[A]]) // println("logEvent " + tag.key) val entry: ObjectEvent[A] = ObjectEvent(level, v, channelName, execId, tag.key) xlogger.log( diff --git a/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala b/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala index 344d4c002..e2b54232a 100644 --- a/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala +++ b/internal/util-logging/src/main/scala/sbt/internal/util/StringTypeTag.scala @@ -7,6 +7,7 @@ package sbt.internal.util +import scala.language.experimental.macros import scala.reflect.runtime.universe._ /** This is used to carry type information in JSON. */ @@ -15,6 +16,10 @@ final case class StringTypeTag[A](key: String) { } object StringTypeTag { + + /** Generates a StringTypeTag for any type at compile time. */ + implicit def fast[A]: StringTypeTag[A] = macro appmacro.StringTypeTag.impl[A] + @deprecated("Prefer macro generated StringTypeTag", "1.4.0") def apply[A: TypeTag]: StringTypeTag[A] = synchronized { def doApply: StringTypeTag[A] = { @@ -38,6 +43,7 @@ object StringTypeTag { retry(3) } + @deprecated("Prefer macro generated StringTypeTag", "1.4.0") def typeToString(tpe: Type): String = tpe match { case TypeRef(_, sym, args) => diff --git a/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala b/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala index a1073b36f..326d23d3c 100644 --- a/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala +++ b/internal/util-logging/src/main/scala/sbt/util/LogExchange.scala @@ -15,7 +15,6 @@ import org.apache.logging.log4j.core.config.{ AppenderRef, LoggerConfig } import org.apache.logging.log4j.core.layout.PatternLayout import scala.collection.JavaConverters._ import scala.collection.concurrent -import scala.reflect.runtime.universe.TypeTag import sjsonnew.JsonFormat // http://logging.apache.org/log4j/2.x/manual/customconfig.html @@ -114,9 +113,15 @@ sealed abstract class LogExchange { def getOrElseUpdateStringCodec[A](tag: String, v: ShowLines[A]): ShowLines[A] = stringCodecs.getOrElseUpdate(tag, v).asInstanceOf[ShowLines[A]] - def registerStringCodec[A: ShowLines: TypeTag]: Unit = { - val tag = StringTypeTag[A] - registerStringCodecByStringTypeTag(tag) + @deprecated("Prefer macro based registerStringCodec", "1.4.0") + def registerStringCodec[A]( + st: ShowLines[A], + tt: scala.reflect.runtime.universe.TypeTag[A] + ): Unit = { + registerStringCodecByStringTypeTag(StringTypeTag.apply[A](tt))(st) + } + private[sbt] def registerStringCodec[A: ShowLines: StringTypeTag]: Unit = { + registerStringCodecByStringTypeTag(implicitly[StringTypeTag[A]]) } private[sbt] def registerStringCodecByStringTypeTag[A: ShowLines](tag: StringTypeTag[A]): Unit = { diff --git a/internal/util-logging/src/test/scala/LogExchangeSpec.scala b/internal/util-logging/src/test/scala/LogExchangeSpec.scala index afdf7621b..3a26b44ab 100644 --- a/internal/util-logging/src/test/scala/LogExchangeSpec.scala +++ b/internal/util-logging/src/test/scala/LogExchangeSpec.scala @@ -14,9 +14,17 @@ import org.scalatest._ class LogExchangeSpec extends FlatSpec with Matchers { import LogExchange._ - checkTypeTag("stringTypeTagThrowable", stringTypeTagThrowable, StringTypeTag[Throwable]) - checkTypeTag("stringTypeTagTraceEvent", stringTypeTagTraceEvent, StringTypeTag[TraceEvent]) - checkTypeTag("stringTypeTagSuccessEvent", stringTypeTagSuccessEvent, StringTypeTag[SuccessEvent]) + checkTypeTag("stringTypeTagThrowable", stringTypeTagThrowable, StringTypeTag.fast[Throwable]) + checkTypeTag( + "stringTypeTagTraceEvent", + stringTypeTagTraceEvent, + StringTypeTag.fast[TraceEvent] + ) + checkTypeTag( + "stringTypeTagSuccessEvent", + stringTypeTagSuccessEvent, + StringTypeTag.fast[SuccessEvent] + ) private def checkTypeTag[A](name: String, inc: StringTypeTag[A], exp: StringTypeTag[A]): Unit = s"LogExchange.$name" should s"match real StringTypeTag[$exp]" in { diff --git a/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala b/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala index dcab747fa..b5c99ca38 100644 --- a/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala +++ b/internal/util-logging/src/test/scala/ManagedLoggerSpec.scala @@ -84,7 +84,7 @@ class ManagedLoggerSpec extends FlatSpec with Matchers { } { pool.submit(new Runnable { def run(): Unit = { - val stringTypeTag = StringTypeTag[List[Int]] + val stringTypeTag = StringTypeTag.fast[List[Int]] val log = LogExchange.logger(s"foo$i") LogExchange.bindLoggerAppenders(s"foo$i", List(LogExchange.asyncStdout -> Level.Info)) if (i % 100 == 0) { diff --git a/main/src/main/scala/sbt/internal/XMainConfiguration.scala b/main/src/main/scala/sbt/internal/XMainConfiguration.scala index 1e72eb139..e4ebdf6bc 100644 --- a/main/src/main/scala/sbt/internal/XMainConfiguration.scala +++ b/main/src/main/scala/sbt/internal/XMainConfiguration.scala @@ -14,7 +14,6 @@ import java.util.concurrent.{ ExecutorService, Executors } import ClassLoaderClose.close import sbt.plugins.{ CorePlugin, IvyPlugin, JvmPlugin } -import sbt.util.LogExchange import xsbti._ private[internal] object ClassLoaderWarmup { @@ -29,7 +28,6 @@ private[internal] object ClassLoaderWarmup { () } - submit(LogExchange.context) submit(Class.forName("sbt.internal.parser.SbtParserInit").getConstructor().newInstance()) submit(CorePlugin.projectSettings) submit(IvyPlugin.projectSettings) diff --git a/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala b/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala index 5c7a7152f..10330d687 100644 --- a/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala +++ b/main/src/main/scala/sbt/internal/server/BuildServerReporter.scala @@ -11,7 +11,7 @@ import java.io.File import sbt.StandardMain import sbt.internal.bsp._ -import sbt.internal.inc.ManagedLoggedReporter +import sbt.internal.inc.LoggedReporter import sbt.internal.util.ManagedLogger import xsbti.{ Problem, Severity, Position => XPosition } @@ -30,7 +30,11 @@ class BuildServerReporter( logger: ManagedLogger, sourcePositionMapper: XPosition => XPosition = identity[XPosition], sources: Seq[File] -) extends ManagedLoggedReporter(maximumErrors, logger, sourcePositionMapper) { +) extends LoggedReporter(maximumErrors, logger, sourcePositionMapper) { + import LoggedReporter.problemFormats._ + import LoggedReporter.problemStringFormats._ + logger.registerStringCodec[Problem] + import sbt.internal.bsp.codec.JsonProtocol._ import sbt.internal.inc.JavaInterfaceUtil._ @@ -55,21 +59,21 @@ class BuildServerReporter( publishDiagnostic(problem) // console channel can keep using the xsbi.Problem - super.logError(problem) + logger.errorEvent(problem) } override def logWarning(problem: Problem): Unit = { publishDiagnostic(problem) // console channel can keep using the xsbi.Problem - super.logWarning(problem) + logger.warnEvent(problem) } override def logInfo(problem: Problem): Unit = { publishDiagnostic(problem) // console channel can keep using the xsbi.Problem - super.logInfo(problem) + logger.infoEvent(problem) } private def publishDiagnostic(problem: Problem): Unit = {