Merge pull request #1974 from justmara/fix/debug-optimization

small debug logging optimization

app/src/main/java/info/nightscout/androidaps/plugins/iob/iobCobCalculator/IobCobOref1Worker.kt

@@ -97,11 +97,11 @@ class IobCobOref1Worker(
             val bucketedData = ads.bucketedData
             val autosensDataTable = ads.autosensDataTable
             if (bucketedData == null || bucketedData.size < 3) {
-                aapsLogger.debug(LTag.AUTOSENS, "Aborting calculation thread (No bucketed data available): ${data.from}")
+                aapsLogger.debug(LTag.AUTOSENS,  {"Aborting calculation thread (No bucketed data available): ${data.from}"})
                 return Result.success(workDataOf("Error" to "Aborting calculation thread (No bucketed data available): ${data.from}"))
             }
             val prevDataTime = ads.roundUpTime(bucketedData[bucketedData.size - 3].timestamp)
-            aapsLogger.debug(LTag.AUTOSENS, "Prev data time: " + dateUtil.dateAndTimeString(prevDataTime))
+            aapsLogger.debug(LTag.AUTOSENS, {"Prev data time: " + dateUtil.dateAndTimeString(prevDataTime)})
             var previous = autosensDataTable[prevDataTime]
             // start from oldest to be able sub cob
             for (i in bucketedData.size - 4 downTo 0) {
@@ -156,15 +156,15 @@ class IobCobOref1Worker(
                     val hourAgoData = ads.getAutosensDataAtTime(hourAgo)
                     if (hourAgoData != null) {
                         val initialIndex = autosensDataTable.indexOfKey(hourAgoData.time)
-                        aapsLogger.debug(LTag.AUTOSENS, ">>>>> bucketed_data.size()=" + bucketedData.size + " i=" + i + " hourAgoData=" + hourAgoData.toString())
+                        aapsLogger.debug(LTag.AUTOSENS, { ">>>>> bucketed_data.size()=" + bucketedData.size + " i=" + i + " hourAgoData=" + hourAgoData.toString()})
                         var past = 1
                         try {
                             while (past < 12) {
                                 val ad = autosensDataTable.valueAt(initialIndex + past)
-                                aapsLogger.debug(LTag.AUTOSENS, ">>>>> past=" + past + " ad=" + ad?.toString())
+                                aapsLogger.debug(LTag.AUTOSENS, {">>>>> past=" + past + " ad=" + ad?.toString()})
                                 if (ad == null) {
-                                    aapsLogger.debug(LTag.AUTOSENS, autosensDataTable.toString())
-                                    aapsLogger.debug(LTag.AUTOSENS, bucketedData.toString())
+                                    aapsLogger.debug(LTag.AUTOSENS, {autosensDataTable.toString()})
+                                    aapsLogger.debug(LTag.AUTOSENS, {bucketedData.toString()})
                                     //aapsLogger.debug(LTag.AUTOSENS, iobCobCalculatorPlugin.getBgReadingsDataTable().toString())
                                     val notification = Notification(Notification.SEND_LOGFILES, rh.gs(R.string.sendlogfiles), Notification.LOW)
                                     rxBus.send(EventNewNotification(notification))
@@ -319,14 +319,12 @@ class IobCobOref1Worker(
                 if (bgTime < dateUtil.now()) autosensDataTable.put(bgTime, autosensData)
                 aapsLogger.debug(
                     LTag.AUTOSENS,
-                    "Running detectSensitivity from: " + dateUtil.dateAndTimeString(oldestTimeWithData) + " to: " + dateUtil.dateAndTimeString(bgTime) + " lastDataTime:" + ads.lastDataTime(
-                        dateUtil
-                    )
+                    {"Running detectSensitivity from: " + dateUtil.dateAndTimeString(oldestTimeWithData) + " to: " + dateUtil.dateAndTimeString(bgTime) + " lastDataTime:" + ads.lastDataTime(dateUtil)}
                 )
                 val sensitivity = activePlugin.activeSensitivity.detectSensitivity(ads, oldestTimeWithData, bgTime)
                 aapsLogger.debug(LTag.AUTOSENS, "Sensitivity result: $sensitivity")
                 autosensData.autosensResult = sensitivity
-                aapsLogger.debug(LTag.AUTOSENS, autosensData.toString())
+                aapsLogger.debug(LTag.AUTOSENS, {autosensData.toString()})
             }
             data.iobCobCalculator.ads = ads
             Thread {
@@ -335,7 +333,7 @@ class IobCobOref1Worker(
             }.start()
         } finally {
             rxBus.send(EventIobCalculationProgress(CalculationWorkflow.ProgressData.IOB_COB_OREF, 100, data.cause))
-            aapsLogger.debug(LTag.AUTOSENS, "AUTOSENSDATA thread ended: ${data.from}")
+            aapsLogger.debug(LTag.AUTOSENS, {"AUTOSENSDATA thread ended: ${data.from}"})
             profiler.log(LTag.AUTOSENS, "IobCobOref1Thread", start)
         }
         return Result.success()

core/src/main/java/info/nightscout/androidaps/plugins/iob/iobCobCalculator/AutosensDataStore.kt

@@ -57,7 +57,7 @@ class AutosensDataStore {
         synchronized(autosensDataTable) {
             for (index in autosensDataTable.size() - 1 downTo 0) {
                 if (autosensDataTable.keyAt(index) > time) {
-                    aapsLogger.debug(LTag.AUTOSENS, "Removing from autosensDataTable: " + dateUtil.dateAndTimeAndSecondsString(autosensDataTable.keyAt(index)))
+                    aapsLogger.debug(LTag.AUTOSENS, {"Removing from autosensDataTable: " + dateUtil.dateAndTimeAndSecondsString(autosensDataTable.keyAt(index))})
                     autosensDataTable.removeAt(index)
                 } else {
                     break
@@ -135,10 +135,10 @@ class AutosensDataStore {
                 return null
             }
             return if (data.time < System.currentTimeMillis() - 11 * 60 * 1000) {
-                aapsLogger.debug(LTag.AUTOSENS, "AUTOSENSDATA null: data is old (" + reason + ") size()=" + autosensDataTable.size() + " lastData=" + dateUtil.dateAndTimeAndSecondsString(data.time))
+                aapsLogger.debug(LTag.AUTOSENS, {"AUTOSENSDATA null: data is old (" + reason + ") size()=" + autosensDataTable.size() + " lastData=" + dateUtil.dateAndTimeAndSecondsString(data.time)})
                 null
             } else {
-                aapsLogger.debug(LTag.AUTOSENS, "AUTOSENSDATA ($reason) $data")
+                aapsLogger.debug(LTag.AUTOSENS, {"AUTOSENSDATA ($reason) $data"})
                 data
             }
         }
@@ -164,7 +164,7 @@ class AutosensDataStore {
                 .compatGetBgReadingsDataFromTime(start, to + T.mins(2).msecs(), false)
                 .blockingGet()
                 .filter { it.value >= 39 }
-            aapsLogger.debug(LTag.AUTOSENS, "BG data loaded. Size: " + bgReadings.size + " Start date: " + dateUtil.dateAndTimeString(start) + " End date: " + dateUtil.dateAndTimeString(to))
+            aapsLogger.debug(LTag.AUTOSENS, {"BG data loaded. Size: " + bgReadings.size + " Start date: " + dateUtil.dateAndTimeString(start) + " End date: " + dateUtil.dateAndTimeString(to)})
             createBucketedData(aapsLogger, dateUtil)
             rxBus.send(EventBucketedDataCreated())
         }
@@ -270,7 +270,7 @@ class AutosensDataStore {
         }
         val bData: MutableList<InMemoryGlucoseValue> = ArrayList()
         bData.add(InMemoryGlucoseValue(bgReadings[0]))
-        aapsLogger.debug(LTag.AUTOSENS, "Adding. bgTime: " + dateUtil.toISOString(bgReadings[0].timestamp) + " lastBgTime: " + "none-first-value" + " " + bgReadings[0].toString())
+        aapsLogger.debug(LTag.AUTOSENS, {"Adding. bgTime: " + dateUtil.toISOString(bgReadings[0].timestamp) + " lastBgTime: " + "none-first-value" + " " + bgReadings[0].toString()})
         var j = 0
         for (i in 1 until bgReadings.size) {
             val bgTime = bgReadings[i].timestamp
@@ -293,7 +293,7 @@ class AutosensDataStore {
                         val newBgReading = InMemoryGlucoseValue(nextBgTime, nextBg.roundToLong().toDouble(), true)
                         //console.error("Interpolated", bData[j]);
                         bData.add(newBgReading)
-                        aapsLogger.debug(LTag.AUTOSENS, "Adding. bgTime: " + dateUtil.toISOString(bgTime) + " lastBgTime: " + dateUtil.toISOString(lastBgTime) + " " + newBgReading.toString())
+                        aapsLogger.debug(LTag.AUTOSENS, {"Adding. bgTime: " + dateUtil.toISOString(bgTime) + " lastBgTime: " + dateUtil.toISOString(lastBgTime) + " " + newBgReading.toString()})
                         elapsedMinutes -= 5
                         lastBg = nextBg
                         lastBgTime = nextBgTime
@@ -301,14 +301,14 @@ class AutosensDataStore {
                     j++
                     val newBgReading = InMemoryGlucoseValue(bgTime, bgReadings[i].value)
                     bData.add(newBgReading)
-                    aapsLogger.debug(LTag.AUTOSENS, "Adding. bgTime: " + dateUtil.toISOString(bgTime) + " lastBgTime: " + dateUtil.toISOString(lastBgTime) + " " + newBgReading.toString())
+                    aapsLogger.debug(LTag.AUTOSENS, {"Adding. bgTime: " + dateUtil.toISOString(bgTime) + " lastBgTime: " + dateUtil.toISOString(lastBgTime) + " " + newBgReading.toString()})
                 }
 
                 abs(elapsedMinutes) > 2 -> {
                     j++
                     val newBgReading = InMemoryGlucoseValue(bgTime, bgReadings[i].value)
                     bData.add(newBgReading)
-                    aapsLogger.debug(LTag.AUTOSENS, "Adding. bgTime: " + dateUtil.toISOString(bgTime) + " lastBgTime: " + dateUtil.toISOString(lastBgTime) + " " + newBgReading.toString())
+                    aapsLogger.debug(LTag.AUTOSENS, {"Adding. bgTime: " + dateUtil.toISOString(bgTime) + " lastBgTime: " + dateUtil.toISOString(lastBgTime) + " " + newBgReading.toString()})
                 }
 
                 else                    -> {
@@ -327,7 +327,7 @@ class AutosensDataStore {
             val previous = bData[i + 1]
             val mSecDiff = current.timestamp - previous.timestamp
             val adjusted = (mSecDiff - T.mins(5).msecs()) / 1000
-            aapsLogger.debug(LTag.AUTOSENS, "Adjusting bucketed data time. Current: " + dateUtil.dateAndTimeAndSecondsString(current.timestamp) + " to: " + dateUtil.dateAndTimeAndSecondsString(previous.timestamp + T.mins(5).msecs()) + " by " + adjusted + " sec")
+            aapsLogger.debug(LTag.AUTOSENS, {"Adjusting bucketed data time. Current: " + dateUtil.dateAndTimeAndSecondsString(current.timestamp) + " to: " + dateUtil.dateAndTimeAndSecondsString(previous.timestamp + T.mins(5).msecs()) + " by " + adjusted + " sec"})
             if (abs(adjusted) > 90) {
                 // too big adjustment, fallback to non 5 min data
                 aapsLogger.debug(LTag.AUTOSENS, "Fallback to non 5 min data")

shared/src/main/java/info/nightscout/shared/logging/AAPSLogger.kt

@@ -9,6 +9,7 @@ interface AAPSLogger {
     fun debug(message: String)
     fun debug(enable: Boolean, tag: LTag, message: String)
     fun debug(tag: LTag, message: String)
+    fun debug(tag: LTag, accessor: () -> String)
     fun debug(tag: LTag, format: String, vararg arguments: Any?)
     fun warn(tag: LTag, message: String)
     fun warn(tag: LTag, format: String, vararg arguments: Any?)

shared/src/main/java/info/nightscout/shared/logging/AAPSLoggerProduction.kt

@@ -22,6 +22,11 @@ class AAPSLoggerProduction constructor(val l: L) : AAPSLogger {
             LoggerFactory.getLogger(tag.tag).debug(stackLogMarker() + message)
     }
 
+    override fun debug(tag: LTag, accessor: () -> String) {
+        if (l.findByName(tag.tag).enabled)
+            LoggerFactory.getLogger(tag.tag).debug(stackLogMarker() + accessor.invoke())
+    }
+
     override fun debug(tag: LTag, format: String, vararg arguments: Any?) {
         if (l.findByName(tag.tag).enabled)
             LoggerFactory.getLogger(tag.tag).debug(stackLogMarker() + format, arguments)

shared/src/main/java/info/nightscout/shared/logging/AAPSLoggerTest.kt

@@ -18,6 +18,10 @@ class AAPSLoggerTest : AAPSLogger {
         println("DEBUG: : " + tag.tag + " " + message)
     }
 
+    override fun debug(tag: LTag, accessor: () -> String) {
+        println("DEBUG: : " + tag.tag + " " + accessor.invoke())
+    }
+
     override fun debug(tag: LTag, format: String, vararg arguments: Any?) {
         println("DEBUG: : " + tag.tag + " " + String.format(format, arguments))
     }