performance counters infrastructure

2015-06-03 13:17:12 +02:00
parent a3a33ce089
commit a321e8eef5
10 changed files with 304 additions and 122 deletions
@@ -66,6 +66,9 @@ public class K2JVMCompilerArguments extends CommonCompilerArguments {
    @Argument(value = "Xno-optimize", description = "Disable optimizations")
    public boolean noOptimize;

+    @Argument(value = "Xreport-perf", description = "Report detailed performance statistics")
+    public boolean reportPerf;
+
    @Override
    @NotNull
    public String executableScriptFileName() {
@@ -19,6 +19,8 @@ package org.jetbrains.kotlin.cli.jvm;
 import com.google.common.base.Splitter;
 import com.google.common.collect.Lists;
 import com.intellij.openapi.Disposable;
+import kotlin.Unit;
+import kotlin.jvm.functions.Function1;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.kotlin.cli.common.CLICompiler;
 import org.jetbrains.kotlin.cli.common.CLIConfigurationKeys;
@@ -37,6 +39,7 @@ import org.jetbrains.kotlin.config.CompilerConfiguration;
 import org.jetbrains.kotlin.config.Services;
 import org.jetbrains.kotlin.load.kotlin.incremental.cache.IncrementalCacheProvider;
 import org.jetbrains.kotlin.resolve.AnalyzerScriptParameter;
+import org.jetbrains.kotlin.util.PerformanceCounter;
 import org.jetbrains.kotlin.utils.KotlinPaths;
 import org.jetbrains.kotlin.utils.KotlinPathsFromHomeDir;
 import org.jetbrains.kotlin.utils.PathUtil;
@@ -44,14 +47,17 @@ import org.jetbrains.kotlin.utils.PathUtil;
 import java.io.File;
 import java.util.Collections;
 import java.util.List;
+import java.util.concurrent.TimeUnit;

 import static com.google.common.base.Predicates.in;
 import static org.jetbrains.kotlin.cli.common.ExitCode.*;
-import static org.jetbrains.kotlin.cli.jvm.config.ConfigPackage.*;
+import static org.jetbrains.kotlin.cli.jvm.config.ConfigPackage.addJavaSourceRoot;
+import static org.jetbrains.kotlin.cli.jvm.config.ConfigPackage.addJvmClasspathRoots;
 import static org.jetbrains.kotlin.config.ConfigPackage.addKotlinSourceRoot;

@SuppressWarnings("UseOfSystemOutOrSystemErr")
 public class K2JVMCompiler extends CLICompiler<K2JVMCompilerArguments> {
+    private final long initStartNanos = System.nanoTime();

    public static void main(String... args) {
        doMain(new K2JVMCompiler(), args);
@@ -72,7 +78,7 @@ public class K2JVMCompiler extends CLICompiler<K2JVMCompilerArguments> {
        messageCollector.report(CompilerMessageSeverity.LOGGING,
                                "Using Kotlin home directory " + paths.getHomePath(), CompilerMessageLocation.NO_LOCATION);

-        CompilerConfiguration configuration = new CompilerConfiguration();
+        final CompilerConfiguration configuration = new CompilerConfiguration();
        configuration.put(CLIConfigurationKeys.MESSAGE_COLLECTOR_KEY, messageCollector);

        IncrementalCacheProvider incrementalCacheProvider = services.get(IncrementalCacheProvider.class);
@@ -163,6 +169,7 @@ public class K2JVMCompiler extends CLICompiler<K2JVMCompilerArguments> {
                jar = null;
                outputDir = null;
            }
+            final KotlinCoreEnvironment environment;

            if (arguments.module != null) {
                MessageCollector sanitizedCollector = new FilteringMessageCollector(messageCollector, in(CompilerMessageSeverity.VERBOSE));
@@ -175,21 +182,33 @@ public class K2JVMCompiler extends CLICompiler<K2JVMCompilerArguments> {
                }

                File directory = new File(arguments.module).getAbsoluteFile().getParentFile();
+
+                CompilerConfiguration compilerConfiguration = KotlinToJVMBytecodeCompiler
+                        .createCompilerConfiguration(configuration, moduleScript.getModules(), directory);
+                environment = createCoreEnvironment(rootDisposable, compilerConfiguration);
+
                KotlinToJVMBytecodeCompiler.compileModules(
-                        configuration, moduleScript.getModules(), directory, jar, arguments.includeRuntime
-                );
+                        environment, configuration, moduleScript.getModules(), directory, jar, arguments.includeRuntime);
            }
            else if (arguments.script) {
                List<String> scriptArgs = arguments.freeArgs.subList(1, arguments.freeArgs.size());
-                KotlinCoreEnvironment environment =
-                        KotlinCoreEnvironment.createForProduction(rootDisposable, configuration, EnvironmentConfigFiles.JVM_CONFIG_FILES);
+                environment = createCoreEnvironment(rootDisposable, configuration);
                KotlinToJVMBytecodeCompiler.compileAndExecuteScript(configuration, paths, environment, scriptArgs);
            }
            else {
-                KotlinCoreEnvironment environment =
-                        KotlinCoreEnvironment.createForProduction(rootDisposable, configuration, EnvironmentConfigFiles.JVM_CONFIG_FILES);
+                environment = createCoreEnvironment(rootDisposable, configuration);
                KotlinToJVMBytecodeCompiler.compileBunchOfSources(environment, jar, outputDir, arguments.includeRuntime);
            }
+
+            if (arguments.reportPerf) {
+                PerformanceCounter.Companion.report(new Function1<String, Unit>() {
+                    @Override
+                    public Unit invoke(String s) {
+                        reportPerf(environment.getConfiguration(), s);
+                        return Unit.INSTANCE$;
+                    }
+                });
+            }
            return OK;
        }
        catch (CompilationException e) {
@@ -199,6 +218,23 @@ public class K2JVMCompiler extends CLICompiler<K2JVMCompilerArguments> {
        }
    }

+    private KotlinCoreEnvironment createCoreEnvironment(
+            @NotNull Disposable rootDisposable,
+            @NotNull CompilerConfiguration configuration) {
+        KotlinCoreEnvironment result = KotlinCoreEnvironment.createForProduction(
+                rootDisposable, configuration, EnvironmentConfigFiles.JVM_CONFIG_FILES);
+
+        long initNanos = System.nanoTime() - initStartNanos;
+        reportPerf(configuration, "Compiler initialized in " + TimeUnit.NANOSECONDS.toMillis(initNanos) + " ms");
+        return result;
+    }
+
+    public static void reportPerf(CompilerConfiguration configuration, String message) {
+        MessageCollector collector = configuration.get(CLIConfigurationKeys.MESSAGE_COLLECTOR_KEY);
+        assert collector != null;
+        collector.report(CompilerMessageSeverity.INFO, "PERF: " + message, CompilerMessageLocation.NO_LOCATION);
+    }
+
    private static void putAdvancedOptions(@NotNull CompilerConfiguration configuration, @NotNull K2JVMCompilerArguments arguments) {
        configuration.put(JVMConfigurationKeys.DISABLE_CALL_ASSERTIONS, arguments.noCallAssertions);
        configuration.put(JVMConfigurationKeys.DISABLE_PARAM_ASSERTIONS, arguments.noParamAssertions);
@@ -29,12 +29,14 @@ import com.intellij.psi.search.GlobalSearchScope
 import org.jetbrains.kotlin.name.ClassId
 import org.jetbrains.kotlin.name.FqName
 import org.jetbrains.kotlin.resolve.jvm.KotlinCliJavaFileManager
+import org.jetbrains.kotlin.util.PerformanceCounter
 import java.util.ArrayList
 import kotlin.properties.Delegates

 public class KotlinCliJavaFileManagerImpl(private val myPsiManager: PsiManager)
 : CoreJavaFileManager(myPsiManager), KotlinCliJavaFileManager {

+    private val perfCounter = PerformanceCounter("Find Java class")
    private var index: JvmDependenciesIndex by Delegates.notNull()

    public fun initIndex(packagesCache: JvmDependenciesIndex) {
@@ -42,9 +44,11 @@ public class KotlinCliJavaFileManagerImpl(private val myPsiManager: PsiManager)
    }

    public override fun findClass(classId: ClassId, searchScope: GlobalSearchScope): PsiClass? {
-        val classNameWithInnerClasses = classId.getRelativeClassName().asString()
-        return index.findClass(classId) { dir, type ->
-            findClassGivenPackage(searchScope, dir, classNameWithInnerClasses, type)
+        return perfCounter.time {
+            val classNameWithInnerClasses = classId.getRelativeClassName().asString()
+            index.findClass(classId) { dir, type ->
+                findClassGivenPackage(searchScope, dir, classNameWithInnerClasses, type)
+            }
        }
    }

@@ -58,22 +62,26 @@ public class KotlinCliJavaFileManagerImpl(private val myPsiManager: PsiManager)
    }

    override fun findClasses(qName: String, scope: GlobalSearchScope): Array<PsiClass> {
-        val classIdAsTopLevelClass = qName.toSafeTopLevelClassId() ?: return super<CoreJavaFileManager>.findClasses(qName, scope)
+        return perfCounter.time {
+            val classIdAsTopLevelClass = qName.toSafeTopLevelClassId() ?: return@time super<CoreJavaFileManager>.findClasses(qName, scope)

-        val result = ArrayList<PsiClass>()
-        val classNameWithInnerClasses = classIdAsTopLevelClass.getRelativeClassName().asString()
-        index.traverseDirectoriesInPackage(classIdAsTopLevelClass.getPackageFqName()) { dir, rootType ->
-            val psiClass = findClassGivenPackage(scope, dir, classNameWithInnerClasses, rootType)
-            if (psiClass != null) {
-                result.add(psiClass)
+            val result = ArrayList<PsiClass>()
+            val classNameWithInnerClasses = classIdAsTopLevelClass.getRelativeClassName().asString()
+            index.traverseDirectoriesInPackage(classIdAsTopLevelClass.getPackageFqName()) { dir, rootType ->
+                val psiClass = findClassGivenPackage(scope, dir, classNameWithInnerClasses, rootType)
+                if (psiClass != null) {
+                    result.add(psiClass)
+                }
+                // traverse all
+                true
+            }
+            if (result.isEmpty()) {
+                super<CoreJavaFileManager>.findClasses(qName, scope)
+            }
+            else {
+                result.toTypedArray()
            }
-            // traverse all
-            true
        }
-        if (result.isEmpty()) {
-            return super<CoreJavaFileManager>.findClasses(qName, scope)
-        }
-        return result.toArray<PsiClass>(arrayOfNulls<PsiClass>(result.size()))
    }

    override fun findPackage(packageName: String): PsiPackage? {
@@ -37,6 +37,7 @@ import com.intellij.openapi.fileTypes.PlainTextFileType
 import com.intellij.openapi.project.Project
 import com.intellij.openapi.util.Disposer
 import com.intellij.openapi.util.io.FileUtil
+import com.intellij.openapi.util.text.StringUtil
 import com.intellij.openapi.vfs.VirtualFile
 import com.intellij.psi.FileContextProvider
 import com.intellij.psi.PsiElementFinder
@@ -86,6 +87,7 @@ import java.io.File
 import java.util.ArrayList
 import java.util.Comparator
 import kotlin.platform.platformStatic
+import kotlin.properties.Delegates

 public class KotlinCoreEnvironment private(
        parentDisposable: Disposable, 
@@ -157,6 +159,14 @@ public class KotlinCoreEnvironment private(
    public val project: Project
        get() = projectEnvironment.getProject()

+    public val sourceLinesOfCode: Int by Delegates.lazy { countLinesOfCode(sourceFiles) }
+
+    public fun countLinesOfCode(sourceFiles: List<JetFile>): Int  =
+            sourceFiles.sumBy {
+                val text = it.getText()
+                StringUtil.getLineBreakCount(it.getText()) + (if (StringUtil.endsWithLineBreak(text)) 0 else 1)
+            }
+
    private fun addExternalAnnotationsRoot(path: File) {
        if (!path.exists()) {
            report(WARNING, "Annotations path entry points to a non-existent location: " + path)
@@ -18,8 +18,6 @@ package org.jetbrains.kotlin.cli.jvm.compiler;

 import com.google.common.collect.Lists;
 import com.google.common.collect.Maps;
-import com.intellij.openapi.Disposable;
-import com.intellij.openapi.util.Disposer;
 import com.intellij.util.ArrayUtil;
 import kotlin.Unit;
 import kotlin.jvm.functions.Function0;
@@ -35,6 +33,7 @@ import org.jetbrains.kotlin.cli.common.messages.AnalyzerWithCompilerReport;
 import org.jetbrains.kotlin.cli.common.messages.MessageCollector;
 import org.jetbrains.kotlin.cli.common.modules.Module;
 import org.jetbrains.kotlin.cli.common.output.outputUtils.OutputUtilsPackage;
+import org.jetbrains.kotlin.cli.jvm.K2JVMCompiler;
 import org.jetbrains.kotlin.cli.jvm.config.JVMConfigurationKeys;
 import org.jetbrains.kotlin.codegen.*;
 import org.jetbrains.kotlin.codegen.state.GenerationState;
@@ -55,6 +54,7 @@ import org.jetbrains.kotlin.resolve.BindingTraceContext;
 import org.jetbrains.kotlin.resolve.ScriptNameUtil;
 import org.jetbrains.kotlin.resolve.jvm.JvmClassName;
 import org.jetbrains.kotlin.resolve.jvm.TopDownAnalyzerFacadeForJVM;
+import org.jetbrains.kotlin.util.PerformanceCounter;
 import org.jetbrains.kotlin.utils.KotlinPaths;

 import java.io.File;
@@ -64,6 +64,7 @@ import java.util.Collection;
 import java.util.HashSet;
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.TimeUnit;

 import static org.jetbrains.kotlin.cli.jvm.config.ConfigPackage.*;
 import static org.jetbrains.kotlin.config.ConfigPackage.addKotlinSourceRoots;
@@ -110,6 +111,7 @@ public class KotlinToJVMBytecodeCompiler {
    }

    public static boolean compileModules(
+            @NotNull KotlinCoreEnvironment environment,
            @NotNull CompilerConfiguration configuration,
            @NotNull List<Module> chunk,
            @NotNull File directory,
@@ -118,39 +120,25 @@ public class KotlinToJVMBytecodeCompiler {
    ) {
        Map<Module, ClassFileFactory> outputFiles = Maps.newHashMap();

-        CompilerConfiguration compilerConfiguration = createCompilerConfiguration(configuration, chunk, directory);
-
-        Disposable parentDisposable = Disposer.newDisposable();
-        KotlinCoreEnvironment environment = null;
-        try {
-            environment = KotlinCoreEnvironment
-                    .createForProduction(parentDisposable, compilerConfiguration, EnvironmentConfigFiles.JVM_CONFIG_FILES);
-
-            AnalysisResult result = analyze(environment);
-            if (result == null) {
-                return false;
-            }
-
-            result.throwIfError();
-
-            for (Module module : chunk) {
-                List<JetFile> jetFiles = CompileEnvironmentUtil.getJetFiles(
-                        environment.getProject(), getAbsolutePaths(directory, module), new Function1<String, Unit>() {
-                            @Override
-                            public Unit invoke(String s) {
-                                throw new IllegalStateException("Should have been checked before: " + s);
-                            }
-                        }
-                );
-                GenerationState generationState =
-                        generate(environment, result, jetFiles, module.getModuleName(), new File(module.getOutputDirectory()));
-                outputFiles.put(module, generationState.getFactory());
-            }
+        AnalysisResult result = analyze(environment);
+        if (result == null) {
+            return false;
        }
-        finally {
-            if (environment != null) {
-                Disposer.dispose(parentDisposable);
-            }
+
+        result.throwIfError();
+
+        for (Module module : chunk) {
+            List<JetFile> jetFiles = CompileEnvironmentUtil.getJetFiles(
+                    environment.getProject(), getAbsolutePaths(directory, module), new Function1<String, Unit>() {
+                        @Override
+                        public Unit invoke(String s) {
+                            throw new IllegalStateException("Should have been checked before: " + s);
+                        }
+                    }
+            );
+            GenerationState generationState =
+                    generate(environment, result, jetFiles, module.getModuleName(), new File(module.getOutputDirectory()));
+            outputFiles.put(module, generationState.getFactory());
        }

        for (Module module : chunk) {
@@ -160,7 +148,7 @@ public class KotlinToJVMBytecodeCompiler {
    }

    @NotNull
-    private static CompilerConfiguration createCompilerConfiguration(
+    public static CompilerConfiguration createCompilerConfiguration(
            @NotNull CompilerConfiguration base,
            @NotNull List<Module> chunk,
            @NotNull File directory
@@ -309,6 +297,7 @@ public class KotlinToJVMBytecodeCompiler {
        MessageCollector collector = environment.getConfiguration().get(CLIConfigurationKeys.MESSAGE_COLLECTOR_KEY);
        assert collector != null;

+        long analysisStart = PerformanceCounter.Companion.currentThreadCpuTime();
        AnalyzerWithCompilerReport analyzerWithCompilerReport = new AnalyzerWithCompilerReport(collector);
        analyzerWithCompilerReport.analyzeAndReport(
                environment.getSourceFiles(), new Function0<AnalysisResult>() {
@@ -328,6 +317,10 @@ public class KotlinToJVMBytecodeCompiler {
                    }
                }
        );
+        long analysisNanos = PerformanceCounter.Companion.currentThreadCpuTime() - analysisStart;
+        String message = "Analyzed " + environment.getSourceFiles().size() + " files (" +
+                         environment.getSourceLinesOfCode() + " lines) in " + TimeUnit.NANOSECONDS.toMillis(analysisNanos) + " ms";
+        K2JVMCompiler.reportPerf(environment.getConfiguration(), message);

        AnalysisResult result = analyzerWithCompilerReport.getAnalysisResult();
        assert result != null : "AnalysisResult should be non-null, compiling: " + environment.getSourceFiles();
@@ -381,7 +374,15 @@ public class KotlinToJVMBytecodeCompiler {
                diagnosticHolder,
                outputDirectory
        );
+        long generationStart = PerformanceCounter.Companion.currentThreadCpuTime();
+
        KotlinCodegenFacade.compileCorrectFiles(generationState, CompilationErrorHandler.THROW_EXCEPTION);
+
+        long generationNanos = PerformanceCounter.Companion.currentThreadCpuTime() - generationStart;
+        String message = "Generated " + sourceFiles.size() + " files (" +
+                         environment.countLinesOfCode(sourceFiles) + " lines) in " + TimeUnit.NANOSECONDS.toMillis(generationNanos) + " ms";
+        K2JVMCompiler.reportPerf(environment.getConfiguration(), message);
+
        AnalyzerWithCompilerReport.reportDiagnostics(
                new FilteredJvmDiagnostics(
                        diagnosticHolder.getBindingContext().getDiagnostics(),
@@ -19,12 +19,12 @@ package org.jetbrains.kotlin.load.kotlin
 import com.intellij.ide.highlighter.JavaClassFileType
 import com.intellij.openapi.diagnostic.Logger
 import com.intellij.openapi.vfs.VirtualFile
-import org.jetbrains.kotlin.name.ClassId
 import org.jetbrains.kotlin.load.kotlin.header.KotlinClassHeader
-import org.jetbrains.kotlin.utils.*
-
-import java.io.IOException
+import org.jetbrains.kotlin.name.ClassId
+import org.jetbrains.kotlin.util.PerformanceCounter
+import org.jetbrains.kotlin.utils.rethrow
 import java.io.FileNotFoundException
+import java.io.IOException

 public class VirtualFileKotlinClass private(
        public val file: VirtualFile,
@@ -51,28 +51,30 @@ public class VirtualFileKotlinClass private(

    companion object Factory {
        private val LOG = Logger.getInstance(javaClass<VirtualFileKotlinClass>())
+        private val perfCounter = PerformanceCounter("Binary class from Kotlin file")

        deprecated("Use KotlinBinaryClassCache")
        fun create(file: VirtualFile): VirtualFileKotlinClass? {
-            assert(file.getFileType() == JavaClassFileType.INSTANCE) { "Trying to read binary data from a non-class file $file" }
+            return perfCounter.time {
+                assert(file.getFileType() == JavaClassFileType.INSTANCE) { "Trying to read binary data from a non-class file $file" }

-            try {
-                val byteContent = file.contentsToByteArray()
-                if (byteContent.isEmpty()) return null
-
-                return FileBasedKotlinClass.create(byteContent) {
-                    name, header, innerClasses ->
-                    VirtualFileKotlinClass(file, name, header, innerClasses)
+                try {
+                    val byteContent = file.contentsToByteArray()
+                    if (!byteContent.isEmpty()) {
+                        return@time FileBasedKotlinClass.create(byteContent) {
+                            name, header, innerClasses ->
+                            VirtualFileKotlinClass(file, name, header, innerClasses)
+                        }
+                    }
                }
+                catch (e: FileNotFoundException) {
+                    // Valid situation. User can delete jar file.
+                }
+                catch (e: Throwable) {
+                    LOG.warn(renderFileReadingErrorMessage(file))
+                }
+                null
            }
-            catch (e: FileNotFoundException) {
-                // Valid situation. User can delete jar file.
-            }
-            catch (e: Throwable) {
-                LOG.warn(renderFileReadingErrorMessage(file))
-            }
-
-            return null
        }

        private fun renderFileReadingErrorMessage(file: VirtualFile): String =
@@ -18,6 +18,8 @@ package org.jetbrains.kotlin.resolve.calls;

 import com.google.common.collect.Lists;
 import com.intellij.openapi.progress.ProgressIndicatorProvider;
+import kotlin.Unit;
+import kotlin.jvm.functions.Function0;
 import org.jetbrains.annotations.NotNull;
 import org.jetbrains.annotations.Nullable;
 import org.jetbrains.kotlin.descriptors.*;
@@ -47,6 +49,7 @@ import org.jetbrains.kotlin.types.TypeSubstitutor;
 import org.jetbrains.kotlin.types.expressions.ExpressionTypingContext;
 import org.jetbrains.kotlin.types.expressions.ExpressionTypingServices;
 import org.jetbrains.kotlin.types.expressions.OperatorConventions;
+import org.jetbrains.kotlin.util.PerformanceCounter;

 import javax.inject.Inject;
 import java.util.Collection;
@@ -70,6 +73,9 @@ public class CallResolver {
    private CallCompleter callCompleter;
    private TaskPrioritizer taskPrioritizer;
    private AdditionalCheckerProvider additionalCheckerProvider;
+    
+    private static PerformanceCounter callResolvePerfCounter = new PerformanceCounter("Call resolve", true);
+    private static PerformanceCounter candidatePerfCounter = new PerformanceCounter("Call resolve candidate analysis", true);

    @Inject
    public void setExpressionTypingServices(@NotNull ExpressionTypingServices expressionTypingServices) {
@@ -172,14 +178,19 @@ public class CallResolver {

    @NotNull
    private <D extends CallableDescriptor, F extends D> OverloadResolutionResults<F> computeTasksAndResolveCall(
-            @NotNull BasicCallResolutionContext context,
-            @NotNull Name name,
-            @NotNull TracingStrategy tracing,
-            @NotNull CallableDescriptorCollectors<D> collectors,
-            @NotNull CallTransformer<D, F> callTransformer
+            @NotNull final BasicCallResolutionContext context,
+            @NotNull final Name name,
+            @NotNull final TracingStrategy tracing,
+            @NotNull final CallableDescriptorCollectors<D> collectors,
+            @NotNull final CallTransformer<D, F> callTransformer
    ) {
-        List<ResolutionTask<D, F>> tasks = taskPrioritizer.<D, F>computePrioritizedTasks(context, name, tracing, collectors);
-        return doResolveCallOrGetCachedResults(context, tasks, callTransformer, tracing);
+        return callResolvePerfCounter.time(new Function0<OverloadResolutionResults<F>>() {
+            @Override
+            public OverloadResolutionResults<F> invoke() {
+                List<ResolutionTask<D, F>> tasks = taskPrioritizer.<D, F>computePrioritizedTasks(context, name, tracing, collectors);
+                return doResolveCallOrGetCachedResults(context, tasks, callTransformer, tracing);
+            }
+        });
    }

    @NotNull
@@ -195,14 +206,19 @@ public class CallResolver {

    @NotNull
    private <D extends CallableDescriptor, F extends D> OverloadResolutionResults<F> computeTasksFromCandidatesAndResolvedCall(
-            @NotNull BasicCallResolutionContext context,
-            @NotNull Collection<ResolutionCandidate<D>> candidates,
-            @NotNull CallTransformer<D, F> callTransformer,
-            @NotNull TracingStrategy tracing
+            @NotNull final BasicCallResolutionContext context,
+            @NotNull final Collection<ResolutionCandidate<D>> candidates,
+            @NotNull final CallTransformer<D, F> callTransformer,
+            @NotNull final TracingStrategy tracing
    ) {
-        List<ResolutionTask<D, F>> prioritizedTasks =
-                taskPrioritizer.<D, F>computePrioritizedTasksFromCandidates(context, candidates, tracing);
-        return doResolveCallOrGetCachedResults(context, prioritizedTasks, callTransformer, tracing);
+        return callResolvePerfCounter.time(new Function0<OverloadResolutionResults<F>>() {
+            @Override
+            public OverloadResolutionResults<F> invoke() {
+                List<ResolutionTask<D, F>> prioritizedTasks =
+                        taskPrioritizer.<D, F>computePrioritizedTasksFromCandidates(context, candidates, tracing);
+                return doResolveCallOrGetCachedResults(context, prioritizedTasks, callTransformer, tracing);
+            }
+        });
    }

    @NotNull
@@ -388,19 +404,24 @@ public class CallResolver {
    }

    public OverloadResolutionResults<FunctionDescriptor> resolveCallWithKnownCandidate(
-            @NotNull Call call,
-            @NotNull TracingStrategy tracing,
-            @NotNull ResolutionContext<?> context,
-            @NotNull ResolutionCandidate<CallableDescriptor> candidate,
-            @Nullable MutableDataFlowInfoForArguments dataFlowInfoForArguments
+            @NotNull final Call call,
+            @NotNull final TracingStrategy tracing,
+            @NotNull final ResolutionContext<?> context,
+            @NotNull final ResolutionCandidate<CallableDescriptor> candidate,
+            @Nullable final MutableDataFlowInfoForArguments dataFlowInfoForArguments
    ) {
-        BasicCallResolutionContext basicCallResolutionContext =
-                BasicCallResolutionContext.create(context, call, CheckValueArgumentsMode.ENABLED, dataFlowInfoForArguments);
+        return callResolvePerfCounter.time(new Function0<OverloadResolutionResults<FunctionDescriptor>>() {
+            @Override
+            public OverloadResolutionResults<FunctionDescriptor> invoke() {
+                BasicCallResolutionContext basicCallResolutionContext =
+                        BasicCallResolutionContext.create(context, call, CheckValueArgumentsMode.ENABLED, dataFlowInfoForArguments);

-        List<ResolutionTask<CallableDescriptor, FunctionDescriptor>> tasks =
-                taskPrioritizer.<CallableDescriptor, FunctionDescriptor>computePrioritizedTasksFromCandidates(
-                        basicCallResolutionContext, Collections.singleton(candidate), tracing);
-        return doResolveCallOrGetCachedResults(basicCallResolutionContext, tasks, CallTransformer.FUNCTION_CALL_TRANSFORMER, tracing);
+                List<ResolutionTask<CallableDescriptor, FunctionDescriptor>> tasks =
+                        taskPrioritizer.<CallableDescriptor, FunctionDescriptor>computePrioritizedTasksFromCandidates(
+                                basicCallResolutionContext, Collections.singleton(candidate), tracing);
+                return doResolveCallOrGetCachedResults(basicCallResolutionContext, tasks, CallTransformer.FUNCTION_CALL_TRANSFORMER, tracing);
+            }
+        });
    }

    private <D extends CallableDescriptor, F extends D> OverloadResolutionResultsImpl<F> doResolveCallOrGetCachedResults(
@@ -547,31 +568,37 @@ public class CallResolver {

    @NotNull
    private <D extends CallableDescriptor, F extends D> OverloadResolutionResultsImpl<F> performResolution(
-            @NotNull ResolutionTask<D, F> task,
-            @NotNull CallTransformer<D, F> callTransformer
+            @NotNull final ResolutionTask<D, F> task,
+            @NotNull final CallTransformer<D, F> callTransformer
    ) {

-        for (ResolutionCandidate<D> resolutionCandidate : task.getCandidates()) {
-            TemporaryBindingTrace candidateTrace = TemporaryBindingTrace.create(
-                    task.trace, "trace to resolve candidate");
-            Collection<CallCandidateResolutionContext<D>> contexts = callTransformer.createCallContexts(resolutionCandidate, task, candidateTrace);
-            for (CallCandidateResolutionContext<D> context : contexts) {
+        for (final ResolutionCandidate<D> resolutionCandidate : task.getCandidates()) {
+            candidatePerfCounter.time(new Function0<Unit>() {
+                @Override
+                public Unit invoke() {
+                    TemporaryBindingTrace candidateTrace = TemporaryBindingTrace.create(
+                            task.trace, "trace to resolve candidate");
+                    Collection<CallCandidateResolutionContext<D>> contexts = callTransformer.createCallContexts(resolutionCandidate, task, candidateTrace);
+                    for (CallCandidateResolutionContext<D> context : contexts) {

-                candidateResolver.performResolutionForCandidateCall(context, task);
+                        candidateResolver.performResolutionForCandidateCall(context, task);

                /* important for 'variable as function case': temporary bind reference to descriptor (will be rewritten)
                to have a binding to variable while 'invoke' call resolve */
-                task.tracing.bindReference(context.candidateCall.getTrace(), context.candidateCall);
+                        task.tracing.bindReference(context.candidateCall.getTrace(), context.candidateCall);

-                Collection<MutableResolvedCall<F>> resolvedCalls = callTransformer.transformCall(context, this, task);
+                        Collection<MutableResolvedCall<F>> resolvedCalls = callTransformer.transformCall(context, CallResolver.this, task);

-                for (MutableResolvedCall<F> resolvedCall : resolvedCalls) {
-                    BindingTrace trace = resolvedCall.getTrace();
-                    task.tracing.bindReference(trace, resolvedCall);
-                    task.tracing.bindResolvedCall(trace, resolvedCall);
-                    task.addResolvedCall(resolvedCall);
+                        for (MutableResolvedCall<F> resolvedCall : resolvedCalls) {
+                            BindingTrace trace = resolvedCall.getTrace();
+                            task.tracing.bindReference(trace, resolvedCall);
+                            task.tracing.bindResolvedCall(trace, resolvedCall);
+                            task.addResolvedCall(resolvedCall);
+                        }
+                    }
+                    return Unit.INSTANCE$;
                }
-            }
+            });
        }

        OverloadResolutionResultsImpl<F> results = ResolutionResultsHandler.INSTANCE.computeResultAndReportErrors(
@@ -0,0 +1,89 @@
+/*
+ * 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.util
+
+import java.lang.management.ManagementFactory
+import java.util.concurrent.TimeUnit
+
+public class PerformanceCounter jvmOverloads constructor (val name: String, val reenterable: Boolean = false) {
+    companion object {
+        private val threadMxBean = ManagementFactory.getThreadMXBean()
+        private val allCounters = arrayListOf<PerformanceCounter>()
+
+        private val enteredCounters = ThreadLocal<MutableSet<PerformanceCounter>>()
+
+        init {
+            threadMxBean.setThreadCpuTimeEnabled(true)
+        }
+
+        private fun enterCounter(counter: PerformanceCounter): Boolean {
+            var enteredCountersInThread = enteredCounters.get()
+            if (enteredCountersInThread == null) {
+                enteredCountersInThread = hashSetOf(counter)
+                enteredCounters.set(enteredCountersInThread)
+                return true
+            }
+            return enteredCountersInThread.add(counter)
+        }
+
+        private fun leaveCounter(counter: PerformanceCounter) {
+            enteredCounters.get()?.remove(counter)
+        }
+
+        public fun currentThreadCpuTime(): Long = threadMxBean.getCurrentThreadUserTime()
+
+        public fun report(consumer: (String) -> Unit) {
+            allCounters.forEach { it.report(consumer) }
+        }
+    }
+
+    private var count: Int = 0
+    private var totalTimeNanos: Long = 0
+
+    init {
+        allCounters.add(this)
+    }
+
+    public fun increment() {
+        count++
+    }
+
+    public fun time<T>(block: () -> T): T {
+        count++
+        val needTime = !reenterable || enterCounter(this)
+        val startTime = currentThreadCpuTime()
+        try {
+            return block()
+        }
+        finally {
+            if (needTime) {
+                totalTimeNanos += currentThreadCpuTime() - startTime
+                if (reenterable) leaveCounter(this)
+            }
+        }
+    }
+
+    public fun report(consumer: (String) -> Unit) {
+        if (totalTimeNanos == 0L) {
+            consumer("$name performed $count times")
+        }
+        else {
+            val millis = TimeUnit.NANOSECONDS.toMillis(totalTimeNanos)
+            consumer("$name performed $count times, total time $millis ms")
+        }
+    }
+}
@@ -73,7 +73,11 @@ public class CliBaseTest {
                .replace("expected ABI version is " + Integer.toString(JvmAbi.VERSION), "expected ABI version is $ABI_VERSION$")
                .replace("\\", "/");

-        return normalizedOutputWithoutExitCode + exitCode;
+        return removePerfOutput(normalizedOutputWithoutExitCode) + exitCode;
+    }
+
+    public static String removePerfOutput(String output) {
+        return output.replaceAll("INFO: PERF:.+\n", "");
    }

    private void executeCompilerCompareOutput(@NotNull CLICompiler<?> compiler, @NotNull String testDataDir) throws Exception {
@@ -18,6 +18,7 @@ package org.jetbrains.kotlin.integration;

 import com.intellij.util.ArrayUtil;
 import org.jetbrains.annotations.NotNull;
+import org.jetbrains.kotlin.cli.CliBaseTest;

 import java.io.File;
 import java.util.ArrayList;
@@ -38,7 +39,8 @@ public abstract class AntTaskBaseTest extends KotlinIntegrationTestBase {

    @Override
    protected String normalizeOutput(String content) {
-        return super.normalizeOutput(content).replaceAll("Total time: .+\n", "Total time: [time]\n");
+        return CliBaseTest.removePerfOutput(super.normalizeOutput(content))
+                .replaceAll("Total time: .+\n", "Total time: [time]\n");
    }

    private int runAnt(String logName, String scriptName, String... extraArgs) throws Exception {