Extracting performance measuring utils into mini-framework, implement measurements of the rpc time, adding more measurements to performance logging, minor refactorings

compiler/rmi/kotlinr/src/org/jetbrains/kotlin/rmi/kotlinr/KotlinCompilerClient.kt

@@ -123,15 +123,13 @@ public object KotlinCompilerClient {
     }
 
 
-    // TODO: remove jvmStatic after all use sites will switch to kotlin
+    public fun incrementalCompile(compiler: CompileService, args: Array<out String>, services: CompilationServices, compilerOut: OutputStream, daemonOut: OutputStream, profiler: Profiler = DummyProfiler()): Int {
-    @JvmStatic
-    public fun incrementalCompile(compiler: CompileService, args: Array<out String>, services: CompilationServices, compilerOut: OutputStream, daemonOut: OutputStream): Int {
 
         val compilerOutStreamServer = RemoteOutputStreamServer(compilerOut)
         val daemonOutStreamServer = RemoteOutputStreamServer(daemonOut)
         val cacheServers = hashMapOf<TargetId, RemoteIncrementalCacheServer>()
         try {
-            return compiler.remoteIncrementalCompile(args, makeRemoteServices(services), compilerOutStreamServer, CompileService.OutputFormat.XML, daemonOutStreamServer)
+            return profiler.withMeasure(this) { compiler.remoteIncrementalCompile(args, makeRemoteServices(services), compilerOutStreamServer, CompileService.OutputFormat.XML, daemonOutStreamServer) }
         }
         finally {
             cacheServers.forEach { it.getValue().disconnect() }

compiler/rmi/rmi-interface/src/org/jetbrains/kotlin/rmi/DaemonParams.kt

@@ -205,14 +205,18 @@ public data class DaemonOptions(
         public var runFilesPath: String = COMPILE_DAEMON_DEFAULT_RUN_DIR_PATH,
         public var autoshutdownMemoryThreshold: Long = COMPILE_DAEMON_MEMORY_THRESHOLD_INFINITE,
         public var autoshutdownIdleSeconds: Int = COMPILE_DAEMON_DEFAULT_IDLE_TIMEOUT_S,
-        public var clientAliveFlagPath: String? = null
+        public var clientAliveFlagPath: String? = null,
+        public var verbose: Boolean = false,
+        public var reportPerf: Boolean = false
 ) : OptionsGroup {
 
     override val mappers: List<PropMapper<*, *, *>>
         get() = listOf(PropMapper(this, DaemonOptions::runFilesPath, fromString = { it.trimQuotes() }),
                        PropMapper(this, DaemonOptions::autoshutdownMemoryThreshold, fromString = { it.toLong() }, skipIf = { it == 0L }, mergeDelimiter = "="),
                        PropMapper(this, DaemonOptions::autoshutdownIdleSeconds, fromString = { it.toInt() }, skipIf = { it == 0 }, mergeDelimiter = "="),
-                       NullablePropMapper(this, DaemonOptions::clientAliveFlagPath, fromString = { it }, toString = { "${it?.trimQuotes()}" }, mergeDelimiter = "="))
+                       NullablePropMapper(this, DaemonOptions::clientAliveFlagPath, fromString = { it }, toString = { "${it?.trimQuotes()}" }, mergeDelimiter = "="),
+                       BoolPropMapper(this, DaemonOptions::verbose),
+                       BoolPropMapper(this, DaemonOptions::reportPerf))
 }
 
 
@@ -298,8 +302,6 @@ public fun configureDaemonJVMOptions(opts: DaemonJVMOptions, inheritMemoryLimits
                   .filterExtractProps(opts.mappers, "-", opts.restMapper))
     }
 
-    System.getProperty(COMPILE_DAEMON_REPORT_PERF_PROPERTY)?.let { opts.jvmParams.add("D" + COMPILE_DAEMON_REPORT_PERF_PROPERTY) }
-    System.getProperty(COMPILE_DAEMON_VERBOSE_REPORT_PROPERTY)?.let { opts.jvmParams.add("D" + COMPILE_DAEMON_VERBOSE_REPORT_PROPERTY) }
     System.getProperty(COMPILE_DAEMON_LOG_PATH_PROPERTY)?.let { opts.jvmParams.add("D$COMPILE_DAEMON_LOG_PATH_PROPERTY=\"$it\"" ) }
     opts.jvmParams.addAll(additionalParams)
     return opts
@@ -324,6 +326,8 @@ public fun configureDaemonOptions(opts: DaemonOptions): DaemonOptions {
             opts.clientAliveFlagPath = trimmed
         }
     }
+    System.getProperty(COMPILE_DAEMON_VERBOSE_REPORT_PROPERTY)?.let { opts.verbose = true }
+    System.getProperty(COMPILE_DAEMON_REPORT_PERF_PROPERTY)?.let { opts.reportPerf = true }
     return opts
 }
 

