Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 6507ee14 authored by Makoto Onuki's avatar Makoto Onuki
Browse files

Fix method call tree log 

When method call log is enabled, we print "method call tree" in the log.
This feature has baked-in filtering to avoid unnecessary verbosity.
For example, we don't want to log every single "Log.i" calls or
"ArrayMap" class use.

We also filter out nested calls from such ignored methods, because
otherwise some of the "loggable" APIs are used by ignored APIs
and it'd also be too verbose.

Previously, this nest call check was done by keeping track of the
nest level where a "disable" happened.
This would work if we get method call callbacks for every single method
call, but in reality, this only happens from HostStubGen-processed
classes. This confused the original logic.

To fix it, we'd need "method exit callback" too, but I don't think it's
worth implementing that. Instead, let's do the following:

Now, we just always check every single class in every method call.
Even before this, we had to get the stack trace to get the nest level,
so there's no extra const in getting the stacktrace.

But stacktraces don't contain class objects, while our innermost check
method operates on class objects. So we now use reflections. But we
now cache the result to mitigate the performance hit.

We could rewrite the check method to operate on Strings too, but
we also have some inheritance check too, so let's not change that.
Having a cache should be good enough.

Bug: 292141694
Flag: TEST_ONLY
Test: $ANDROID_BUILD_TOP/frameworks/base/ravenwood/scripts/run-ravenwood-tests.sh -r
Test: Enable method call log and manually check the output
Change-Id: Iedef9791116140a01b27b27d8821a3b5bcd8204d
parent de5e925e

ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodInternalUtils.java

0 → 100644
+57 −0
Original line number Diff line number Diff line 
/*

 * Copyright (C) 2025 The Android Open Source Project

 *

 * 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 android.platform.test.ravenwood;



import java.util.HashMap;



public class RavenwoodInternalUtils {

    private RavenwoodInternalUtils() {

    }



    /**

     * Base class for a simple key value cache. Subclass implements {@link #compute}.

     */

    public abstract static class MapCache<K, V> {

        private final Object mLock = new Object();



        private final HashMap<K, V> mCache = new HashMap<>();



        /**

         * Subclass implements it.

         *

         * This method may be called for the same key multiple times if access to the same

         * key happens on multiple threads at the same time.

         */

        protected abstract V compute(K key);



        /**

         * @return the value for a given key, using the cache.

         */

        public V get(K key) {

            synchronized (mLock) {

                var cached = mCache.get(key);

                if (cached != null) {

                    return cached;

                }

            }

            V value = compute(key);

            synchronized (mLock) {

                mCache.put(key, value);

            }

            return value;

        }

    }

}

ravenwood/junit-impl-src/android/platform/test/ravenwood/RavenwoodMethodCallLogger.java

+74 −67
Original line number Diff line number Diff line
@@ -17,6 +17,7 @@ package android.platform.test.ravenwood; 


import android.annotation.NonNull;

import android.annotation.Nullable;

import android.platform.test.ravenwood.RavenwoodInternalUtils.MapCache;

import android.util.Log;



