LoginSignup
7
6

More than 5 years have passed since last update.

@JavaToKotlin(カエル キム)

AndroidでAspectJを用いてメソッドのログを見やすく出力 + plantuml

Last updated at Posted at 2018-11-30

こんにちは。
最近、作業中にメソッドの呼び出しを確認するためBreakpointをむりやりにかけてみましたが
それもどんどん雑になってもっと見やすくように色々なことを工夫してみました。

AndroidのLogメソッドを用いてBooleanの値で出力するものもいいと思いますがソース内にゴミが積み重ねてるのが嫌いのでそれを控えたがったです。
で、AspectJというものを試して見るように決めました。

（元の資料はこちらを参照しました。https://qiita.com/shmz/items/5fd3f885b4117e320b8c）

幸いにAndroid用のAspectJライブラリがありますね。＾＿＾

次のようにやってみました。

１．aspectjtoolsというものをロード

build.grade(Project:YourProject)にdependenciesを追加

∨Gradle Scripts 
  build.grade(Project:YourProject)

buildscript {
    repositories {
        jcenter()
        google()
        mavenCentral()
    }
    ...
    dependencies {
        classpath 'org.aspectj:aspectjtools:1.9.2'
    }
}


allprojects {
    repositories {
        jcenter()
        google()
        mavenCentral()
    }
}

２．build.grade(Project:YourApp)に設定とAspectJ Weavingとdependenciesを追加


import org.aspectj.bridge.IMessage
import org.aspectj.bridge.MessageHandler
import org.aspectj.tools.ajc.Main

∨Gradle Scripts 
  build.grade(Project:YourApp)

android {
    ...
    defaultConfig {
        ...
        minSdkVersion 14　//14以上を求める
    }

    applicationVariants.all {  variant ->
        ...
       variant.javaCompiler.doLast {
            String[] args = ["-showWeaveInfo",
                             "-1.8",
                             "-inpath", javaCompile.destinationDir.toString(),
                             "-aspectpath", javaCompile.classpath.asPath,
                             "-d", javaCompile.destinationDir.toString(),
                             "-classpath", javaCompile.classpath.asPath,
                             "-bootclasspath", project.android.bootClasspath.join(
                    File.pathSeparator)]

            MessageHandler handler = new MessageHandler(true);
            new Main().run(args, handler)

            def log = project.logger
            for (IMessage message : handler.getMessages(null, true)) {
                switch (message.getKind()) {
                    case IMessage.ABORT:
                    case IMessage.ERROR:
                    case IMessage.FAIL:
                        log.error message.message, message.thrown
                        break;
                    case IMessage.WARNING:
                    case IMessage.INFO:
                        log.info message.message, message.thrown
                        break;
                    case IMessage.DEBUG:
                        log.debug message.message, message.thrown
                        break;
                }
            }
        }
    }
}


dependencies {
    ...
    compile 'org.aspectj:aspectjrt:1.9.2'
}

３．AspectJ Class 作成

AspectDebugLog.javaファイルをsrc\main\java\などのホルダーに置く

SpingなどでAspectJを携わった方はご存知てると思いますがjoinpoint,Pointcut,advice等々を用いてメソッドの前とか後に処理を特定することができます。

簡単にいうと
何か処理をしたいメソッドは　execution(* com.example.pcd_b_006.myapplication...(..))　というふうに書き留め、
処理をしたくないメソッドは　！execution(* com.example.pcd_b_006.myapplication...(..))　というふうに書き留めますと
選り分けができます。

で、今回はレガシーソースコードを分析する為にプロジェクトの全体のメソッドにpointcutを引きかけてみます。

レガシーソースコードの流れを洗い出し為にメソッド実行の前後にローグを出力してみます。

どうせながらもっと見やすく見えように飾り付けます。（Draftヴァージョンです）

（StopWatchはこちらを参照
https://fernandocejas.com/2014/08/03/aspect-oriented-programming-in-android/）


import android.util.Log;

import org.aspectj.lang.JoinPoint;
import org.aspectj.lang.ProceedingJoinPoint;
import org.aspectj.lang.annotation.After;
import org.aspectj.lang.annotation.Around;
import org.aspectj.lang.annotation.Aspect;
import org.aspectj.lang.annotation.Before;
import org.aspectj.lang.annotation.Pointcut;
import org.aspectj.lang.reflect.MethodSignature;

import java.util.ArrayList;
import java.util.List;
import java.util.concurrent.TimeUnit;

/**
 * MyApplication
 * Class: AspectDebugLog
 * Created by kim taeho .
 * <p>
 * Description:
 */
@Aspect
public final class AspectDebugLog {
    public static int depth = 0;
    public static List<String> depthText = new ArrayList<>();
    public static String prespace = "│";
    public static String lastClassMethod = "Start";

    private static final String POINTCUT_BEFORE_METHOD =
            "execution(* com.example.pcd_b_006.myapplication..*.*(..)) && " +
                    "!(" +
                    "execution(* com.example.pcd_b_006.myapplication.MainEnumString..*(..)) || " +
                    "execution(* com.example.pcd_b_006.myapplication.sub..*.*(..)) " +
                    ")";


