[6.2.0][技术优化] 优化各线程cpu使用的锁相关逻辑

2023-11-23 20:03:05 +08:00
parent 806915e9aa
commit 6ad3b64bc0
5 changed files with 112 additions and 100 deletions
--- a/app/src/main/java/com/mogo/launcher/lancet/jank/spi/HookInvokerImpl.java
+++ b/app/src/main/java/com/mogo/launcher/lancet/jank/spi/HookInvokerImpl.java
@@ -12,8 +12,8 @@ import com.mogo.eagle.core.function.api.devatools.perf.IMoGoCpuUsageProvider;
 import com.mogo.eagle.core.function.call.devatools.CallerDevaToolsManager;
 import com.mogo.eagle.core.function.main.ARouterUtils;
 import com.zhjt.service.chain.ChainLog;
-import java.util.concurrent.atomic.AtomicLong;
 import java.util.concurrent.atomic.AtomicReference;
+import java.util.concurrent.locks.Lock;


@AutoService(IHookInvoker.class)
@@ -22,7 +22,6 @@ public class HookInvokerImpl implements IHookInvoker {
    private final Looper mainLooper = Looper.getMainLooper();

    private final ThreadLocal<Long> startTime = new ThreadLocal<>();
-    private final AtomicLong syncLockStartTime = new AtomicLong(0L);

    private final ThreadLocal<StringBuilder> message = new ThreadLocal<>();

@@ -30,16 +29,12 @@ public class HookInvokerImpl implements IHookInvoker {

    private final AtomicReference<Thread> holder = new AtomicReference<>();

-    private String holderDesc = null;
+    private final StringBuilder extra = new StringBuilder();

    private volatile IMoGoCpuUsageProvider provider;

    private volatile boolean getProviderRequested = false;

-    private final long logThreshold = 5; //日志打印阈值
-
-    private final long dumpStackThreshold = 20; // dump堆栈阈值
-
    private volatile boolean isCanDump = false; // 是否可以Dump堆栈，加此标记位是防止应用启动过程中，由于dump主线程堆栈导致启动耗时

    // 切记: 请勿在此方法中调用其它模块类中的api,可能会出现StackOverFlowException
@@ -47,7 +42,12 @@ public class HookInvokerImpl implements IHookInvoker {
    public void i(Type type, Object caller,String methodName, Object... objects) {
        startTime.set(SystemClock.elapsedRealtime());
        boolean isMainThread = mainLooper == Looper.myLooper();
-        handleSynchronizedLock(isMainThread, caller, methodName, objects);
+        if (type == Type.SYNCHRONIZED_LOCK) {
+            handleSynchronizedLock(isMainThread, caller, methodName, objects);
+        }
+        if (type == Type.AQS_LOCK) {
+            handleAqsLockEnterBefore(isMainThread, caller, methodName, objects);
+        }
        if (!getProviderRequested && provider == null && mainLooper != Looper.myLooper() && ARouterUtils.isInit.get()) {
            getProviderRequested = true;
            new Thread(() -> {
@@ -70,19 +70,22 @@ public class HookInvokerImpl implements IHookInvoker {

    // 切记: 请勿在此方法中调用其它模块类中的api,可能会出现StackOverFlowException
    @Override
-    public void o(Type type, Object caller,String methodName, Object... objects) {
+    public void o(Type type, Object caller,String methodName, Object... args) {
        long now = SystemClock.elapsedRealtime();
        Long old = startTime.get();
        long cost = now - (old == null ? now : old);
-        if (mainLooper == Looper.myLooper() && type != Type.SYNCHRONIZED_LOCK) {
-            handleCostTimeRecord(type, caller, methodName, cost, objects);
+        boolean isMainThread = mainLooper == Looper.myLooper();
+        if (isMainThread && type != Type.SYNCHRONIZED_LOCK) {
+            handleCostTimeRecord(type, null, caller, methodName, cost, args);
        }
-        if (mainLooper == Looper.myLooper() && type == Type.ACTIVITY) {
-            handleActivity((Activity) caller, methodName);
+        if (isMainThread && type == Type.ACTIVITY) {
+            handleActivity((Activity) caller, methodName, args);
+        }
+        if (type == Type.AQS_LOCK) {
+            handleAqsLockEnterAfter(isMainThread, caller, methodName, args);
        }
-
        if (provider != null) {
-            if (mainLooper == Looper.myLooper()) {
+            if (isMainThread) {
                provider.updateMainThreadTime();
            } else {
                provider.updateOtherThreadTime();
@@ -90,7 +93,32 @@ public class HookInvokerImpl implements IHookInvoker {
        }
    }

-    private void handleCostTimeRecord(Type type, Object caller, String methodName, long cost, Object... args) {
+    private void handleAqsLockEnterBefore(boolean isMainThread, Object caller, String methodName, Object[] objects) {
+        if (isMainThread && caller instanceof Lock) {
+            if ("lock".equals(methodName) || "lockInterruptibly".equals(methodName)) {
+                if (extra.length() > 0)  {
+                    extra.setLength(0);
+                }
+                extra.append(caller);
+            }
+        }
+    }
+
+    private void handleAqsLockEnterAfter(boolean isMainThread, Object caller, String methodName, Object[] objects) {
+        if (isMainThread && caller instanceof Lock) {
+            if ("lock".equals(methodName) || "lockInterruptibly".equals(methodName)) {
+                Long start = startTime.get();
+                if (start != null) {
+                    long dur = SystemClock.elapsedRealtime() - start;
+                    handleCostTimeRecord(Type.AQS_LOCK, extra,  caller, methodName, dur, objects);
+                }
+            }
+        }
+    }
+
+    private void handleCostTimeRecord(Type type, StringBuilder extra, Object caller, String methodName, long cost, Object... args) {
+        //日志打印阈值
+        long logThreshold = 5;
        if (cost >= logThreshold) {
            StringBuilder builder = message.get();
            if (builder == null) {
@@ -123,6 +151,13 @@ public class HookInvokerImpl implements IHookInvoker {
            }

            builder.append("#").append(cost);
+            if (extra != null && extra.length() > 0) {
+                builder.append("#");
+                builder.append(extra);
+                extra.setLength(0);
+            }
+            // dump堆栈阈值
+            long dumpStackThreshold = 20;
            if (cost >= dumpStackThreshold && isCanDump) {
                builder.append("\n");
                StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
@@ -131,13 +166,13 @@ public class HookInvokerImpl implements IHookInvoker {
                }
                builder.setLength(builder.length() - 1);
            }
-            Log.w("HookHandler", "Jank Detected:" + builder);
+            Log.w("HookHandler", "Junk Detected:" + builder);
            linkedLog(type, builder.toString());
        }
    }


-    private void handleActivity(Activity caller, String methodName) {
+    private void handleActivity(Activity caller, String methodName, Object... args) {
        if ("onCreate".equals(methodName)) {
            try {
                IMoGoBlockProvider block = CallerDevaToolsManager.INSTANCE.block();
@@ -157,8 +192,14 @@ public class HookInvokerImpl implements IHookInvoker {
            } catch (Throwable t) {
                t.printStackTrace();
            }
-            if (!isCanDump) {
-                isCanDump = true;
+        }
+
+        if ("onWindowFocusChanged".equals(methodName)) {
+            if (args.length > 0) {
+                boolean hasFocus = (boolean)args[0];
+                if (hasFocus && !isCanDump) {
+                    isCanDump = true;
+                }
            }
        }

@@ -188,70 +229,38 @@ public class HookInvokerImpl implements IHookInvoker {
    private void handleSynchronizedLock(boolean isMainThread,Object caller, String methodName, Object [] objects) {
        if (isMainThread) {
            if ("onMonitorBefore".equals(methodName)) {
-                syncLockStartTime.set(SystemClock.elapsedRealtime());
+                Object monitor = null;
                if (objects.length > 0) {
-                    this.monitor.set(objects[0]);
+                    this.monitor.set(monitor = objects[0]);
                }
                Thread holder = this.holder.get();
-                if (holder != null) {
-                    holderDesc = holder.toString();
+                StringBuilder sb = new StringBuilder();
+
+                if (monitor != null) {
+                    sb.append("monitor::").append(monitor.getClass().getName());
                }
+                if (holder != null) {
+                    if (sb.length() > 0) {
+                        sb.append("##holder::").append(holder);
+                    } else {
+                        sb.append("holder::").append(holder);
+                    }
+                }
+                if (extra.length() > 0) {
+                    extra.setLength(0);
+                }
+                extra.append(sb);
            }
            if ("onMonitorEnter".equals(methodName)) {
-                long elapsedTime = SystemClock.elapsedRealtime() - syncLockStartTime.get();
-                if (elapsedTime >= logThreshold) {
-                    StringBuilder builder = message.get();
-                    if (builder == null) {
-                        builder = new StringBuilder();
-                        message.set(builder);
-                    }
-                    if (builder.length() > 0) {
-                        builder.setLength(0);
-                    }
-                    builder
-                            .append(Type.SYNCHRONIZED_LOCK)
-                            .append("#")
-                            .append(caller == null ? "caller is null" : caller.getClass().getSimpleName())
-                            .append("#")
-                            .append(methodName);
-                    if (objects.length > 0) {
-                        builder.append("#(");
-                    }
-                    for (Object o : objects) {
-                        if (o == null) {
-                            continue;
-                        }
-                        builder.append(o.getClass().getSimpleName())
-                                .append(",");
-                    }
-
-                    if (objects.length > 0) {
-                        builder.setLength(builder.length() - 1);
-                        builder.append(")");
-                    }
-                    builder.append("#").append(elapsedTime);
-                    Object monitor = this.monitor.get();
-                    if (monitor != null) {
-                        builder.append("#").append("monitor->").append(monitor.getClass().getName()).append("@").append(monitor.hashCode());
-                    }
-                    if (holderDesc != null) {
-                        builder.append("#").append("holder->").append(holderDesc);
-                    }
-                    if (elapsedTime >= dumpStackThreshold && isCanDump) {
-                        builder.append("\n");
-                        StackTraceElement[] stackTrace = Thread.currentThread().getStackTrace();
-                        for (StackTraceElement trace: stackTrace) {
-                            builder.append(trace.getClassName()).append("#").append(trace.getMethodName()).append("#").append(trace.getLineNumber()).append("\n");
-                        }
-                        builder.setLength(builder.length() - 1);
-                    }
-                    Log.w("HookHandler", "Jank detected:" + builder);
-                    linkedLog(Type.SYNCHRONIZED_LOCK, builder.toString());
+                Long startTime = this.startTime.get();
+                if (startTime == null) {
+                    return;
                }
+                long cost = SystemClock.elapsedRealtime() - startTime;
+                handleCostTimeRecord(Type.SYNCHRONIZED_LOCK, extra, caller, methodName, cost, objects);
            }
            if ("onMonitorExit".equals(methodName)) {
                this.monitor.remove();
-                holderDesc = null;
            }
        } else {
            if ("onMonitorBefore".equals(methodName)) {
--- a/config.gradle
+++ b/config.gradle
@@ -228,7 +228,7 @@ ext {
            passport_secret              : "com.zhidaoauto:sdk-java:1.0.5-SNAPSHOT",

            // 主线程卡顿监测
-            block_detector               : "com.mogo.eagle.core.block:runtime:10.80.0",
+            block_detector               : "com.mogo.eagle.core.block:runtime:10.90.0",

            //======================== google auto-service ===============
            google_auto_service          : "com.google.auto.service:auto-service:1.0-rc7",
--- a/core/function-impl/mogo-core-function-devatools/src/main/java/com/zhjt/mogo_core_function_devatools/block/MainBlockLinkedLog.kt
+++ b/core/function-impl/mogo-core-function-devatools/src/main/java/com/zhjt/mogo_core_function_devatools/block/MainBlockLinkedLog.kt
@@ -5,32 +5,19 @@ import com.zhjt.service.chain.*

 internal class MainBlockLinkedLog {

-    fun record(extra: Map<String, List<String>>) {
+    fun record(json: String) {
        try {
-            recordInternal(extra)
+            recordInternal(json)
        } catch (t: Throwable) {
            t.printStackTrace()
        }
    }

-    fun recordCpuUsage(extra: Map<String, String>) {
-        recordCpuInternal(extra)
-    }
-
    @ChainLog(
        linkChainLog = ChainConstant.CHAIN_TYPE_ANR_LEAK,
        linkCode = ChainConstant.CHAIN_SOURCE_HMI,
        nodeAliasCode = ChainConstant.CHAIN_CODE_MAIN_BLOCK,
        paramIndexes = [0]
    )
-    private fun recordInternal(extra: Map<String, List<String>>) {}
-
-
-    @ChainLog(
-        linkChainLog = ChainConstant.CHAIN_TYPE_ANR_LEAK,
-        linkCode = ChainConstant.CHAIN_SOURCE_HMI,
-        nodeAliasCode = ChainConstant.CHAIN_CODE_MAIN_BLOCK,
-        paramIndexes = [0]
-    )
-    private fun recordCpuInternal(extra: Map<String, String>) {}
+    private fun recordInternal(json: String) {}
 }
--- a/core/function-impl/mogo-core-function-devatools/src/main/java/com/zhjt/mogo_core_function_devatools/block/MoGoBlockProviderImpl.kt
+++ b/core/function-impl/mogo-core-function-devatools/src/main/java/com/zhjt/mogo_core_function_devatools/block/MoGoBlockProviderImpl.kt
@@ -12,6 +12,7 @@ import com.mogo.eagle.core.block.runtime.listener.*
 import com.mogo.eagle.core.block.runtime.report.*
 import com.mogo.eagle.core.function.api.devatools.block.*
 import com.mogo.eagle.core.function.call.devatools.CallerDevaToolsManager
+import com.mogo.eagle.core.utilcode.util.GsonUtils
 import java.util.concurrent.TimeUnit.SECONDS

 internal class MoGoBlockProviderImpl: IMoGoBlockProvider, IBlockListener {
@@ -55,15 +56,15 @@ internal class MoGoBlockProviderImpl: IMoGoBlockProvider, IBlockListener {
                    val mainThreadUsage = cpu.remove("MainThreadUsage")
                    val processUsage = cpu.remove("ProcessUsage")
                    if (mainThreadUsage != null && processUsage != null) {
-                        linkedLog.recordCpuUsage(LinkedHashMap<String, String>().also { itx ->
-                            itx["MainThread"] = "${ "%.2f".format(mainThreadUsage * 1.0f * 100 / processUsage) }% ($mainThreadUsage, $processUsage)"
-                            cpu.entries.sortedByDescending { it.value }.forEach { sorted ->
-                                itx[sorted.key] = "${ "%.2f".format(sorted.value * 1.0f * 100 / processUsage) }% (${sorted.value}, $processUsage)"
+                        map["cpu"] = ArrayList<String>().also {
+                            it.add("MainThread: ${ "%.2f".format(mainThreadUsage * 1.0f * 100 / processUsage) }% ($mainThreadUsage, $processUsage)")
+                            cpu.entries.sortedByDescending { e ->
+                                it.add("${e.key}: ${ "%.2f".format(e.value * 1.0f * 100 / processUsage) }% (${e.value}, $processUsage)")
                            }
-                        })
+                        }
                    }
                }
-                linkedLog.record(map)
+                linkedLog.record(GsonUtils.toJson(map))
            }
        })
    }
--- a/core/function-impl/mogo-core-function-devatools/src/main/java/com/zhjt/mogo_core_function_devatools/perf/MoGoCpuUsageProviderImpl.kt
+++ b/core/function-impl/mogo-core-function-devatools/src/main/java/com/zhjt/mogo_core_function_devatools/perf/MoGoCpuUsageProviderImpl.kt
@@ -50,13 +50,20 @@ internal class MoGoCpuUsageProviderImpl: IMoGoCpuUsageProvider {
    override fun updateOtherThreadTime() {
        val last = otherThreadLaunchedTime.get()
        val now = Debug.threadCpuTimeNanos()
+        var flag = true
        try {
            if (last == null) {
+                flag = false
                otherThreadLaunchedTime.set(now)
                return
            }
            val duration = now - last
-            if (duration <= 10000) {
+            if (duration < 1_000_000) {
+                //每1毫秒更新线程时间
+                flag = false
+                return
+            }
+            if (lock.isLocked) {
                return
            }
            var builder = builder.get()
@@ -68,16 +75,24 @@ internal class MoGoCpuUsageProviderImpl: IMoGoCpuUsageProvider {
                builder.setLength(0)
            }
            builder.append(Thread.currentThread().name)
-            lock.withLock {
+            val isGetLock = lock.tryLock()
+            if (!isGetLock) {
+                return
+            }
+            try {
                while (map.size >= maxSize) {
                    val toEvict = map.entries.iterator().next()
                    map.remove(toEvict.key)
                }
                val key = builder.toString()
                map[key] = map.getOrPut(key) { 0L } + duration
+            } finally {
+                lock.unlock()
            }
        } finally {
-            otherThreadLaunchedTime.set(now)
+            if (flag) {
+                otherThreadLaunchedTime.set(now)
+            }
        }
    }