compiler/rmi/rmi-interface/src/org/jetbrains/kotlin/rmi/PerfUtils.kt

@@ -0,0 +1,174 @@
+/*
+ * Copyright 2010-2015 JetBrains s.r.o.
+ *
+ * Licensed under the Apache License, Version 2.0 (the "License");
+ * you may not use this file except in compliance with the License.
+ * You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.jetbrains.kotlin.rmi
+
+import java.lang.management.ManagementFactory
+import java.lang.management.ThreadMXBean
+import java.util.concurrent.atomic.AtomicLong
+
+interface PerfCounters {
+    val count: Long
+    val time: Long
+    val threadTime: Long
+    val threadUserTime: Long
+    val memory: Long
+
+    fun addMeasurement(time: Long = 0, thread: Long = 0, threadUser: Long = 0, memory: Long = 0)
+}
+
+interface Profiler {
+    fun getCounters(): Map<Any?, PerfCounters>
+    fun getTotalCounters(): PerfCounters
+
+    fun<R> withMeasure(obj: Any?, body: () -> R): R
+}
+
+
+open class SimplePerfCounters : PerfCounters {
+    private val _count: AtomicLong = AtomicLong(0L)
+    private val _time: AtomicLong = AtomicLong(0L)
+    private val _threadTime: AtomicLong = AtomicLong(0L)
+    private val _threadUserTime: AtomicLong = AtomicLong(0L)
+    private val _memory: AtomicLong = AtomicLong(0L)
+
+    override val count: Long get() = _count.get()
+    override val time: Long get() = _time.get()
+    override val threadTime: Long get() = _threadTime.get()
+    override val threadUserTime: Long get() = _threadUserTime.get()
+    override val memory: Long get() = _memory.get()
+
+    override fun addMeasurement(time: Long, thread: Long, threadUser: Long, memory: Long) {
+        _count.incrementAndGet()
+        _time.addAndGet(time)
+        _threadTime.addAndGet(thread)
+        _threadUserTime.addAndGet(threadUser)
+        _memory.addAndGet(memory)
+    }
+}
+
+
+class SimplePerfCountersWithTotal(val totalRef: PerfCounters) : SimplePerfCounters() {
+    override fun addMeasurement(time: Long, thread: Long, threadUser: Long, memory: Long) {
+        super.addMeasurement(time, thread, threadUser, memory)
+        totalRef.addMeasurement(time, thread, threadUser, memory)
+    }
+}
+
+
+@Suppress("NOTHING_TO_INLINE")
+inline fun ThreadMXBean.threadCpuTime() = if (isCurrentThreadCpuTimeSupported) currentThreadCpuTime else 0L
+
+@Suppress("NOTHING_TO_INLINE")
+inline fun ThreadMXBean.threadUserTime() = if (isCurrentThreadCpuTimeSupported) currentThreadUserTime else 0L
+
+@Suppress("NOTHING_TO_INLINE")
+inline fun usedMemory(withGC: Boolean): Long {
+    if (withGC) {
+        System.gc()
+    }
+    val rt = Runtime.getRuntime()
+    return (rt.totalMemory() - rt.freeMemory())
+}
+
+
+inline fun<R> withMeasureWallTime(perfCounters: PerfCounters, body: () -> R): R {
+    val startTime = System.nanoTime()
+    val res = body()
+    perfCounters.addMeasurement(time = System.nanoTime() - startTime) // TODO: add support for time wrapping
+    return res
+}
+
+
+inline fun<R> withMeasureWallAndThreadTimes(perfCounters: PerfCounters, threadMXBean: ThreadMXBean, body: () -> R): R {
+    val startTime = System.nanoTime()
+    val startThreadTime = threadMXBean.threadCpuTime()
+    val startThreadUserTime = threadMXBean.threadUserTime()
+
+    val res = body()
+
+    // TODO: add support for time wrapping
+    perfCounters.addMeasurement(time = System.nanoTime() - startTime,
+                                thread = threadMXBean.threadCpuTime() - startThreadTime,
+                                threadUser = threadMXBean.threadUserTime() - startThreadUserTime)
+    return res
+}
+
+inline fun<R> withMeasureWallAndThreadTimes(perfCounters: PerfCounters, body: () -> R): R = withMeasureWallAndThreadTimes(perfCounters, ManagementFactory.getThreadMXBean(), body)
+
+
+inline fun<R> withMeasureWallAndThreadTimesAndMemory(perfCounters: PerfCounters, withGC: Boolean = false, threadMXBean: ThreadMXBean, body: () -> R): R {
+    val startMem = usedMemory(withGC)
+    val startTime = System.nanoTime()
+    val startThreadTime = threadMXBean.threadCpuTime()
+    val startThreadUserTime = threadMXBean.threadUserTime()
+
+    val res = body()
+
+    // TODO: add support for time wrapping
+    perfCounters.addMeasurement(time = System.nanoTime() - startTime,
+                                thread = threadMXBean.threadCpuTime() - startThreadTime,
+                                threadUser = threadMXBean.threadUserTime() - startThreadUserTime,
+                                memory = usedMemory(withGC) - startMem)
+    return res
+}
+
+inline fun<R> withMeasureWallAndThreadTimesAndMemory(perfCounters: PerfCounters, withGC: Boolean, body: () -> R): R =
+        withMeasureWallAndThreadTimesAndMemory(perfCounters, withGC, ManagementFactory.getThreadMXBean(), body)
+
+
+class DummyProfiler : Profiler {
+    override fun getCounters(): Map<Any?,PerfCounters> = mapOf(null to SimplePerfCounters())
+    override fun getTotalCounters(): PerfCounters = SimplePerfCounters()
+
+    override final inline fun <R> withMeasure(obj: Any?, body: () -> R): R = body()
+}
+
+
+abstract class TotalProfiler : Profiler {
+
+    val total = SimplePerfCounters()
+    val threadMXBean = ManagementFactory.getThreadMXBean()
+
+    override fun getCounters(): Map<Any?, PerfCounters> = mapOf()
+    override fun getTotalCounters(): PerfCounters = total
+}
+
+
+class WallTotalProfiler : TotalProfiler() {
+    override final inline fun <R> withMeasure(obj: Any?, body: () -> R): R = withMeasureWallTime(total, body)
+}
+
+
+class WallAndThreadTotalProfiler : TotalProfiler() {
+    override final inline fun <R> withMeasure(obj: Any?, body: () -> R): R = withMeasureWallAndThreadTimes(total, threadMXBean, body)
+}
+
+
+class WallAndThreadAndMemoryTotalProfiler(val withGC: Boolean) : TotalProfiler() {
+    override final inline fun <R> withMeasure(obj: Any?, body: () -> R): R = withMeasureWallAndThreadTimesAndMemory(total, withGC, threadMXBean, body)
+}
+
+
+class WallAndThreadByClassProfiler() : TotalProfiler() {
+
+    val counters = hashMapOf<Any?, SimplePerfCountersWithTotal>()
+
+    override fun getCounters(): Map<Any?,PerfCounters> = counters
+
+    override final inline fun <R> withMeasure(obj: Any?, body: () -> R): R =
+            withMeasureWallAndThreadTimes(counters.getOrPut(obj?.javaClass?.name, { SimplePerfCountersWithTotal(total) } ), threadMXBean, body)
+}

compiler/rmi/rmi-server/src/org/jetbrains/kotlin/rmi/service/CompileDaemon.kt

@@ -134,7 +134,7 @@ public object CompileDaemon {
             runFile.deleteOnExit()
 
             val compiler = K2JVMCompiler()
-            val compilerService = CompileServiceImpl(registry, compiler, compilerId, port)
+            val compilerService = CompileServiceImpl(registry, compiler, compilerId, daemonOptions, port)
 
             if (daemonOptions.runFilesPath.isNotEmpty())
                 println(daemonOptions.runFilesPath)

compiler/rmi/rmi-server/src/org/jetbrains/kotlin/rmi/service/CompileServiceImpl.kt

@@ -23,8 +23,6 @@ import org.jetbrains.kotlin.load.kotlin.incremental.components.IncrementalCompil
 import org.jetbrains.kotlin.progress.CompilationCanceledStatus
 import org.jetbrains.kotlin.rmi.*
 import java.io.PrintStream
-import java.lang.management.ManagementFactory
-import java.lang.management.ThreadMXBean
 import java.rmi.NoSuchObjectException
 import java.rmi.registry.Registry
 import java.rmi.server.UnicastRemoteObject
@@ -35,12 +33,13 @@ import kotlin.concurrent.read
 import kotlin.concurrent.write
 
 
-fun nowSeconds() = System.nanoTime() / 1000000000L
+fun nowSeconds() = TimeUnit.NANOSECONDS.toSeconds(System.nanoTime())
 
 class CompileServiceImpl<Compiler: CLICompiler<*>>(
         val registry: Registry,
         val compiler: Compiler,
         val selfCompilerId: CompilerId,
+        val daemonOptions: DaemonOptions,
         port: Int
 ) : CompileService, UnicastRemoteObject() {
 
@@ -48,7 +47,7 @@ class CompileServiceImpl<Compiler: CLICompiler<*>>(
 
     override fun getCompilerId(): CompilerId = ifAlive { selfCompilerId }
 
-    override fun getUsedMemory(): Long = ifAlive { usedMemory() }
+    override fun getUsedMemory(): Long = ifAlive { usedMemory(withGC = true) }
 
     override fun shutdown() {
         ifAliveExclusive {
@@ -65,10 +64,10 @@ class CompileServiceImpl<Compiler: CLICompiler<*>>(
                                outputFormat: CompileService.OutputFormat,
                                serviceOutputStream: RemoteOutputStream
     ): Int =
-            doCompile(args, compilerOutputStream, serviceOutputStream) { printStream ->
+            doCompile(args, compilerOutputStream, serviceOutputStream) { printStream, profiler ->
                 when (outputFormat) {
                     CompileService.OutputFormat.PLAIN -> compiler.exec(printStream, *args)
-                    CompileService.OutputFormat.XML -> compiler.execAndOutputXml(printStream, Services.EMPTY, *args)
+                    CompileService.OutputFormat.XML -> compiler.execAndOutputXml(printStream, createCompileServices(services, profiler), *args)
                 }
             }
 
@@ -78,10 +77,10 @@ class CompileServiceImpl<Compiler: CLICompiler<*>>(
                                           compilerOutputFormat: CompileService.OutputFormat,
                                           serviceOutputStream: RemoteOutputStream
     ): Int =
-            doCompile(args, compilerOutputStream, serviceOutputStream) { printStream ->
+            doCompile(args, compilerOutputStream, serviceOutputStream) { printStream, profiler ->
                 when (compilerOutputFormat) {
                     CompileService.OutputFormat.PLAIN -> throw NotImplementedError("Only XML output is supported in remote incremental compilation")
-                    CompileService.OutputFormat.XML -> compiler.execAndOutputXml(printStream, createCompileServices(services), *args)
+                    CompileService.OutputFormat.XML -> compiler.execAndOutputXml(printStream, createCompileServices(services, profiler), *args)
                 }
             }
 
@@ -123,57 +122,58 @@ class CompileServiceImpl<Compiler: CLICompiler<*>>(
         alive = true
     }
 
-    private fun doCompile(args: Array<out String>, compilerMessagesStreamProxy: RemoteOutputStream, serviceOutputStreamProxy: RemoteOutputStream, body: (PrintStream) -> ExitCode): Int =
+    private fun doCompile(args: Array<out String>, compilerMessagesStreamProxy: RemoteOutputStream, serviceOutputStreamProxy: RemoteOutputStream, body: (PrintStream, Profiler) -> ExitCode): Int =
             ifAlive {
-                val compilerMessagesStream = PrintStream(RemoteOutputStreamClient(compilerMessagesStreamProxy))
+                val rpcProfiler = if (daemonOptions.reportPerf) WallAndThreadTotalProfiler() else DummyProfiler()
-                val serviceOutputStream = PrintStream(RemoteOutputStreamClient(serviceOutputStreamProxy))
+                val compilerMessagesStream = PrintStream(RemoteOutputStreamClient(compilerMessagesStreamProxy, rpcProfiler))
-                checkedCompile(args, serviceOutputStream) {
+                val serviceOutputStream = PrintStream(RemoteOutputStreamClient(serviceOutputStreamProxy, rpcProfiler))
-                    val res = body( compilerMessagesStream).code
+                checkedCompile(args, serviceOutputStream, rpcProfiler) {
+                    val res = body( compilerMessagesStream, rpcProfiler).code
                     _lastUsedSeconds = nowSeconds()
                     res
                 }
             }
 
-    private fun createCompileServices(services: CompileService.RemoteCompilationServices): Services {
+    private fun createCompileServices(services: CompileService.RemoteCompilationServices, rpcProfiler: Profiler): Services {
         val builder = Services.Builder()
-        services.incrementalCompilationComponents?.let { builder.register(IncrementalCompilationComponents::class.java, RemoteIncrementalCompilationComponentsClient(it)) }
+        services.incrementalCompilationComponents?.let { builder.register(IncrementalCompilationComponents::class.java, RemoteIncrementalCompilationComponentsClient(it, rpcProfiler)) }
-        services.compilationCanceledStatus?.let { builder.register(CompilationCanceledStatus::class.java, RemoteCompilationCanceledStatusClient(it)) }
+        services.compilationCanceledStatus?.let { builder.register(CompilationCanceledStatus::class.java, RemoteCompilationCanceledStatusClient(it, rpcProfiler)) }
         return builder.build()
     }
 
 
-    fun usedMemory(): Long {
+    fun<R> checkedCompile(args: Array<out String>, serviceOut: PrintStream, rpcProfiler: Profiler, body: () -> R): R {
-        System.gc()
-        val rt = Runtime.getRuntime()
-        return (rt.totalMemory() - rt.freeMemory())
-    }
-
-    fun ThreadMXBean.threadCpuTime() = if (isCurrentThreadCpuTimeSupported) currentThreadCpuTime else 0L
-    fun ThreadMXBean.threadUserTime() = if (isCurrentThreadCpuTimeSupported) currentThreadUserTime else 0L
-
-    fun<R> checkedCompile(args: Array<out String>, serviceOut: PrintStream, body: () -> R): R {
         try {
             if (args.none())
                 throw IllegalArgumentException("Error: empty arguments list.")
             log.info("Starting compilation with args: " + args.joinToString(" "))
-            val threadMXBean: ThreadMXBean = ManagementFactory.getThreadMXBean()
+
-            val startMem = usedMemory() / 1024
+            val profiler = if (daemonOptions.reportPerf) WallAndThreadAndMemoryTotalProfiler(withGC = false) else DummyProfiler()
-            val startTime = System.nanoTime()
+
-            val startThreadTime = threadMXBean.threadCpuTime()
+            val res = profiler.withMeasure(null, body)
-            val startThreadUserTime = threadMXBean.threadUserTime()
+
-            val res = body()
+            val endMem = if (daemonOptions.reportPerf) usedMemory(withGC = false) else 0L
-            val endTime = System.nanoTime()
+
-            val endThreadTime = threadMXBean.threadCpuTime()
-            val endThreadUserTime = threadMXBean.threadUserTime()
-            val endMem = usedMemory() / 1024
             log.info("Done with result " + res.toString())
-            val elapsed = TimeUnit.NANOSECONDS.toMillis(endTime - startTime)
+
-            val elapsedThread = TimeUnit.NANOSECONDS.toMillis(endThreadTime - startThreadTime)
+            if (daemonOptions.reportPerf) {
-            val elapsedThreadUser = TimeUnit.NANOSECONDS.toMillis(endThreadUserTime - startThreadUserTime)
+                fun Long.ms() = TimeUnit.NANOSECONDS.toMillis(this)
-            log.info("Elapsed time: $elapsed ms (thread user: $elapsedThreadUser ms sys: ${elapsedThread - elapsedThreadUser} ms)")
+                fun Long.kb() = this / 1024
-            log.info("Used memory: $endMem kb (${"%+d".format(endMem - startMem)} kb)")
+                val pc = profiler.getTotalCounters()
-            System.getProperty(COMPILE_DAEMON_REPORT_PERF_PROPERTY)?.let {
+                val rpc = rpcProfiler.getTotalCounters()
-                serviceOut.println("PERF: Compile on daemon: $elapsed ms (thread user: $elapsedThreadUser ms sys: ${elapsedThread - elapsedThreadUser} ms); memory: $endMem kb (${"%+d".format(endMem - startMem)} kb)")
+
+                "PERF: Compile on daemon: ${pc.time.ms()} ms; thread: user ${pc.threadUserTime.ms()} ms, sys ${(pc.threadTime - pc.threadUserTime).ms()} ms; rpc: ${rpc.count} calls, ${rpc.time.ms()} ms, thread ${rpc.threadTime.ms()} ms; memory: ${endMem.kb()} kb (${"%+d".format(pc.memory.kb())} kb)".let {
+                    serviceOut.println(it)
+                    log.info(it)
+                }
+
+                // this will only be reported if if appropriate (e.g. ByClass) profiler is used
+                for ((obj, counters) in rpcProfiler.getCounters()) {
+                    "PERF: rpc by $obj: ${counters.count} calls, ${counters.time.ms()} ms, thread ${counters.threadTime.ms()} ms".let {
+                        serviceOut.println(it)
+                        log.info(it)
+                    }
+                }
             }
             return res
         }
@@ -200,5 +200,4 @@ class CompileServiceImpl<Compiler: CLICompiler<*>>(
         log.info(msg + " = " + res.toString())
         return res
     }
-
 }

compiler/rmi/rmi-server/src/org/jetbrains/kotlin/rmi/service/RemoteCompilationCanceledStatusClient.kt

@@ -18,10 +18,12 @@ package org.jetbrains.kotlin.rmi.service
 
 import org.jetbrains.kotlin.progress.CompilationCanceledStatus
 import org.jetbrains.kotlin.rmi.CompileService
+import org.jetbrains.kotlin.rmi.DummyProfiler
+import org.jetbrains.kotlin.rmi.Profiler
 
 
-class RemoteCompilationCanceledStatusClient(val proxy: CompileService.RemoteCompilationCanceledStatus): CompilationCanceledStatus {
+class RemoteCompilationCanceledStatusClient(val proxy: CompileService.RemoteCompilationCanceledStatus, val profiler: Profiler = DummyProfiler()): CompilationCanceledStatus {
     override fun checkCanceled() {
-        proxy.checkCanceled()
+        profiler.withMeasure(this) { proxy.checkCanceled() }
     }
 }

compiler/rmi/rmi-server/src/org/jetbrains/kotlin/rmi/service/RemoteIncrementalCacheClient.kt

@@ -19,25 +19,28 @@ package org.jetbrains.kotlin.rmi.service
 import org.jetbrains.kotlin.load.kotlin.incremental.components.IncrementalCache
 import org.jetbrains.kotlin.load.kotlin.incremental.components.JvmPackagePartProto
 import org.jetbrains.kotlin.rmi.CompileService
+import org.jetbrains.kotlin.rmi.DummyProfiler
+import org.jetbrains.kotlin.rmi.Profiler
 
-public class RemoteIncrementalCacheClient(val cache: CompileService.RemoteIncrementalCache): IncrementalCache {
+public class RemoteIncrementalCacheClient(val cache: CompileService.RemoteIncrementalCache, val profiler: Profiler = DummyProfiler()): IncrementalCache {
-    override fun getObsoleteMultifileClasses(): Collection<String> = cache.getObsoleteMultifileClassFacades()
 
-    override fun getStableMultifileFacadeParts(facadeInternalName: String): Collection<String>? = cache.getMultifileFacadeParts(facadeInternalName)
+    override fun getObsoletePackageParts(): Collection<String> = profiler.withMeasure(this) { cache.getObsoletePackageParts() }
 
-    override fun getObsoletePackageParts(): Collection<String> = cache.getObsoletePackageParts()
+    override fun getObsoleteMultifileClasses(): Collection<String> = profiler.withMeasure(this) { cache.getObsoleteMultifileClassFacades() }
 
-    override fun getMultifileFacade(partInternalName: String): String? = cache.getMultifileFacade(partInternalName)
+    override fun getStableMultifileFacadeParts(facadeInternalName: String): Collection<String>? = profiler.withMeasure(this) { cache.getMultifileFacadeParts(facadeInternalName) }
 
-    override fun getPackagePartData(fqName: String): JvmPackagePartProto? = cache.getPackagePartData(fqName)
+    override fun getPackagePartData(fqName: String): JvmPackagePartProto? = profiler.withMeasure(this) { cache.getPackagePartData(fqName) }
 
-    override fun getModuleMappingData(): ByteArray? = cache.getModuleMappingData()
+    override fun getMultifileFacade(partInternalName: String): String? = profiler.withMeasure(this) { cache.getMultifileFacade(partInternalName) }
+
+    override fun getModuleMappingData(): ByteArray? = profiler.withMeasure(this) { cache.getModuleMappingData() }
 
     override fun registerInline(fromPath: String, jvmSignature: String, toPath: String) {
-        cache.registerInline(fromPath, jvmSignature, toPath)
+        profiler.withMeasure(this) { cache.registerInline(fromPath, jvmSignature, toPath) }
     }
 
-    override fun getClassFilePath(internalClassName: String): String = cache.getClassFilePath(internalClassName)
+    override fun getClassFilePath(internalClassName: String): String = profiler.withMeasure(this) { cache.getClassFilePath(internalClassName) }
 
-    override fun close(): Unit = cache.close()
+    override fun close(): Unit = profiler.withMeasure(this) { cache.close() }
 }

compiler/rmi/rmi-server/src/org/jetbrains/kotlin/rmi/service/RemoteIncrementalCompilationComponentsClient.kt

@@ -21,11 +21,13 @@ import org.jetbrains.kotlin.load.kotlin.incremental.components.IncrementalCache
 import org.jetbrains.kotlin.load.kotlin.incremental.components.IncrementalCompilationComponents
 import org.jetbrains.kotlin.modules.TargetId
 import org.jetbrains.kotlin.rmi.CompileService
+import org.jetbrains.kotlin.rmi.DummyProfiler
+import org.jetbrains.kotlin.rmi.Profiler
 
 
-class RemoteIncrementalCompilationComponentsClient(val proxy: CompileService.RemoteIncrementalCompilationComponents) : IncrementalCompilationComponents {
+class RemoteIncrementalCompilationComponentsClient(val proxy: CompileService.RemoteIncrementalCompilationComponents, val profiler: Profiler = DummyProfiler()) : IncrementalCompilationComponents {
 
-    override fun getIncrementalCache(target: TargetId): IncrementalCache = RemoteIncrementalCacheClient(proxy.getIncrementalCache(target))
+    override fun getIncrementalCache(target: TargetId): IncrementalCache = RemoteIncrementalCacheClient(profiler.withMeasure(this) { proxy.getIncrementalCache(target) }, profiler)
 
-    override fun getLookupTracker(): LookupTracker = RemoteLookupTrackerClient(proxy.getLookupTracker())
+    override fun getLookupTracker(): LookupTracker = RemoteLookupTrackerClient(profiler.withMeasure(this) { proxy.getLookupTracker() }, profiler)
 }

compiler/rmi/rmi-server/src/org/jetbrains/kotlin/rmi/service/RemoteLookupTrackerClient.kt

@@ -19,14 +19,19 @@ package org.jetbrains.kotlin.rmi.service
 import org.jetbrains.kotlin.incremental.components.LookupTracker
 import org.jetbrains.kotlin.incremental.components.ScopeKind
 import org.jetbrains.kotlin.rmi.CompileService
+import org.jetbrains.kotlin.rmi.DummyProfiler
+import org.jetbrains.kotlin.rmi.Profiler
 
 
-class RemoteLookupTrackerClient(val proxy: CompileService.RemoteLookupTracker) : LookupTracker {
+class RemoteLookupTrackerClient(val proxy: CompileService.RemoteLookupTracker, val profiler: Profiler = DummyProfiler()) : LookupTracker {
 
-    private val isDoNothing = proxy.isDoNothing()
+    private val isDoNothing = profiler.withMeasure(this) { proxy.isDoNothing() }
 
     override fun record(lookupContainingFile: String, lookupLine: Int?, lookupColumn: Int?, scopeFqName: String, scopeKind: ScopeKind, name: String) {
-        if (!isDoNothing)
+        if (!isDoNothing) {
-            proxy.record(lookupContainingFile, lookupLine, lookupColumn, scopeFqName, scopeKind, name)
+            profiler.withMeasure(this) {
+                proxy.record(lookupContainingFile, lookupLine, lookupColumn, scopeFqName, scopeKind, name)
+            }
+        }
     }
 }

compiler/rmi/rmi-server/src/org/jetbrains/kotlin/rmi/service/RemoteOutputStreamClient.kt

@@ -16,19 +16,21 @@
 
 package org.jetbrains.kotlin.rmi.service
 
+import org.jetbrains.kotlin.rmi.DummyProfiler
+import org.jetbrains.kotlin.rmi.Profiler
 import org.jetbrains.kotlin.rmi.RemoteOutputStream
 import java.io.OutputStream
 
-class RemoteOutputStreamClient(val remote: RemoteOutputStream): OutputStream() {
+class RemoteOutputStreamClient(val remote: RemoteOutputStream, val profiler: Profiler = DummyProfiler()): OutputStream() {
     override fun write(data: ByteArray) {
-        remote.write(data, 0, data.size())
+        profiler.withMeasure(this) { remote.write(data, 0, data.size()) }
     }
 
     override fun write(data: ByteArray, offset: Int, length: Int) {
-        remote.write(data, offset, length)
+        profiler.withMeasure(this) { remote.write(data, offset, length) }
     }
 
     override fun write(byte: Int) {
-        remote.write(byte)
+        profiler.withMeasure(this) { remote.write(byte) }
     }
 }

compiler/tests/org/jetbrains/kotlin/daemon/CompilerDaemonTest.kt

@@ -60,14 +60,15 @@ public class CompilerDaemonTest : KotlinIntegrationTestBase() {
         val flagFile = createTempFile(getTestName(true), ".alive")
         flagFile.deleteOnExit()
         val daemonOptions = DaemonOptions(runFilesPath = File(tmpdir, getTestName(true)).absolutePath,
-                                          clientAliveFlagPath = flagFile.absolutePath)
+                                          clientAliveFlagPath = flagFile.absolutePath,
+                                          verbose = true,
+                                          reportPerf = true)
 
         KotlinCompilerClient.shutdownCompileService(compilerId, daemonOptions)
 
         val logFile = createTempFile("kotlin-daemon-test.", ".log")
 
         val daemonJVMOptions = configureDaemonJVMOptions(false,
-                                                         "D$COMPILE_DAEMON_VERBOSE_REPORT_PROPERTY",
                                                          "D$COMPILE_DAEMON_LOG_PATH_PROPERTY=\"${logFile.absolutePath}\"")
         var daemonShotDown = false
 
@@ -83,9 +84,9 @@ public class CompilerDaemonTest : KotlinIntegrationTestBase() {
             logFile.reader().useLines {
                 it.ifNotContainsSequence( LinePattern("Kotlin compiler daemon version"),
                                           LinePattern("Starting compilation with args: "),
-                                          LinePattern("Elapsed time: (\\d+) ms", { it.groups.get(1)?.value?.toLong()?.let { compileTime1 = it }; true } ),
+                                          LinePattern("Compile on daemon: (\\d+) ms", { it.groups.get(1)?.value?.toLong()?.let { compileTime1 = it }; true } ),
                                           LinePattern("Starting compilation with args: "),
-                                          LinePattern("Elapsed time: (\\d+) ms", { it.groups.get(1)?.value?.toLong()?.let { compileTime2 = it }; true } ),
+                                          LinePattern("Compile on daemon: (\\d+) ms", { it.groups.get(1)?.value?.toLong()?.let { compileTime2 = it }; true } ),
                                           LinePattern("Shutdown complete"))
                 { unmatchedPattern, lineNo ->
                     TestCase.fail("pattern not found in the input: " + unmatchedPattern.regex +

jps-plugin/src/org/jetbrains/kotlin/compilerRunner/KotlinCompilerRunner.kt

@@ -16,10 +16,6 @@
 
 package org.jetbrains.kotlin.compilerRunner
 
-import com.intellij.openapi.util.text.StringUtil
-import com.intellij.util.ArrayUtil
-import com.intellij.util.Function
-import com.intellij.util.containers.ContainerUtil
 import com.intellij.util.xmlb.XmlSerializerUtil
 import org.jetbrains.kotlin.cli.common.ExitCode
 import org.jetbrains.kotlin.cli.common.arguments.CommonCompilerArguments
@@ -34,16 +30,13 @@ import org.jetbrains.kotlin.cli.common.messages.MessageCollectorUtil
 import org.jetbrains.kotlin.config.CompilerSettings
 import org.jetbrains.kotlin.load.kotlin.incremental.components.IncrementalCompilationComponents
 import org.jetbrains.kotlin.progress.CompilationCanceledStatus
-import org.jetbrains.kotlin.rmi.CompilerId
+import org.jetbrains.kotlin.rmi.*
-import org.jetbrains.kotlin.rmi.configureDaemonJVMOptions
-import org.jetbrains.kotlin.rmi.configureDaemonOptions
-import org.jetbrains.kotlin.rmi.isDaemonEnabled
 import org.jetbrains.kotlin.rmi.kotlinr.*
-import org.jetbrains.kotlin.utils.rethrow
 import java.io.*
 import java.lang.reflect.Field
 import java.lang.reflect.Modifier
 import java.util.*
+import java.util.concurrent.TimeUnit
 
 public object KotlinCompilerRunner {
     private val K2JVM_COMPILER = "org.jetbrains.kotlin.cli.jvm.K2JVMCompiler"
@@ -150,14 +143,9 @@ public object KotlinCompilerRunner {
             val daemon = KotlinCompilerClient.connectToCompileService(compilerId, daemonJVMOptions, daemonOptions, DaemonReportingTargets(null, daemonReportMessages), true, true)
 
             for (msg in daemonReportMessages) {
-                if (msg.category === DaemonReportCategory.EXCEPTION && daemon == null) {
+                messageCollector.report(CompilerMessageSeverity.INFO,
-                    messageCollector.report(CompilerMessageSeverity.INFO,
+                                        (if (msg.category == DaemonReportCategory.EXCEPTION && daemon == null)  "Falling  back to compilation without daemon due to error: " else "") + msg.message,
-                                            "Falling  back to compilation without daemon due to error: " + msg.message,
+                                        CompilerMessageLocation.NO_LOCATION)
-                                            CompilerMessageLocation.NO_LOCATION)
-                }
-                else {
-                    messageCollector.report(CompilerMessageSeverity.INFO, msg.message, CompilerMessageLocation.NO_LOCATION)
-                }
             }
 
             if (daemon != null) {
@@ -168,12 +156,21 @@ public object KotlinCompilerRunner {
                         incrementalCompilationComponents = environment.services.get(IncrementalCompilationComponents::class.java),
                         compilationCanceledStatus = environment.services.get(CompilationCanceledStatus::class.java))
 
-                val res = KotlinCompilerClient.incrementalCompile(daemon, argsArray, services, compilerOut, daemonOut)
+                val profiler = if (daemonOptions.reportPerf) WallAndThreadTotalProfiler() else DummyProfiler()
+
+                val res = KotlinCompilerClient.incrementalCompile(daemon, argsArray, services, compilerOut, daemonOut, profiler)
 
                 processCompilerOutput(messageCollector, collector, compilerOut, res.toString())
                 BufferedReader(StringReader(daemonOut.toString())).forEachLine {
                     messageCollector.report(CompilerMessageSeverity.INFO, it, CompilerMessageLocation.NO_LOCATION)
                 }
+                if (daemonOptions.reportPerf) {
+                    fun Long.ms() = TimeUnit.NANOSECONDS.toMillis(this)
+                    val counters = profiler.getTotalCounters()
+                    messageCollector.report(CompilerMessageSeverity.INFO,
+                                            "PERF: Daemon call total ${counters.time.ms()} ms, thread ${counters.threadTime.ms()}",
+                                            CompilerMessageLocation.NO_LOCATION)
+                }
                 return true
             }
         }