    private static final String POINTCUT_AROUND_METHOD = POINTCUT_BEFORE_METHOD;

    @Pointcut(POINTCUT_BEFORE_METHOD)
    public void pointcutDebugTraceBefore() {
    }

    @Pointcut(POINTCUT_AROUND_METHOD)
    public void pointcutDebugTraceAround() {
    }

    @Before("pointcutDebugTraceBefore()")
    public void weaveDebugTraceBefore(JoinPoint joinPoint) throws Throwable {
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        String className = methodSignature.getDeclaringType().getSimpleName();
        String methodName = methodSignature.getName();

        Object[] objArray = joinPoint.getArgs();
        String[] sigParamNames = methodSignature.getParameterNames();
        int i = 0;
        String argName = "";
        StringBuilder argAll = new StringBuilder();
        for (Object obj : objArray) {
            argName = sigParamNames[i];
            i++;
            if (obj == null) continue;
            argAll.append(argName + ":[" + obj.toString() + "]");
        }

        if (argAll.length() > 1) {
            argAll.insert(0, " [Args]  ");
        }


        lastClassMethod = "";
        if(depthText.size() >0) {
            lastClassMethod = depthText.get(depthText.size()-1);
        }

        //### weaveDebugTraceBefore:
        Log.d("Aspect", repeat(prespace, AspectDebugLog.depth + 1) + "▼" + "(" + methodSignature.getMethod() + ")"); 
        //### weaveDebugTraceBefore:
        Log.d("Aspect", repeat(prespace, AspectDebugLog.depth + 2) + " " + lastClassMethod + className + "." + methodName + argAll); 


    }

    @Around("pointcutDebugTraceAround()")
    public Object weaveDebugTraceAround(ProceedingJoinPoint joinPoint) throws Throwable {
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        String className = methodSignature.getDeclaringType().getSimpleName();
        String methodName = methodSignature.getName();


        AspectDebugLog.depth++;
        Log.d("Aspect", repeat(prespace, AspectDebugLog.depth) + "┏ " + className + "." + methodName); 

        lastClassMethod = className + "." + methodName + " <- ";
        depthText.add(lastClassMethod);


        StopWatch stopWatch = new StopWatch();
        stopWatch.start();
        Object result = joinPoint.proceed();
        stopWatch.stop();

        Log.d("Aspect", repeat(prespace, AspectDebugLog.depth) +
                "┗ " + className + "." + methodName +
                " □  result : " + result +
                " : " + stopWatch.getTotalTimeMillis() + "ms"); 
        AspectDebugLog.depth--;
        if(depthText.size() >0) {
            depthText.remove(depthText.size()-1);
        }

        return result;
    }


    public synchronized static String repeat(String string, int times) {
        StringBuilder out = new StringBuilder();

        while (times-- > 0) {
            out.append(string);
        }
        return out.toString();
    }

    //---------------------------------------------------------------------------Activity
    @Pointcut("execution(void android.app.Activity.onResume(..))")
    public void pointcutOnResume() {
    }

    @Pointcut("execution(void android.app.Activity.onCreate(..))")
    public void pointcutOnCreate() {
    }

    @Pointcut("execution(void android.app.Activity.onDestroy(..))")
    public void pointcutOnDestroy() {
    }

    @Before("pointcutOnCreate()")
    public void weavePreOnCreate(JoinPoint joinPoint) {
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        String className = methodSignature.getDeclaringType().getSimpleName();

        Log.d("Aspect", "### weavePreOnCreate: " + className);
    }

    @After("pointcutOnCreate()")
    public void weavePostOnCreate(JoinPoint joinPoint) throws Throwable {
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        String className = methodSignature.getDeclaringType().getSimpleName();

        Log.d("Aspect", "### weavePostOnCreate: " + className);
    }

    @Before("pointcutOnResume()")
    public void weavePreOnResume(JoinPoint joinPoint) {
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        String className = methodSignature.getDeclaringType().getSimpleName();

        Log.d("Aspect", "### weavePreResume: " + className);
    }

    @After("pointcutOnDestroy()")
    public void weavePostOnDestroy(JoinPoint joinPoint) throws Throwable {
        MethodSignature methodSignature = (MethodSignature) joinPoint.getSignature();
        String className = methodSignature.getDeclaringType().getSimpleName();

        Log.d("Aspect", "### weavePostOnDestroy: " + className);
    }

    /**
     * Class representing a StopWatch for measuring time.
     */
    public class StopWatch {
        private long startTime;
        private long endTime;
        private long elapsedTime;

        public StopWatch() {
            //empty
        }

        private void reset() {
            startTime = 0;
            endTime = 0;
            elapsedTime = 0;
        }

        public void start() {
            reset();
            startTime = System.nanoTime();
        }

        public void stop() {
            if (startTime != 0) {
                endTime = System.nanoTime();
                elapsedTime = endTime - startTime;
            } else {
                reset();
            }
        }

