From 48c60bee0993548cc18a80cb7a44ccc3cd6155e2 Mon Sep 17 00:00:00 2001 From: Dmitry Bushev Date: Tue, 7 Nov 2023 18:31:46 +0300 Subject: [PATCH 1/4] feat: global profiling --- .../boot/LanguageServerComponent.scala | 24 ---- .../org/enso/runner/LanguageServerApp.scala | 6 +- .../src/main/scala/org/enso/runner/Main.scala | 112 +++++++++++++----- .../org/enso/profiling/FileSampler.scala | 15 +-- .../ExecutorWithUnlimitedPool.scala | 4 +- 5 files changed, 91 insertions(+), 70 deletions(-) diff --git a/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala b/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala index facebd1cd148..99b3705da8ba 100644 --- a/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala +++ b/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala @@ -14,7 +14,6 @@ import org.enso.languageserver.runtime.RuntimeKiller.{ RuntimeShutdownResult, ShutDownRuntime } -import org.enso.profiling.{FileSampler, MethodsSampler, NoopSampler} import org.slf4j.event.Level import scala.concurrent.duration._ import scala.concurrent.{Await, ExecutionContextExecutor, Future} @@ -37,8 +36,6 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) /** @inheritdoc */ override def start(): Future[ComponentStarted.type] = { logger.info("Starting Language Server...") - val sampler = startSampling(config) - logger.debug("Started [{}].", sampler.getClass.getName) val module = new MainModule(config, logLevel) val bindJsonServer = for { @@ -79,7 +76,6 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) _ <- Future { maybeServerCtx = Some( ServerContext( - sampler, module, jsonBinding, secureJsonBinding, @@ -101,20 +97,6 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) } yield ComponentStarted } - /** Start the application sampling. */ - private def startSampling(config: LanguageServerConfig): MethodsSampler = { - val sampler = config.profilingConfig.profilingPath match { - case Some(path) => - new FileSampler(path.toFile) - case None => - NoopSampler() - } - sampler.start() - config.profilingConfig.profilingTime.foreach(sampler.stop(_)) - - sampler - } - /** @inheritdoc */ override def stop(): Future[ComponentStopped.type] = maybeServerCtx match { @@ -123,7 +105,6 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) case Some(serverContext) => for { - _ <- stopSampling(serverContext) _ <- terminateTruffle(serverContext) _ <- terminateAkka(serverContext) _ <- releaseResources(serverContext) @@ -131,9 +112,6 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) } yield ComponentStopped } - private def stopSampling(serverContext: ServerContext): Future[Unit] = - Future(serverContext.sampler.stop()).recover(logError) - private def releaseResources(serverContext: ServerContext): Future[Unit] = for { _ <- Future(serverContext.mainModule.close()).recover(logError) @@ -188,7 +166,6 @@ object LanguageServerComponent { /** A running server context. * - * @param sampler a sampler gathering the application performance statistics * @param mainModule a main module containing all components of the server * @param jsonBinding a http binding for rpc protocol * @param secureJsonBinding an optional https binding for rpc protocol @@ -196,7 +173,6 @@ object LanguageServerComponent { * @param secureBinaryBinding an optional https binding for data protocol */ case class ServerContext( - sampler: MethodsSampler, mainModule: MainModule, jsonBinding: Http.ServerBinding, secureJsonBinding: Option[Http.ServerBinding], diff --git a/engine/runner/src/main/scala/org/enso/runner/LanguageServerApp.scala b/engine/runner/src/main/scala/org/enso/runner/LanguageServerApp.scala index 036defcf560a..a510c2830469 100644 --- a/engine/runner/src/main/scala/org/enso/runner/LanguageServerApp.scala +++ b/engine/runner/src/main/scala/org/enso/runner/LanguageServerApp.scala @@ -23,19 +23,19 @@ object LanguageServerApp { * * @param config the application config * @param logLevel the logging level - * @param deamonize should the language server process be daemonized + * @param daemonize should the language server process be daemonized */ def run( config: LanguageServerConfig, logLevel: Level, - deamonize: Boolean + daemonize: Boolean ): Unit = { val server = new LanguageServerComponent(config, logLevel) Runtime.getRuntime.addShutdownHook(new Thread(() => { stop(server, "shutdown hook")(config.computeExecutionContext) })) Await.result(server.start(), 1.minute) - if (deamonize) { + if (daemonize) { val lock = new AnyRef lock.synchronized { lock.wait() diff --git a/engine/runner/src/main/scala/org/enso/runner/Main.scala b/engine/runner/src/main/scala/org/enso/runner/Main.scala index 3fa8d820c398..55f2ce85a683 100644 --- a/engine/runner/src/main/scala/org/enso/runner/Main.scala +++ b/engine/runner/src/main/scala/org/enso/runner/Main.scala @@ -1,6 +1,6 @@ package org.enso.runner -import akka.http.scaladsl.model.{IllegalUriException} +import akka.http.scaladsl.model.IllegalUriException import buildinfo.Info import cats.implicits._ import com.typesafe.scalalogging.Logger @@ -17,6 +17,7 @@ import org.enso.libraryupload.LibraryUploader.UploadFailedError import org.slf4j.event.Level import org.enso.pkg.{Contact, PackageManager, Template} import org.enso.polyglot.{HostEnsoUtils, LanguageInfo, Module, PolyglotContext} +import org.enso.profiling.{FileSampler, NoopSampler} import org.enso.version.VersionDescription import org.graalvm.polyglot.PolyglotException @@ -24,9 +25,11 @@ import java.io.File import java.net.URI import java.nio.file.{Path, Paths} import java.util.{HashMap, UUID} + import scala.Console.err import scala.Console.out import scala.collection.compat.immutable.ArraySeq +import scala.concurrent.{ExecutionContext, ExecutionContextExecutor} import scala.concurrent.duration._ import scala.jdk.CollectionConverters._ import scala.util.control.NonFatal @@ -48,9 +51,9 @@ object Main { private val REPL_OPTION = "repl" private val DOCS_OPTION = "docs" private val PREINSTALL_OPTION = "preinstall-dependencies" + private val PROFILING_PATH = "profiling-path" + private val PROFILING_TIME = "profiling-time" private val LANGUAGE_SERVER_OPTION = "server" - private val LANGUAGE_SERVER_PROFILING_PATH = "server-profiling-path" - private val LANGUAGE_SERVER_PROFILING_TIME = "server-profiling-time" private val LANGUAGE_SERVER_PROFILING_EVENTS_LOG_PATH = "server-profiling-events-log-path" private val DAEMONIZE_OPTION = "daemon" @@ -188,14 +191,14 @@ object Main { .hasArg(true) .numberOfArgs(1) .argName("file") - .longOpt(LANGUAGE_SERVER_PROFILING_PATH) + .longOpt(PROFILING_PATH) .desc("The path to the Language Server profiling file.") .build() val lsProfilingTimeOption = CliOption.builder .hasArg(true) .numberOfArgs(1) .argName("seconds") - .longOpt(LANGUAGE_SERVER_PROFILING_TIME) + .longOpt(PROFILING_TIME) .desc("The duration in seconds limiting the profiling time.") .build() val lsProfilingEventsLogPathOption = CliOption.builder @@ -872,7 +875,7 @@ object Main { } ) val res = main.execute(parsedArgs: _*) - if (!res.isNull()) { + if (!res.isNull) { out.println(res); } case None => @@ -992,13 +995,32 @@ object Main { secureDataPort <- Either .catchNonFatal(secureDataPortStr.map(_.toInt)) .leftMap(_ => "Port must be integer") - profilingPathStr = - Option(line.getOptionValue(LANGUAGE_SERVER_PROFILING_PATH)) + profilingConfig <- parseProfilingConfig(line) + graalVMUpdater = Option(line.hasOption(SKIP_GRAALVM_UPDATER)) + .getOrElse(false) + } yield boot.LanguageServerConfig( + interface, + rpcPort, + secureRpcPort, + dataPort, + secureDataPort, + rootId, + rootPath, + profilingConfig, + StartupConfig(graalVMUpdater) + ) + + private def parseProfilingConfig( + line: CommandLine + ): Either[String, ProfilingConfig] = { + val profilingPathStr = + Option(line.getOptionValue(PROFILING_PATH)) + for { profilingPath <- Either .catchNonFatal(profilingPathStr.map(Paths.get(_))) .leftMap(_ => "Profiling path is invalid") profilingTimeStr = Option( - line.getOptionValue(LANGUAGE_SERVER_PROFILING_TIME) + line.getOptionValue(PROFILING_TIME) ) profilingTime <- Either .catchNonFatal(profilingTimeStr.map(_.toInt.seconds)) @@ -1008,25 +1030,18 @@ object Main { profilingEventsLogPath <- Either .catchNonFatal(profilingEventsLogPathStr.map(Paths.get(_))) .leftMap(_ => "Profiling events log path is invalid") - graalVMUpdater = Option(line.hasOption(SKIP_GRAALVM_UPDATER)) - .getOrElse(false) - } yield boot.LanguageServerConfig( - interface, - rpcPort, - secureRpcPort, - dataPort, - secureDataPort, - rootId, - rootPath, - ProfilingConfig(profilingEventsLogPath, profilingPath, profilingTime), - StartupConfig(graalVMUpdater) + } yield ProfilingConfig( + profilingEventsLogPath, + profilingPath, + profilingTime ) + } /** Prints the version of the Enso executable. * * @param useJson whether the output should be JSON or human-readable. */ - def displayVersion(useJson: Boolean): Unit = { + private def displayVersion(useJson: Boolean): Unit = { val versionDescription = VersionDescription.make( "Enso Compiler and Runtime", includeRuntimeJVMInfo = true, @@ -1037,7 +1052,7 @@ object Main { /** Parses the log level option. */ - def parseLogLevel(levelOption: String): Level = { + private def parseLogLevel(levelOption: String): Level = { val name = levelOption.toLowerCase Level.values().find(_.name().toLowerCase() == name).getOrElse { val possible = @@ -1049,7 +1064,7 @@ object Main { /** Parses an URI that specifies the logging service connection. */ - def parseUri(string: String): URI = + private def parseUri(string: String): URI = try { URI.create(string) } catch { @@ -1060,7 +1075,7 @@ object Main { /** Default log level to use if the LOG_LEVEL option is not provided. */ - val defaultLogLevel: Level = Level.WARN + private val defaultLogLevel: Level = Level.WARN /** Main entry point for the CLI program. * @@ -1069,10 +1084,27 @@ object Main { def main(args: Array[String]): Unit = { val options = buildOptions val parser = new DefaultParser - val line: CommandLine = Try(parser.parse(options, args)).getOrElse { - printHelp(options) - exitFail() - } + val line: CommandLine = + Try(parser.parse(options, args)) + .getOrElse { + printHelp(options) + exitFail() + } + parseProfilingConfig(line).fold( + error => { + System.err.println(error) + exitFail() + }, + withProfiling(_)(runMain(options, line)) + ) + } + + /** Main entry point for the CLI program. + * + * @param options the command line options + * @param line the provided command line arguments + */ + private def runMain(options: Options, line: CommandLine): Unit = { if (line.hasOption(HELP_OPTION)) { printHelp(options) exitSuccess() @@ -1182,7 +1214,7 @@ object Main { Option(line.getOptionValue(EXECUTION_ENVIRONMENT_OPTION)) .orElse(Some("live")), Option(line.getOptionValue(WARNINGS_LIMIT)) - .map(Integer.parseInt(_)) + .map(Integer.parseInt) .getOrElse(100) ) } @@ -1245,4 +1277,24 @@ object Main { .resolve(historyFileName) TerminalIO(historyFilePath) } + + private def withProfiling[A]( + profilingConfig: ProfilingConfig, + executor: ExecutionContextExecutor = ExecutionContext.global + )(main: => A): A = { + val sampler = profilingConfig.profilingPath match { + case Some(path) => + new FileSampler(path.toFile) + case None => + NoopSampler() + } + sampler.start() + profilingConfig.profilingTime.foreach(sampler.stop(_)(executor)) + + try { + main + } finally { + sampler.stop() + } + } } diff --git a/lib/scala/profiling-utils/src/main/scala/org/enso/profiling/FileSampler.scala b/lib/scala/profiling-utils/src/main/scala/org/enso/profiling/FileSampler.scala index 0aa2a9dc1d88..5b9b9517c6df 100644 --- a/lib/scala/profiling-utils/src/main/scala/org/enso/profiling/FileSampler.scala +++ b/lib/scala/profiling-utils/src/main/scala/org/enso/profiling/FileSampler.scala @@ -3,7 +3,7 @@ package org.enso.profiling import org.netbeans.modules.sampler.Sampler import java.io.{DataOutputStream, File, FileOutputStream} -import java.util.concurrent.{CompletableFuture, Executor, Executors} +import java.util.concurrent.{CompletableFuture, Executor} import scala.concurrent.duration.FiniteDuration import scala.util.Using @@ -41,15 +41,8 @@ final class FileSampler(output: File) extends MethodsSampler { /** @inheritdoc */ def stop(delay: FiniteDuration)(implicit ec: Executor): Unit = this.synchronized { - val executor = Executors.newSingleThreadScheduledExecutor() - - CompletableFuture - .runAsync( - { () => - executor.schedule[Unit](() => this.stop(), delay.length, delay.unit) - }: Runnable, - ec - ) - .whenComplete((_, _) => executor.shutdown()) + val delayedExecutor = + CompletableFuture.delayedExecutor(delay.length, delay.unit, ec) + CompletableFuture.supplyAsync(() => this.stop(), delayedExecutor) } } diff --git a/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala b/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala index fa7f5a4f89a3..5996cf12d8d1 100644 --- a/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala +++ b/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala @@ -103,11 +103,11 @@ object ExecutorWithUnlimitedPool extends LanguageServerExecutor { ) val profilingPathArguments = descriptor.profilingPath.toSeq - .flatMap(path => Seq("--server-profiling-path", path.toString)) + .flatMap(path => Seq("--profiling-path", path.toString)) val profilingTimeArguments = descriptor.profilingTime.toSeq .flatMap(time => - Seq("--server-profiling-time", time.toSeconds.toString) + Seq("--profiling-time", time.toSeconds.toString) ) val profilingEventsLogPathArguments = descriptor.profilingEventsLogPath.toSeq From 6064295d9a28eb05603cccbe0240bc349a09c9af Mon Sep 17 00:00:00 2001 From: Dmitry Bushev Date: Wed, 8 Nov 2023 17:03:26 +0300 Subject: [PATCH 2/4] fix: language server profiling --- .../boot/LanguageServerComponent.scala | 24 +++++++++++++ .../src/main/scala/org/enso/runner/Main.scala | 35 ++++++++++++------- 2 files changed, 46 insertions(+), 13 deletions(-) diff --git a/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala b/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala index 99b3705da8ba..facebd1cd148 100644 --- a/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala +++ b/engine/language-server/src/main/scala/org/enso/languageserver/boot/LanguageServerComponent.scala @@ -14,6 +14,7 @@ import org.enso.languageserver.runtime.RuntimeKiller.{ RuntimeShutdownResult, ShutDownRuntime } +import org.enso.profiling.{FileSampler, MethodsSampler, NoopSampler} import org.slf4j.event.Level import scala.concurrent.duration._ import scala.concurrent.{Await, ExecutionContextExecutor, Future} @@ -36,6 +37,8 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) /** @inheritdoc */ override def start(): Future[ComponentStarted.type] = { logger.info("Starting Language Server...") + val sampler = startSampling(config) + logger.debug("Started [{}].", sampler.getClass.getName) val module = new MainModule(config, logLevel) val bindJsonServer = for { @@ -76,6 +79,7 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) _ <- Future { maybeServerCtx = Some( ServerContext( + sampler, module, jsonBinding, secureJsonBinding, @@ -97,6 +101,20 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) } yield ComponentStarted } + /** Start the application sampling. */ + private def startSampling(config: LanguageServerConfig): MethodsSampler = { + val sampler = config.profilingConfig.profilingPath match { + case Some(path) => + new FileSampler(path.toFile) + case None => + NoopSampler() + } + sampler.start() + config.profilingConfig.profilingTime.foreach(sampler.stop(_)) + + sampler + } + /** @inheritdoc */ override def stop(): Future[ComponentStopped.type] = maybeServerCtx match { @@ -105,6 +123,7 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) case Some(serverContext) => for { + _ <- stopSampling(serverContext) _ <- terminateTruffle(serverContext) _ <- terminateAkka(serverContext) _ <- releaseResources(serverContext) @@ -112,6 +131,9 @@ class LanguageServerComponent(config: LanguageServerConfig, logLevel: Level) } yield ComponentStopped } + private def stopSampling(serverContext: ServerContext): Future[Unit] = + Future(serverContext.sampler.stop()).recover(logError) + private def releaseResources(serverContext: ServerContext): Future[Unit] = for { _ <- Future(serverContext.mainModule.close()).recover(logError) @@ -166,6 +188,7 @@ object LanguageServerComponent { /** A running server context. * + * @param sampler a sampler gathering the application performance statistics * @param mainModule a main module containing all components of the server * @param jsonBinding a http binding for rpc protocol * @param secureJsonBinding an optional https binding for rpc protocol @@ -173,6 +196,7 @@ object LanguageServerComponent { * @param secureBinaryBinding an optional https binding for data protocol */ case class ServerContext( + sampler: MethodsSampler, mainModule: MainModule, jsonBinding: Http.ServerBinding, secureJsonBinding: Option[Http.ServerBinding], diff --git a/engine/runner/src/main/scala/org/enso/runner/Main.scala b/engine/runner/src/main/scala/org/enso/runner/Main.scala index 55f2ce85a683..269078fd0ef3 100644 --- a/engine/runner/src/main/scala/org/enso/runner/Main.scala +++ b/engine/runner/src/main/scala/org/enso/runner/Main.scala @@ -1090,12 +1090,25 @@ object Main { printHelp(options) exitFail() } + + val logLevel = Option(line.getOptionValue(LOG_LEVEL)) + .map(parseLogLevel) + .getOrElse(defaultLogLevel) + val connectionUri = + Option(line.getOptionValue(LOGGER_CONNECT)).map(parseUri) + val logMasking = !line.hasOption(NO_LOG_MASKING) + RunnerLogging.setup(connectionUri, logLevel, logMasking) + + if (line.hasOption(LANGUAGE_SERVER_OPTION)) { + runLanguageServer(line, logLevel) + } + parseProfilingConfig(line).fold( error => { System.err.println(error) exitFail() }, - withProfiling(_)(runMain(options, line)) + withProfiling(_)(runMain(options, line, logLevel, logMasking)) ) } @@ -1103,8 +1116,15 @@ object Main { * * @param options the command line options * @param line the provided command line arguments + * @param logLevel the provided log level + * @param logMasking the flag indicating if the log masking is enabled */ - private def runMain(options: Options, line: CommandLine): Unit = { + private def runMain( + options: Options, + line: CommandLine, + logLevel: Level, + logMasking: Boolean + ): Unit = { if (line.hasOption(HELP_OPTION)) { printHelp(options) exitSuccess() @@ -1114,14 +1134,6 @@ object Main { exitSuccess() } - val logLevel = Option(line.getOptionValue(LOG_LEVEL)) - .map(parseLogLevel) - .getOrElse(defaultLogLevel) - val connectionUri = - Option(line.getOptionValue(LOGGER_CONNECT)).map(parseUri) - val logMasking = !line.hasOption(NO_LOG_MASKING) - RunnerLogging.setup(connectionUri, logLevel, logMasking) - if (line.hasOption(NEW_OPTION)) { createNew( path = line.getOptionValue(NEW_OPTION), @@ -1240,9 +1252,6 @@ object Main { logLevel ) } - if (line.hasOption(LANGUAGE_SERVER_OPTION)) { - runLanguageServer(line, logLevel) - } if (line.getOptions.isEmpty) { printHelp(options) exitFail() From 51dee7c5e2ae632cde5caffd4c471e2f821c077e Mon Sep 17 00:00:00 2001 From: Dmitry Bushev Date: Wed, 8 Nov 2023 19:19:38 +0300 Subject: [PATCH 3/4] misc: update docs --- docs/profiler/engine-startup.md | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/docs/profiler/engine-startup.md b/docs/profiler/engine-startup.md index 96ad272eeac8..9128dd9adbce 100644 --- a/docs/profiler/engine-startup.md +++ b/docs/profiler/engine-startup.md @@ -9,6 +9,8 @@ Enso engine. ## Collecting the data +### Via the Project Manager + Start `project-manager` with following options to record first 20s of the Enso engine startup sequence: @@ -26,6 +28,21 @@ $ graalvm/bin/jvisualvm --openfile start.npss Use VisualVM to analyze to recorded data. +### Via the runner + +Runner executable also supports the profiling with the `--profiling-path` +option. For example, you can run the Enso project with the profiling enabled: + +``` +$ enso --profiling-path=/tmp/run.npss --run ~/enso/project/New_Project_1 +``` + +And then open it in the VisualVM: + +``` +$ visualvm --openfile /tmp/run.npss +``` + ### Interactively Analyze VisualVM offers two timelines. A "stackdepth" one and also _"UI Actions"_ line. From 73bb9efb2dfce8bf05a59f5c0a0b14872c4574fb Mon Sep 17 00:00:00 2001 From: Dmitry Bushev Date: Wed, 8 Nov 2023 19:20:36 +0300 Subject: [PATCH 4/4] misc: scalafmt --- .../languageserver/ExecutorWithUnlimitedPool.scala | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala b/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala index 5996cf12d8d1..7afb5b5255cb 100644 --- a/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala +++ b/lib/scala/project-manager/src/main/scala/org/enso/projectmanager/infrastructure/languageserver/ExecutorWithUnlimitedPool.scala @@ -106,9 +106,7 @@ object ExecutorWithUnlimitedPool extends LanguageServerExecutor { .flatMap(path => Seq("--profiling-path", path.toString)) val profilingTimeArguments = descriptor.profilingTime.toSeq - .flatMap(time => - Seq("--profiling-time", time.toSeconds.toString) - ) + .flatMap(time => Seq("--profiling-time", time.toSeconds.toString)) val profilingEventsLogPathArguments = descriptor.profilingEventsLogPath.toSeq .flatMap(path =>