fix(logger): logger kills the perf (APP-137)

src/main/kotlin/app/Logger.kt

@@ -28,32 +28,38 @@ object Logger {
     /**
      * Current log level. All that higher than this level will not be displayed.
      */
-    private const val LEVEL = BuildConfig.LOG_LEVEL
+    @kotlin.PublishedApi
+    internal const val LEVEL = BuildConfig.LOG_LEVEL
 
     /**
      * Error level.
      */
-    private const val ERROR = 0
+    @kotlin.PublishedApi
+    internal const val ERROR = 0
 
     /**
      * Warning level.
      */
-    private const val WARN = 1
+    @kotlin.PublishedApi
+    internal const val WARN = 1
 
     /**
      * Information level.
      */
-    private const val INFO = 2
+    @kotlin.PublishedApi
+    internal const val INFO = 2
 
     /**
      * Debug level.
      */
-    private const val DEBUG = 3
+    @kotlin.PublishedApi
+    internal const val DEBUG = 3
 
     /**
      * Trace level. For extremely detailed and high volume debug logs.
      */
-    private const val TRACE = 4
+    @kotlin.PublishedApi
+    internal const val TRACE = 4
 
     /**
      * Print stack trace on error log.
@@ -112,45 +118,51 @@ object Logger {
     /**
      * Log warning message. Don't log private information with this method.
      */
-    fun warn(message: String) {
+    inline fun warn(message: () -> String) {
+        val msg = message()
         if (LEVEL >= WARN) {
-            println("[w] $message.")
+            println("[w] $msg.")
         }
-        addBreadcrumb(message, Breadcrumb.Level.WARNING)
+        addBreadcrumb(msg, Breadcrumb.Level.WARNING)
     }
 
     /**
      * Log information message. Don't log private information with this method.
      */
-    fun info(message: String, event: String = "") {
+    inline fun info(event: String = "", message: () -> String) {
+        val msg = message()
         if (LEVEL >= INFO) {
-            println("[i] $message.")
+            println("[i] $msg.")
         }
         if (event.isNotBlank()) {
             Analytics.trackEvent(event)
         }
-        addBreadcrumb(message, Breadcrumb.Level.INFO)
+        addBreadcrumb(msg, Breadcrumb.Level.INFO)
     }
 
     /**
      * Log debug message.
      */
-    fun debug(message: String) {
+    inline fun debug(message: () -> String) {
         if (LEVEL >= DEBUG) {
-            println("[d] $message.")
+            println("[d] ${message()}.")
         }
     }
 
     /**
      * Log trace message.
      */
-    fun trace(message: String) {
+    inline fun trace(message: () -> String) {
         if (LEVEL >= TRACE) {
-            println("[t] $message.")
+            println("[t] ${message()}.")
         }
     }
 
-    private fun addBreadcrumb(message: String, level: Breadcrumb.Level) {
+    val isDebug: Boolean
+        inline get() = LEVEL >= DEBUG
+
+    @kotlin.PublishedApi
+    internal fun addBreadcrumb(message: String, level: Breadcrumb.Level) {
         sentryContext.recordBreadcrumb(BreadcrumbBuilder()
             .setMessage(message)
             .setLevel(level)

src/main/kotlin/app/Main.kt

@@ -31,7 +31,7 @@ class Main(argv: Array<String>) {
 
     init {
         Logger.uuid = configurator.getUuidPersistent()
-        Logger.info("App started", Logger.Events.START)
+        Logger.info(Logger.Events.START) { "App started" }
 
         val options = Options()
         val commandAdd = CommandAdd()
@@ -64,10 +64,10 @@ class Main(argv: Array<String>) {
                 else -> startUi()
             }
         } catch (e: MissingCommandException) {
-            Logger.warn("No such command: ${e.unknownCommand}")
+            Logger.warn { "No such command: ${e.unknownCommand}" }
         }
 
-        Logger.info("App finished", Logger.Events.EXIT)
+        Logger.info(Logger.Events.EXIT) { "App finished" }
     }
 
     private fun startUi() {
@@ -83,17 +83,17 @@ class Main(argv: Array<String>) {
             configurator.saveToFile()
             println("Added git repository at $path.")
 
-            Logger.info("Config changed", Logger.Events.CONFIG_CHANGED)
+            Logger.info(Logger.Events.CONFIG_CHANGED) { "Config changed" }
         } else {
-            Logger.warn("No valid git repository found at specified path")
+            Logger.warn { "No valid git repository found at specified path" }
         }
     }
 
     private fun doConfig(commandOptions: CommandConfig) {
         val (key, value) = commandOptions.pair
 
         if (!arrayListOf("username", "password").contains(key)) {
-            Logger.warn("No such key $key")
+            Logger.warn { "No such key $key" }
             return
         }
 
@@ -104,7 +104,7 @@ class Main(argv: Array<String>) {
 
         configurator.saveToFile()
 
-        Logger.info("Config changed", Logger.Events.CONFIG_CHANGED)
+        Logger.info(Logger.Events.CONFIG_CHANGED) { "Config changed" }
     }
 
     private fun doList() {
@@ -121,7 +121,7 @@ class Main(argv: Array<String>) {
             configurator.saveToFile()
             println("Repository removed from tracking list.")
 
-            Logger.info("Config changed", Logger.Events.CONFIG_CHANGED)
+            Logger.info(Logger.Events.CONFIG_CHANGED) { "Config changed" }
         } else {
             println("Repository not found in tracking list.")
         }

src/main/kotlin/app/api/MockApi.kt

@@ -22,38 +22,39 @@ class MockApi(  // GET requests.
     var receivedDeletedCommits: MutableList<Commit> = mutableListOf()
 
     override fun authorize() {
-        Logger.debug("MockApi: authorize request")
+        Logger.debug { "MockApi: authorize request" }
     }
 
     override fun getUser(): User {
-        Logger.debug("MockApi: getUser request")
+        Logger.debug { "MockApi: getUser request" }
         return mockUser
     }
 
     override fun getRepo(repoRehash: String): Repo {
-        Logger.debug("MockApi: getRepo request")
+        Logger.debug { "MockApi: getRepo request" }
         return mockRepo
     }
 
     override fun postRepo(repo: Repo) {
-        Logger.debug("MockApi: postRepo request ($repo)")
+        Logger.debug { "MockApi: postRepo request ($repo)" }
         receivedRepos.add(repo)
     }
 
     override fun postCommits(commitsList: List<Commit>) {
-        Logger.debug("MockApi: postCommits request "
-            + "(${commitsList.size} commits)")
+        Logger.debug {
+            "MockApi: postCommits request (${commitsList.size} commits)"
+        }
         receivedAddedCommits.addAll(commitsList)
     }
 
     override fun deleteCommits(commitsList: List<Commit>) {
-        Logger.debug("MockApi: deleteCommits request "
-            + "(${commitsList.size} commits)")
+        Logger.debug {
+            "MockApi: deleteCommits request (${commitsList.size} commits)" }
         receivedDeletedCommits.addAll(commitsList)
     }
 
     override fun postFacts(factsList: List<Fact>) {
-        Logger.debug("MockApi: postStats request (${factsList.size} stats)")
+        Logger.debug { "MockApi: postStats request (${factsList.size} stats)" }
         receivedFacts.addAll(factsList)
     }
 }

src/main/kotlin/app/api/ServerApi.kt

@@ -111,11 +111,11 @@ class ServerApi (private val configurator: Configurator) : Api {
                                 requestName: String,
                                 parser: (ByteArray) -> T): T {
         try {
-            Logger.debug("Request $requestName initialized")
+            Logger.debug { "Request $requestName initialized" }
             val (_, res, result) = request.responseString()
             val (_, e) = result
             if (e == null) {
-                Logger.debug("Request $requestName success")
+                Logger.debug { "Request $requestName success" }
                 return parser(res.data)
             } else {
                 throw RequestException(e)

src/main/kotlin/app/config/FileConfigurator.kt

@@ -232,7 +232,7 @@ class FileConfigurator : Configurator {
             }
         } catch (e: IOException) {
             if (e is NoSuchFileException){
-                Logger.warn("No config file found")
+                Logger.warn { "No config file found" }
             } else {
                 Logger.error(e, "Cannot access config file")
             }

src/main/kotlin/app/extractors/ExtractorInterface.kt

@@ -107,12 +107,12 @@ interface ExtractorInterface {
             val pklPath = "$pklDir/$name.pkl.z"
 
             if (Files.notExists(Paths.get(pklPath))) {
-                Logger.info("Downloading $name.pkl.z")
+                Logger.info { "Downloading $name.pkl.z" }
                 downloadModel(name, pklDir)
-                Logger.info("Downloaded $name.pkl.z")
+                Logger.info { "Downloaded $name.pkl.z" }
             }
 
-            Logger.info("Loading $name evaluator")
+            Logger.info { "Loading $name evaluator" }
 
             if (Files.notExists(Paths.get(pmmlDir))) {
                 Files.createDirectories(Paths.get(pmmlDir))
@@ -141,15 +141,15 @@ interface ExtractorInterface {
                 }
             }
             else {
-                Logger.warn("No $name evaluator cache found, building now")
+                Logger.warn { "No $name evaluator cache found, building now" }
                 unpickleModel(getPickleInputStream(pklPath))
             }
 
             val evaluator = ModelEvaluatorFactory.newInstance()
                                                  .newModelEvaluator(pmml)
             evaluatorsCache.put(name, evaluator)
 
-            Logger.info("$name evaluator ready")
+            Logger.info { "$name evaluator ready" }
 
             return evaluator
         }

src/main/kotlin/app/hashers/CodeLongevity.kt

@@ -195,8 +195,9 @@ class CodeLongevity(private val serverRepo: Repo,
                        code = FactCodes.LINE_LONGEVITY_REPO,
                        value = repoAvg.toString()))
         val repoAvgDays = repoAvg / secondsInDay
-        Logger.info("Repo average code line age is $repoAvgDays days, "
-              + "lines total: $repoTotal")
+        Logger.info {
+            "Repo average code line age is $repoAvgDays days, lines total: $repoTotal"
+        }
 
         for (email in emails) {
             val aggrAge = aggrAges[email] ?: CodeLineAges.AggrAge()
@@ -210,7 +211,7 @@ class CodeLongevity(private val serverRepo: Repo,
 
         if (stats.size > 0) {
             api.postFacts(stats)
-            Logger.info("Sent ${stats.size} facts to server")
+            Logger.info { "Sent ${stats.size} facts to server" }
         }
     }
 
@@ -226,7 +227,7 @@ class CodeLongevity(private val serverRepo: Repo,
         try {
             val iStream = ObjectInputStream(FileInputStream(storagePath))
             val storedHeadId = iStream.readUTF()
-            Logger.debug("Stored repo head: $storedHeadId")
+            Logger.debug { "Stored repo head: $storedHeadId" }
             storedHead = RevWalk(repo).parseCommit(repo.resolve(storedHeadId))
             if (storedHead == head) {
                 return null
@@ -243,7 +244,7 @@ class CodeLongevity(private val serverRepo: Repo,
 
         // Update ages.
         getLinesObservable(storedHead).blockingSubscribe { line ->
-            Logger.trace("Scanning: ${line}")
+            Logger.trace { "Scanning: ${line}" }
             if (line.to.isDeleted) {
                 var age = line.age
                 if (ageData.lastingLines.contains(line.oldId)) {
@@ -337,7 +338,7 @@ class CodeLongevity(private val serverRepo: Repo,
                 val oldId = diff.getOldId().toObjectId()
                 val newPath = diff.getNewPath()
                 val newId = diff.getNewId().toObjectId()
-                Logger.trace("old: '$oldPath', new: '$newPath'")
+                Logger.trace { "old: '$oldPath', new: '$newPath'" }
 
                 // Skip binary files.
                 val fileId = if (newPath != DiffEntry.DEV_NULL) newId else oldId
@@ -375,14 +376,14 @@ class CodeLongevity(private val serverRepo: Repo,
                     if (insCount > 0) {
                         val insStart = edit.getBeginB()
                         val insEnd = edit.getEndB()
-                        Logger.trace("ins ($insStart, $insEnd)")
+                        Logger.trace { "ins ($insStart, $insEnd)" }
 
                         for (idx in insStart .. insEnd - 1) {
                             val from = RevCommitLine(commit, newId,
                                                      newPath, idx, false)
                             val to = lines.get(idx)
                             val cl = CodeLine(repo, from, to)
-                            Logger.trace("Collected: ${cl}")
+                            Logger.trace { "Collected: ${cl}" }
                             subscriber.onNext(cl)
                         }
                         lines.subList(insStart, insEnd).clear()
@@ -397,7 +398,7 @@ class CodeLongevity(private val serverRepo: Repo,
                     if (delCount > 0) {
                         val delStart = edit.getBeginA()
                         val delEnd = edit.getEndA()
-                        Logger.trace("del ($delStart, $delEnd)")
+                        Logger.trace { "del ($delStart, $delEnd)" }
 
                         val tmpLines = ArrayList<RevCommitLine>(delCount)
                         for (idx in delStart .. delEnd - 1) {
@@ -433,7 +434,7 @@ class CodeLongevity(private val serverRepo: Repo,
                         val from = RevCommitLine(tail, fileId,
                                                  filePath, idx, false)
                         val cl = CodeLine(repo, from, lines[idx])
-                        Logger.trace("Collected (tail): $cl")
+                        Logger.trace { "Collected (tail): $cl" }
                         subscriber.onNext(cl)
                     }
                 }
@@ -457,14 +458,23 @@ class CodeLongevity(private val serverRepo: Repo,
         while (commit != null && commit != tail) {
             val parentCommit: RevCommit? = revWalk.next()
 
-            Logger.debug("commit: ${commit.getName()}; " +
-                "'${commit.getShortMessage()}'")
-            if (parentCommit != null) {
-                Logger.debug("parent commit: ${parentCommit.getName()}; "
-                    + "'${parentCommit.getShortMessage()}'")
-            }
-            else {
-                Logger.debug("parent commit: null")
+            // Smart casts are not yet supported for a mutable variable captured
+            // in an inline lambda, see
+            // https://youtrack.jetbrains.com/issue/KT-7186.
+            if (Logger.isDebug) {
+                val commitName = commit.getName()
+                val commitMsg = commit.getShortMessage()
+                Logger.debug { "commit: $commitName; '$commitMsg'" }
+                if (parentCommit != null) {
+                    val parentCommitName = parentCommit.getName()
+                    val parentCommitMsg = parentCommit.getShortMessage()
+                    Logger.debug {
+                        "parent commit: ${parentCommitName}; '${parentCommitMsg}'"
+                    }
+                }
+                else {
+                    Logger.debug { "parent commit: null" }
+                }
             }
 
             subscriber.onNext(Pair(commit, df.scan(parentCommit, commit)))