        public long getTotalTimeMillis() {
            return (elapsedTime != 0) ? TimeUnit.NANOSECONDS.toMillis(endTime - startTime) : 0;
        }
    }
}

４．結果は。。

▼：メソッドの名前
<-：呼び出しスタック
□：メソッドの返す値
ms：メソッドの実行時間

10:56:20.942 22427-22427/com.example.pcd_06.myapplication D/Aspect: │▼(protected void com.example.pcd_06.myapplication.MainActivity.onCreate(android.os.Bundle))
10:56:20.942 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││ MainActivity.onCreate
10:56:20.942 22427-22427/com.example.pcd_06.myapplication D/Aspect: │┏ MainActivity.onCreate
10:56:20.942 22427-22427/com.example.pcd_06.myapplication D/Aspect: ### weavePreOnCreate: MainActivity
10:56:20.959 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││▼(public static void com.example.pcd_06.myapplication.MySam.testA())
10:56:20.959 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││ MainActivity.onCreate <- MySam.testA
10:56:20.959 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││┏ MySam.testA
10:56:20.960 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││▼(public void com.example.pcd_06.myapplication.MySam.inA())
10:56:20.960 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││││ MySam.testA <- MySam.inA
10:56:20.960 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┏ MySam.inA
10:56:20.960 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┗ MySam.inA □  result : null : 0ms
10:56:20.960 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││▼(public void com.example.pcd_06.myapplication.MySam.inB())
10:56:20.960 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││││ MySam.testA <- MySam.inB
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┏ MySam.inB
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┗ MySam.inB □  result : null : 0ms
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││┗ MySam.testA □  result : null : 1ms
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││▼(public static void com.example.pcd_06.myapplication.MySam.testA())
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││ MainActivity.onCreate <- MySam.testA
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││┏ MySam.testA
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││▼(public void com.example.pcd_06.myapplication.MySam.inA())
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││││ MySam.testA <- MySam.inA
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┏ MySam.inA
10:56:20.961 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┗ MySam.inA □  result : null : 0ms
10:56:20.962 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││▼(public void com.example.pcd_06.myapplication.MySam.inB())
10:56:20.962 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││││ MySam.testA <- MySam.inB
10:56:20.962 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┏ MySam.inB
10:56:20.962 22427-22427/com.example.pcd_06.myapplication D/Aspect: │││┗ MySam.inB □  result : null : 0ms
10:56:20.962 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││┗ MySam.testA □  result : null : 0ms
10:56:20.963 22427-22427/com.example.pcd_06.myapplication D/Aspect: │┗ MainActivity.onCreate □  result : null : 20ms
10:56:20.963 22427-22427/com.example.pcd_06.myapplication D/Aspect: ### weavePostOnCreate: MainActivity
10:56:23.055 22427-22427/com.example.pcd_06.myapplication D/Aspect: │▼(protected void com.example.pcd_06.myapplication.MainActivity.onDestroy())
10:56:23.055 22427-22427/com.example.pcd_06.myapplication D/Aspect: ││ MainActivity.onDestroy
10:56:23.055 22427-22427/com.example.pcd_06.myapplication D/Aspect: │┏ MainActivity.onDestroy
10:56:23.056 22427-22427/com.example.pcd_06.myapplication D/Aspect: │┗ MainActivity.onDestroy □  result : null : 0ms
10:56:23.056 22427-22427/com.example.pcd_06.myapplication D/Aspect: ### weavePostOnDestroy: MainActivity

5．まとめ

取り得は
- MainとServiceのProcessが入り混じった際にも取り分けができます。
- 大雑把なアプリの流れとメソッドの呼び出しをあるほど把握できます。

6．応用

AndroidStdioログメッセージに手を加えれば plantuml でより安くみることもできます。
-Configure Logcat Header
[ ] Show date and time
[ ] Show process and thread IDs(PID-TID)
[ ] Show package name
[ ] Show tag
によりAndroidStdioからログを拾得すると
(D:　はnotepadなどで削除。。。）

D: Start -> MainActivity : onCreate
D: activate MainActivity
D: MainActivity -> MySam : testA
D: activate MySam
D: MySam -> MySam : inA
D: activate MySam
D: MySam --> MySam : MySam  ( 0ms )
D: deactivate MySam
D: MySam -> MySam : inB
D: activate MySam
D: MySam --> MySam : MySam  ( 0ms )
D: deactivate MySam
D: MySam --> MainActivity : MainActivity  ( 1ms )
D: deactivate MySam
D: MainActivity -> MySam : testA
D: activate MySam
D: MySam -> MySam : inA
D: activate MySam
D: MySam --> MySam : MySam  ( 0ms )
D: deactivate MySam
D: MySam -> MySam : inB
D: activate MySam
D: MySam --> MySam : MySam  ( 0ms )
D: deactivate MySam
D: MySam --> MainActivity : MainActivity  ( 0ms )
D: deactivate MySam
D: MainActivity --> Start : Start  ( 9ms )
D: deactivate MainActivity

こんな風になります。これをPLANTUMLサイトで試してみれば

test.png

7
6
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
7
6