import com.android.hoststubgen.hosthelper.HostTestUtils;
@@ -144,13 +145,6 @@ public class RavenwoodMethodCallLogger { 
    @GuardedBy("sAllMethods")

    private final Map<Class<?>, Set<MethodDesc>> mAllMethods = new HashMap<>();



    /** Return the current thread's call nest level. */

    @VisibleForTesting

    public int getNestLevel() {

        var st = Thread.currentThread().getStackTrace();

        return st.length;

    }



    /** Information about the current thread. */

    private class ThreadInfo {

        /**
@@ -158,13 +152,7 @@ public class RavenwoodMethodCallLogger { 
         * We do it because otherwise the nest level would be too deep by the time test

         * starts.

         */

        public final int mInitialNestLevel = getNestLevel();



        /**

         * A nest level where shouldLog() returned false.

         * Once it's set, we ignore all calls deeper than this.

         */

        public int mDisabledNestLevel = Integer.MAX_VALUE;

        public final int mInitialNestLevel = Thread.currentThread().getStackTrace().length;

    }



    private final ThreadLocal<ThreadInfo> mThreadInfo = ThreadLocal.withInitial(ThreadInfo::new);
@@ -178,17 +166,6 @@ public class RavenwoodMethodCallLogger { 
        sIgnoreClasses.add(android.util.EventLog.class);

        sIgnoreClasses.add(android.util.TimingsTraceLog.class);



        sIgnoreClasses.add(android.util.SparseArray.class);

        sIgnoreClasses.add(android.util.SparseIntArray.class);

        sIgnoreClasses.add(android.util.SparseLongArray.class);

        sIgnoreClasses.add(android.util.SparseBooleanArray.class);

        sIgnoreClasses.add(android.util.SparseDoubleArray.class);

        sIgnoreClasses.add(android.util.SparseSetArray.class);

        sIgnoreClasses.add(android.util.SparseArrayMap.class);

        sIgnoreClasses.add(android.util.LongSparseArray.class);

        sIgnoreClasses.add(android.util.LongSparseLongArray.class);

        sIgnoreClasses.add(android.util.LongArray.class);



        sIgnoreClasses.add(android.text.FontConfig.class);



        sIgnoreClasses.add(android.os.SystemClock.class);
@@ -220,24 +197,30 @@ public class RavenwoodMethodCallLogger { 
    /**

     * Return if a class should be ignored. Uses {link #sIgnoreCladsses}, but

     * we ignore more classes.

     *

     * If we make it operate on class names as strings directly, we wouldn't need

     * the reflections. But we cache the result anyway, so that's not super-critical.

     * Using class objects allow us to easily check inheritance too.

     */

    @VisibleForTesting

    public boolean shouldIgnoreClass(Class<?> clazz) {

    private boolean shouldIgnoreClass(Class<?> clazz) {

        if (mLogAllMethods) {

            return false;

        }

        if (sIgnoreClasses.contains(clazz)) {

            return true;

        }

        // We want to hide a lot of classes from android.util.

        if ("android.util".equals(clazz.getPackageName())) {

            // Let's also ignore collection-ish classes in android.util.

            if (java.util.Collection.class.isAssignableFrom(clazz)

                    || java.util.Map.class.isAssignableFrom(clazz)

                    || java.util.Iterator.class.isAssignableFrom(clazz)

            ) {

            if ("android.util".equals(clazz.getPackageName())) {

                return true;

            }

            return false;

            if (clazz.getSimpleName().endsWith("Array")) {

                return true;

            }

        }



        switch (clazz.getSimpleName()) {
@@ -257,37 +240,59 @@ public class RavenwoodMethodCallLogger { 
        return false;

    }



    private boolean shouldLog(

            Class<?> methodClass,

            String methodName,

            @SuppressWarnings("UnusedVariable") String methodDescriptor

    ) {

    private boolean shouldLogUncached(Class<?> clazz) {

        // Should we ignore this class?

        if (shouldIgnoreClass(methodClass)) {

        if (shouldIgnoreClass(clazz)) {

            return false;

        }

        // Is it a nested class in a class that should be ignored?

        var host = methodClass.getNestHost();

        if (host != methodClass && shouldIgnoreClass(host)) {

        var host = clazz.getNestHost();

        if (host != clazz && shouldIgnoreClass(host)) {

            return false;

        }



        var className = methodClass.getName();



        // Ad-hoc ignore list. They'd be too noisy.

        if ("create".equals(methodName)

                // We may apply jarjar, so use endsWith().

                && className.endsWith("com.android.server.compat.CompatConfig")) {

        var pkg = clazz.getPackageName();

        if (pkg.startsWith("android.icu")) {

            return false;

        }



        var pkg = methodClass.getPackageName();

        if (pkg.startsWith("android.icu")) {

            return false;

        return true;

    }



    /** Cache for {@link #shouldLog(Class)} */

    private final MapCache<Class<?>, Boolean> mClassEnabledCache = new MapCache<>() {

        @Override

        protected Boolean compute(Class<?> key) {

            return shouldLogUncached(key);

        }

    };



    /** @return whether a class should be logged */

    private boolean shouldLog(Class<?> clazz) {

        return mClassEnabledCache.get(clazz);

    }



    /** Cache for {@link #shouldLog(String)} to avoid repeated reflections. */

    private final MapCache<String, Boolean> mStringClassEnabledCache = new MapCache<>() {

        @Override

        protected Boolean compute(String className) {

            try {

                Class<?> c = Class.forName(className);

                if (!shouldLog(c)) {

                    return false;

                }

            } catch (ClassNotFoundException e) {

                // Assume this class is loggable.

            }

            return true;

        }

    };



    /** @return whether a class should be logged */

    @VisibleForTesting

    public boolean shouldLog(String className) {

        return mStringClassEnabledCache.get(className);

    }



    /**

     * Call this to enable logging.
@@ -322,29 +327,31 @@ public class RavenwoodMethodCallLogger { 
    }



    /** Inner method exposed for testing. */

    @VisibleForTesting

    @Nullable

    public String buildMethodCallLogLine(

    private String buildMethodCallLogLine(

            @NonNull Class<?> methodClass,

            @NonNull String methodName,

            @NonNull String methodDesc,

            @NonNull Thread mThread

    ) {

        final var ti = mThreadInfo.get();

        final int nestLevel = getNestLevel() - ti.mInitialNestLevel;



        // Once shouldLog() returns false, we just ignore all deeper calls.

        if (ti.mDisabledNestLevel < nestLevel) {

            return null; // Still ignore.

        if (!shouldLog(methodClass)) {

            return null;

        }

        final boolean shouldLog = shouldLog(methodClass, methodName, methodDesc);



        if (!shouldLog) {

            ti.mDisabledNestLevel = nestLevel;

        final var ti = mThreadInfo.get();

        final var stack = Thread.currentThread().getStackTrace();

        final int nestLevel = stack.length - ti.mInitialNestLevel;



        // If a method is called from a "ignored" class, we don't want to log it,

        // even if this method itself is loggable.

        //

        // To do so, we have to check all the classes in the stacktrace (unfortunately) every time.

        // That's because we can't re-construct the whole call tree only from the information

        // from the method call log call, because we don't know when we exit each method.

        for (var sf : stack) {

            if (!shouldLog(sf.getClassName())) {

                return null;

            }

        ti.mDisabledNestLevel = Integer.MAX_VALUE;



        }

        var sb = new StringBuilder();

        sb.append("# [");

        sb.append(getRawThreadId());

ravenwood/tests/coretest/test/com/android/ravenwoodtest/unittests/RavenwoodMethodCallLoggerTest.java

+20 −79
Original line number Diff line number Diff line
@@ -18,7 +18,6 @@ package com.android.ravenwoodtest.unittests; 
import static com.google.common.truth.Truth.assertThat;



import static org.junit.Assert.assertFalse;

import static org.junit.Assert.assertNull;

import static org.junit.Assert.assertTrue;



import android.content.Context;
@@ -58,95 +57,37 @@ public class RavenwoodMethodCallLoggerTest { 


        /** This allows overriding the nest level. */

        public Integer mNestLevel = null;



        @Override

        public int getNestLevel() {

            return (mNestLevel != null) ? mNestLevel : super.getNestLevel();

        }

    }



    private void assertLogged(Class<?> clazz) {

        assertFalse(clazz + " should be logged", mTarget.shouldIgnoreClass(clazz));

    private void assertLogged(String className) {

        assertTrue(className + " should be logged", mTarget.shouldLog(className));

    }



    private void assertNotLogged(Class<?> clazz) {

        assertTrue(clazz + " should not be logged", mTarget.shouldIgnoreClass(clazz));

    private void assertNotLogged(String className) {

        assertFalse(className + " should not be logged", mTarget.shouldLog(className));

    }



    @Test

    public void testShouldIgnoreClass() {

        assertNotLogged(android.util.Log.class);

        assertNotLogged(android.util.SparseArray.class);

        assertNotLogged(android.util.ArrayMap.class);

        assertNotLogged(android.app.EventLogTags.class);



        assertLogged(android.app.ActivityThread.class);

        assertLogged(android.content.Context.class);

    }



    /**

     * Unit test for buildMethodCallLogLine().

     */

    @Test

    public void testBuildLogLine() {

        Thread thread = new Thread("caller-thread");

        StringBuilder sb = new StringBuilder();



        // Note, buildMethodCallLogLine() doesn't check "mEnabled", so no need to call enable().



        // Here, we should only use public APIs that won't suddenly be removed

        mTarget.mNestLevel = 0;

        sb.append(mTarget.buildMethodCallLogLine(

                Context.class,

                "getPackageName",

                "()Ljava/lang/String;",

                thread));



        mTarget.mNestLevel = 1;

        sb.append(mTarget.buildMethodCallLogLine(

                Context.class,

                "getBasePackageName",

                "()Ljava/lang/String;",

                thread));



        // This shouldn't be logged, so the method should return null.

        mTarget.mNestLevel = 2;

        assertNull(mTarget.buildMethodCallLogLine(

                Log.class,

                "d",

                "(Ljava/lang/String;Ljava/lang/String;)V",

                thread));



        // Called by an ignored method, so this shouldn't be logged either.

        mTarget.mNestLevel = 3;

        assertNull(mTarget.buildMethodCallLogLine(

                Context.class,

                "getBasePackageName",

                "()Ljava/lang/String;",

                thread));



        // This should be logged again.

        mTarget.mNestLevel = 1;

        sb.append(mTarget.buildMethodCallLogLine(

                Context.class,

                "getOpPackgeName",

                "()Ljava/lang/String;",

                thread));

        String expected = """

# [123: caller-thread]: [@ 0] android.content.Context.getPackageName()Ljava/lang/String;

# [123: caller-thread]: [@ 1]   android.content.Context.getBasePackageName()Ljava/lang/String;

# [123: caller-thread]: [@ 1]   android.content.Context.getOpPackgeName()Ljava/lang/String;

                """;

        assertThat(sb.toString().trim()).isEqualTo(expected.trim());

    public void testShouldLog() {

        assertNotLogged("android.util.Log");

        assertNotLogged("android.util.ArrayMap");

        assertNotLogged("android.util.SparseArray");

        assertNotLogged("android.app.EventLogTags");

        assertNotLogged("android.os.Build");

        assertNotLogged("android.os.Build$VERSION"); // Inner class follows the outer class policy.



        assertLogged("android.app.ActivityThread");

        assertLogged("android.content.Context");

        assertLogged("android.util.DebugUtils");

        assertLogged("android.content.pm.PackageManager");

        assertLogged("android.content.pm.PackageManager$NameNotFoundException");

    }



    /**

     * More complete "end-to-end" test that exercises more of the target code.

     * Complete "end-to-end" test that exercises more of the target code.

     *

     * - It doesn't inject the nest level or the caller thread and let RavenwoodMethodCallLogger

     *   figure them out. (That means we can't adjust the nest level, and because

     *   RavenwoodMethodCallLogger gets the nest level from the stacktrace, all the log lines

     *   will get the same nest level.)

     * Note, method call log uses the real stacktrace to figure out the nest level.

     * So all the calls look "flat".

     */

    @Test

    public void testEndToEnd() throws Exception {