From 1a313a9f7834ce30157058105fec1609faf10c4a Mon Sep 17 00:00:00 2001 From: Vitor Pamplona Date: Tue, 16 Jul 2024 09:42:17 -0400 Subject: [PATCH] Adds performance monitors for framedrops in benchmark mode --- .../com/vitorpamplona/amethyst/Amethyst.kt | 5 +- .../com/vitorpamplona/amethyst/LogMonitor.kt | 192 ++++++++++++++++++ 2 files changed, 196 insertions(+), 1 deletion(-) create mode 100644 amethyst/src/main/java/com/vitorpamplona/amethyst/LogMonitor.kt diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt index 152bfb9a1..370b651ed 100644 --- a/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/Amethyst.kt @@ -22,6 +22,7 @@ package com.vitorpamplona.amethyst import android.app.Application import android.content.Context +import android.os.Looper import android.os.StrictMode import android.os.StrictMode.ThreadPolicy import android.os.StrictMode.VmPolicy @@ -76,7 +77,7 @@ class Amethyst : Application() { OtsEvent.otsInstance = OpenTimestamps(OkHttpBlockstreamExplorer(), OkHttpCalendarBuilder()) - if (BuildConfig.DEBUG) { + if (BuildConfig.DEBUG || BuildConfig.BUILD_TYPE == "benchmark") { StrictMode.setThreadPolicy( ThreadPolicy .Builder() @@ -91,6 +92,8 @@ class Amethyst : Application() { .penaltyLog() .build(), ) + Looper.getMainLooper().setMessageLogging(LogMonitor()) + ChoreographerHelper.start() } GlobalScope.launch(Dispatchers.IO) { diff --git a/amethyst/src/main/java/com/vitorpamplona/amethyst/LogMonitor.kt b/amethyst/src/main/java/com/vitorpamplona/amethyst/LogMonitor.kt new file mode 100644 index 000000000..c15269b5a --- /dev/null +++ b/amethyst/src/main/java/com/vitorpamplona/amethyst/LogMonitor.kt @@ -0,0 +1,192 @@ +/** + * Copyright (c) 2024 Vitor Pamplona + * + * Permission is hereby granted, free of charge, to any person obtaining a copy of + * this software and associated documentation files (the "Software"), to deal in + * the Software without restriction, including without limitation the rights to use, + * copy, modify, merge, publish, distribute, sublicense, and/or sell copies of the + * Software, and to permit persons to whom the Software is furnished to do so, + * subject to the following conditions: + * + * The above copyright notice and this permission notice shall be included in all + * copies or substantial portions of the Software. + * + * THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF ANY KIND, EXPRESS OR + * IMPLIED, INCLUDING BUT NOT LIMITED TO THE WARRANTIES OF MERCHANTABILITY, FITNESS + * FOR A PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT SHALL THE AUTHORS OR + * COPYRIGHT HOLDERS BE LIABLE FOR ANY CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN + * AN ACTION OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR IN CONNECTION + * WITH THE SOFTWARE OR THE USE OR OTHER DEALINGS IN THE SOFTWARE. + */ +package com.vitorpamplona.amethyst + +import android.os.Handler +import android.os.HandlerThread +import android.os.Looper +import android.util.Log +import android.util.Printer +import android.view.Choreographer +import java.text.SimpleDateFormat +import java.util.concurrent.atomic.AtomicBoolean + +class LogMonitor : Printer { + private val mStackSampler: StackSampler + private var mPrintingStarted = false + private var mStartTimestamp: Long = 0 + + // threshold + private val mBlockThresholdMillis: Long = 16 + + // Sampling frequency + private val mSampleInterval: Long = 1000 + + private val mLogHandler: Handler + + init { + mStackSampler = StackSampler(mSampleInterval) + val handlerThread = HandlerThread("block-canary-io") + handlerThread.start() + mLogHandler = Handler(handlerThread.getLooper()) + } + + override fun println(x: String) { + // From if to Else, execute DispatchMessage. If the execution takes more than the threshold, the output stuck information + if (!mPrintingStarted) { + // Record start time + mStartTimestamp = System.currentTimeMillis() + mPrintingStarted = true + mStackSampler.startDump() + } else { + val endTime = System.currentTimeMillis() + mPrintingStarted = false + // + if (isBlock(endTime)) { + notifyBlockEvent(endTime) + } + mStackSampler.stopDump() + } + } + + private fun notifyBlockEvent(endTime: Long) { + mLogHandler.post { + // Obtain the stack of the main thread stack + val stacks: List = mStackSampler.getStacks(mStartTimestamp, endTime) + for (stack in stacks) { + Log.e("block-canary", stack) + } + } + } + + private fun isBlock(endTime: Long): Boolean = endTime - mStartTimestamp > mBlockThresholdMillis +} + +class StackSampler( + private val mSampleInterval: Long, +) { + private val mHandler: Handler + private val mStackMap: MutableMap = LinkedHashMap() + private val mMaxCount = 100 + + // Whether to sample + var mShouldSample: AtomicBoolean = AtomicBoolean(false) + + /** + * Start sampling and execute stack + */ + fun startDump() { + // Avoid repeating start + if (mShouldSample.get()) { + return + } + mShouldSample.set(true) + mHandler.removeCallbacks(mRunnable) + mHandler.postDelayed(mRunnable, mSampleInterval) + } + + fun stopDump() { + if (!mShouldSample.get()) { + return + } + mShouldSample.set(false) + mHandler.removeCallbacks(mRunnable) + } + + fun getStacks( + startTime: Long, + endTime: Long, + ): List { + val result = mutableListOf() + synchronized(mStackMap) { + for (entryTime in mStackMap.keys) { + if (startTime < entryTime && entryTime < endTime) { + result.add( + TIME_FORMATTER.format(entryTime) + + SEPARATOR + + SEPARATOR + + mStackMap[entryTime], + ) + } + } + } + return result + } + + init { + val handlerThread = HandlerThread("block-canary-sampler") + handlerThread.start() + mHandler = Handler(handlerThread.looper) + } + + private val mRunnable: Runnable = + object : Runnable { + override fun run() { + val sb = StringBuilder() + val stackTrace = Looper.getMainLooper().thread.stackTrace + for (s in stackTrace) { + sb.append(s.toString()).append("\n") + } + synchronized(mStackMap) { + // Save up to 100 stack information + if (mStackMap.size == mMaxCount) { + mStackMap.remove(mStackMap.keys.iterator().next()) + } + mStackMap.put(System.currentTimeMillis(), sb.toString()) + } + if (mShouldSample.get()) { + mHandler.postDelayed(this, mSampleInterval) + } + } + } + + companion object { + const val SEPARATOR: String = "\r\n" + val TIME_FORMATTER: SimpleDateFormat = SimpleDateFormat("MM-dd HH:mm:ss.SSS") + } +} + +object ChoreographerHelper { + var lastFrameTimeNanos: Long = 0 + + fun start() { + Choreographer.getInstance().postFrameCallback( + object : Choreographer.FrameCallback { + override fun doFrame(frameTimeNanos: Long) { + // Last callback time + if (lastFrameTimeNanos == 0L) { + lastFrameTimeNanos = frameTimeNanos + Choreographer.getInstance().postFrameCallback(this) + return + } + val diff = (frameTimeNanos - lastFrameTimeNanos) / 1000000 + if (diff > 16.6f) { + // Follow the frame number + val droppedCount = (diff / 16.6).toInt() + Log.w("block-canary", "Dropped Frames $droppedCount") + } + lastFrameTimeNanos = frameTimeNanos + Choreographer.getInstance().postFrameCallback(this) + } + }, + ) + } +}