AndroidシステムにおけるWatchDogログ分析

21163 ワード

and roid ---- performance ソース分析 watchdog ロゴデッド・ロックログ

ソース:
https://blog.csdn.net/shift_wwx/article/details/81030749

前言:
AndroidシステムのWatchDogは、WatchDogのソフトウェア設計原理とモニタリングプロセスをsource codeによって詳細に分析し、この例を組み合わせてWatchDogをさらに分析した.

ソースコード:

            final String tracesDirProp = SystemProperties.get("dalvik.vm.stack-trace-dir", "");
            File stackFd = finalStack;
            if (tracesDirProp.isEmpty()) {
                String tracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null);
                String traceFileNameAmendment = "_SystemServer_WDT" +
                        mTraceDateFormat.format(new Date());

                if (tracesPath != null && tracesPath.length() != 0) {
                    File traceRenameFile = new File(tracesPath);
                    String newTracesPath;
                    int lpos = tracesPath.lastIndexOf (".");
                    if (-1 != lpos) {
                        newTracesPath = tracesPath.substring(0, lpos) + traceFileNameAmendment
                                + tracesPath.substring(lpos);
                    } else {
                        newTracesPath = tracesPath + traceFileNameAmendment;
                    }
                    traceRenameFile.renameTo(new File(newTracesPath));
                    stackFd = new File(newTracesPath);
                } else {
                    Slog.w(TAG, "dump WDT Traces: no trace path configured");
                }
            } else {
                // the new trace dumpsing mechanism
                String newTracesPath = "traces_SystemServer_WDT"
                        + mTraceDateFormat.format(new Date()) + "_pid"
                        + String.valueOf(Process.myPid());
                File tracesDir = new File(tracesDirProp);
                File watchdogTraces = new File(tracesDir, newTracesPath);

                try {
                    if (watchdogTraces.createNewFile()) {
                        FileUtils.setPermissions(watchdogTraces.getAbsolutePath(),
                                0600, -1, -1); // -rw------- permissions

                        // Append both traces from the first and second half
                        // to a new file, making it easier to debug Watchdog timeouts
                        //dumpStackTraces() can return a null instance, so check the same
                        if (initialStack != null) {
                            // check the last-modified time of this file.
                            // we are interested in this only it was written to in the
                            // last minute or so
                            final long age = System.currentTimeMillis()
                                    - initialStack.lastModified();
                            final long MINUTE_IN_MILLIS = 1000 * 60;
                            if (age < MINUTE_IN_MILLIS) {
                                Slog.e(TAG, "First set of traces taken from "
                                        + initialStack.getAbsolutePath());
                                appendFile(watchdogTraces, initialStack);
                            }
                        } else {
                            Slog.e(TAG, "First set of traces are empty!");
                        }

                        if (finalStack != null) {
                            Slog.e(TAG, "Second set of traces taken from "
                                    + finalStack.getAbsolutePath());
                            appendFile(watchdogTraces, finalStack);
                        } else {
                             Slog.e(TAG, "Second set of traces are empty!");
                        }
                    } else {
                        Slog.w(TAG, "Unable to create Watchdog dump file: createNewFile failed");
                    }
                } catch (IOException ioe) {
                    Slog.e(TAG, "Exception creating Watchdog dump file:", ioe);
                }
            }
            final File newFd = stackFd;

            // Try to add the error to the dropbox, but assuming that the ActivityManager
            // itself may be deadlocked.  (which has happened, causing this statement to
            // deadlock and the watchdog as a whole to be ineffective)
            Thread dropboxThread = new Thread("watchdogWriteToDropbox") {
                    public void run() {
                        mActivity.addErrorToDropBox(
                                "watchdog", null, "system_server", null, null,
                                subject, null, newFd, null);
                    }
                };
            dropboxThread.start();
            try {
                dropboxThread.join(2000);  // wait up to 2 seconds for it to return.
            } catch (InterruptedException ignored) {}


            // At times, when user space watchdog traces don't give an indication on
            // which component held a lock, because of which other threads are blocked,
            // (thereby causing Watchdog), crash the device to analyze RAM dumps
            boolean crashOnWatchdog = SystemProperties
                                        .getBoolean("persist.sys.crashOnWatchdog", false);
            if (crashOnWatchdog) {
                // Trigger the kernel to dump all blocked threads, and backtraces
                // on all CPUs to the kernel log
                Slog.e(TAG, "Triggering SysRq for system_server watchdog");
                doSysRq('w');
                doSysRq('l');

                // wait until the above blocked threads be dumped into kernel log
                SystemClock.sleep(3000);

                // now try to crash the target
                doSysRq('c');
            }

            IActivityController controller;
            synchronized (this) {
                controller = mController;
            }
            if (controller != null) { //  monkey       
                Slog.i(TAG, "Reporting stuck state to activity controller");
                try {
                    Binder.setDumpDisabled("Service dumps disabled due to hung system process.");
                    // 1 = keep waiting, -1 = kill system
                    int res = controller.systemNotResponding(subject);
                    if (res >= 0) {
                        Slog.i(TAG, "Activity controller requested to coninue to wait");
                        waitedHalf = false;
                        continue;
                    }
                } catch (RemoteException e) {
                }
            }

            // Only kill the process if the debugger is not attached.
            if (Debug.isDebuggerConnected()) {
                debuggerWasConnected = 2;
            }
            if (debuggerWasConnected >= 2) {
                Slog.w(TAG, "Debugger connected: Watchdog is *not* killing the system process");
            } else if (debuggerWasConnected > 0) {
                Slog.w(TAG, "Debugger was connected: Watchdog is *not* killing the system process");
            } else if (!allowRestart) {
                Slog.w(TAG, "Restart not allowed: Watchdog is *not* killing the system process");
            } else {
                Slog.w(TAG, "*** WATCHDOG KILLING SYSTEM PROCESS: " + subject);
                for (int i=0; i

1、prop dalvik.vm.stack-trace-dir
グループは/data/anrを指します

2、watch dogログ名

String newTracesPath = "traces_SystemServer_WDT"
           + mTraceDateFormat.format(new Date()) + "_pid"
           + String.valueOf(Process.myPid());
File tracesDir = new File(tracesDirProp);
File watchdogTraces = new File(tracesDir, newTracesPath);

最後に、プラットフォームの/data/anr/ディレクトリで次のように表示されます.

-rw-------  1 system system 227332 2007-11-06 00:05 BinderTraces.txt
-rw-------  1 system system 179568 2007-11-06 00:04 anr_2007-11-06-00-04-41-133
-rw-------  1 system system 230506 2007-11-06 00:05 anr_2007-11-06-00-05-14-301
-rw-------  1 system system 180175 2007-11-06 02:57 anr_2007-11-06-02-57-39-825
-rw-------  1 system system 229772 2007-11-06 02:58 anr_2007-11-06-02-58-13-023
-rw-------  1 system system 198777 2007-11-06 19:26 anr_2007-11-06-19-26-00-611
-rw-------  1 system system 249791 2007-11-06 19:26 anr_2007-11-06-19-26-33-888
-rw-------  1 system system 410074 2007-11-06 00:05 traces_SystemServer_WDT06_Nov_00_05_28.143_pid2197
-rw-------  1 system system 229772 2007-11-06 02:58 traces_SystemServer_WDT06_Nov_02_58_55.714_pid2726
-rw-------  1 system system 249791 2007-11-06 19:27 traces_SystemServer_WDT06_Nov_19_27_16.140_pid2473

ここは書類が多いですね.携帯電話は久しぶりに片付けたので、大丈夫な後、どの書類が私たちが必要なのか分かります.

3、AMSに記録されたログappendを現在のwatch dogのtracesに入れる
AndroidシステムにおけるWatchDogの詳細なrun()関数解析では,monitorが30秒を超えるとcheckが返す状態がWAITED_であることが分かった.HALF、WatchDogは2回目のチャンスを与えますが、同時にAMSのログをdumpに記録します.

appendFile(watchdogTraces, initialStack);

2回目が正常に戻らない場合は、2回目のlogもwatchdogTracesに追加されます.

appendFile(watchdogTraces, finalStack);

最後のtraces_SystemServer_WDT06_Nov_00_05_28.143_pid 2197のlogは最終的に生成された.

4、/data/system/dropboxでwatchdogファイルを作成する

    Thread dropboxThread = new Thread("watchdogWriteToDropbox") {
        public void run() {
            mActivity.addErrorToDropBox(
                      "watchdog", null, "system_server", null, null,
                       subject, null, newFd, null);
            }
        };
    dropboxThread.start();

(1)subjectはblockedChecker記述である:

        public String describeBlockedStateLocked() {
            if (mCurrentMonitor == null) {
                return "Blocked in handler on " + mName + " (" + getThread().getName() + ")";
            } else {
                return "Blocked in monitor " + mCurrentMonitor.getClass().getName()
                        + " on " + mName + " (" + getThread().getName() + ")";
            }
        }

/data/system/dropbox/のwatchdogログに次のように表示されます.

Subject: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on ActivityManager (ActivityManager)

ここから来ました.
(2)newFdとは、実は上の点で述べたfinalStackのfdを指しているので、最後にdropboxの中のtracesにはinitialStackのlogはありません

具体的なaddErrorToDropBox()関数はしばらく分析されません.以下、logと組み合わせてさらに説明します.プラットフォーム上の/data/system/dropbox/ディレクトリの下に表示されます.

-rw-------  1 system system   329 2007-11-06 00:38 [email protected]
-rw-------  1 system system   329 2007-11-06 00:43 [email protected]
-rw-------  1 system system   329 2007-11-06 00:45 [email protected]
-rw-------  1 system system  1414 2007-11-06 00:44 [email protected]
-rw-------  1 system system  1414 2007-11-06 00:44 [email protected]
-rw-------  1 system system  4302 2007-11-06 00:43 [email protected]
-rw-------  1 system system  1832 2007-11-06 00:43 [email protected]
-rw-------  1 system system  2009 2007-11-06 00:44 [email protected]
-rw-------  1 system system  4035 2007-11-06 00:45 [email protected]
-rw-------  1 system system 19587 2007-11-06 00:05 [email protected]

一般的に問題が発生したら最新のtracesファイルを探せばいいです.

5、logcatでスタック情報を印刷する

    Slog.w(TAG, "*** WATCHDOG KILLING SYSTEM PROCESS: " + subject);
    for (int i=0; i

logcatでは、次のような印刷が表示されます.

11-06 00:05:28.603  2197  2441 W Watchdog: *** WATCHDOG KILLING SYSTEM PROCESS: Blocked in monitor com.android.server.am.ActivityManagerService on foreground thread (android.fg), Blocked in handler on ActivityManager (ActivityManager)
11-06 00:05:28.603  2197  2441 W Watchdog: foreground thread stack trace:
11-06 00:05:28.603  2197  2441 W Watchdog:     at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:23862)
11-06 00:05:28.604  2197  2441 W Watchdog:     at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:211)
11-06 00:05:28.604  2197  2441 W Watchdog:     at android.os.Handler.handleCallback(Handler.java:790)
11-06 00:05:28.604  2197  2441 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:99)
11-06 00:05:28.604  2197  2441 W Watchdog:     at android.os.Looper.loop(Looper.java:164)
11-06 00:05:28.604  2197  2441 W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:65)
11-06 00:05:28.604  2197  2441 W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:46)
11-06 00:05:28.604  2197  2441 W Watchdog: ActivityManager stack trace:
11-06 00:05:28.604  2197  2441 W Watchdog:     at com.android.server.am.ActivityManagerService.idleUids(ActivityManagerService.java:23305)
11-06 00:05:28.604  2197  2441 W Watchdog:     at com.android.server.am.ActivityManagerService$MainHandler.handleMessage(ActivityManagerService.java:2428)
11-06 00:05:28.604  2197  2441 W Watchdog:     at android.os.Handler.dispatchMessage(Handler.java:106)
11-06 00:05:28.604  2197  2441 W Watchdog:     at android.os.Looper.loop(Looper.java:164)
11-06 00:05:28.604  2197  2441 W Watchdog:     at android.os.HandlerThread.run(HandlerThread.java:65)
11-06 00:05:28.604  2197  2441 W Watchdog:     at com.android.server.ServiceThread.run(ServiceThread.java:46)
11-06 00:05:28.604  2197  2441 W Watchdog: *** GOODBYE!
11-06 00:05:28.605  2197  2441 I Process : Sending signal. PID: 2197 SIG: 9

ロゴから見ると:

monitorは、fg thread、すなわちWatchDogのmMonitorCheckerのmonitor()が

をトリガする

monitor()に加えて、AMSのHandlerもWatchDog

をトリガした.

最後に問題が発生したプロセスkillを落とします.ここはpid 2197

です.

問題の分析:
上のロゴと結びつけて、分析してみましょう.
1、logcat
上記の5点目で説明したように、印刷によってどのスレッドか、どのスレッドのモニタに問題があるかを大体知ることができます.

2、tracesファイルの分析
まず/data/anr/watchdogファイルを見て、上のlogcatから最後のpidが2197であることがわかります.では、最後に2197文字列のtracesファイル、つまりtraces_を探します.SystemServer_WDT06_Nov_00_05_28.143_pid2197
(1)上記の5点目に基づいて、まずモニタが現れる場所、すなわちfg threadを見つける.

"android.fg" prio=5 tid=17 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x13380dc8 self=0x9e3b3200
  | sysTid=2225 nice=0 cgrp=default sched=0/0 handle=0x9159d970
  | state=S schedstat=( 0 0 0 ) utm=5 stm=2 core=2 HZ=100
  | stack=0x9149b000-0x9149d000 stackSize=1038KB
  | held mutexes=
  at com.android.server.am.ActivityManagerService.monitor(ActivityManagerService.java:23862)
  - waiting to lock <0x0316e620> (a com.android.server.am.ActivityManagerService) held by thread 81
  at com.android.server.Watchdog$HandlerChecker.run(Watchdog.java:211)
  at android.os.Handler.handleCallback(Handler.java:790)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:164)
  at android.os.HandlerThread.run(HandlerThread.java:65)
  at com.android.server.ServiceThread.run(ServiceThread.java:46)

待機ロックでは、tidが81のスレッドによってこのロックが保持されています.次に、tidが81のために何をしたかを見てみましょう.

"Binder:2197_4" prio=5 tid=81 Waiting
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x14041c20 self=0x8d713200
  | sysTid=2435 nice=-10 cgrp=default sched=0/0 handle=0x8c749970
  | state=S schedstat=( 0 0 0 ) utm=9 stm=6 core=2 HZ=100
  | stack=0x8c64f000-0x8c651000 stackSize=1006KB
  | held mutexes=
  at java.lang.Object.wait(Native method)
  - waiting on <0x0c1b5e76> (a com.android.server.PermissionDialogReqQueue$PermissionDialogReq)
  at com.android.server.PermissionDialogReqQueue$PermissionDialogReq.get(PermissionDialogReqQueue.java:100)
  - locked <0x0c1b5e76> (a com.android.server.PermissionDialogReqQueue$PermissionDialogReq)
  at com.android.server.AppOpsService.noteOperationUnchecked(AppOpsService.java:1157)
  at com.android.server.AppOpsService.noteOperation(AppOpsService.java:1086)
  at com.android.server.am.ActivityManagerService.isStartAllowed(ActivityManagerService.java:24937)
  at com.android.server.am.ActiveServices.startServiceLocked(ActiveServices.java:369)
  at com.android.server.am.ActivityManagerService.startService(ActivityManagerService.java:18450)
  - locked <0x0316e620> (a com.android.server.am.ActivityManagerService)
  at android.app.IActivityManager$Stub.onTransact(IActivityManager.java:528)
  at com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:2971)
  at android.os.Binder.execTransact(Binder.java:697)

startServiceの時にAMSというロックを占有していたのですが、後ろにはPermissionDialogReqQueueのロックが待っていて、このロックは自分でロックしたもので出てこなかったので、一連のデッドロックを招きました.
(2)同様に,上の5点目よりAMS中のHandlerもWatchDogをトリガーしている.

"ActivityManager" prio=5 tid=12 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x13380710 self=0x9e0fae00
  | sysTid=2216 nice=-2 cgrp=default sched=0/0 handle=0x91bb4970
  | state=S schedstat=( 0 0 0 ) utm=60 stm=23 core=3 HZ=100
  | stack=0x91ab2000-0x91ab4000 stackSize=1038KB
  | held mutexes=
  at com.android.server.am.ActivityManagerService.idleUids(ActivityManagerService.java:23305)
  - waiting to lock <0x0316e620> (a com.android.server.am.ActivityManagerService) held by thread 81
  at com.android.server.am.ActivityManagerService$MainHandler.handleMessage(ActivityManagerService.java:2428)
  at android.os.Handler.dispatchMessage(Handler.java:106)
  at android.os.Looper.loop(Looper.java:164)
  at android.os.HandlerThread.run(HandlerThread.java:65)
  at com.android.server.ServiceThread.run(ServiceThread.java:46)

同じロックを待つ

上のtraces分析を合わせると、AMSのロックが持たれていてずっと放されていないことがわかります.dropboxのtraces(一般的には2回目のtracesの時にANRが現れた)を見てみましょう.この時、メインスレッドにANRが現れるはずです.mainを見てみましょう.

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 flags=1 obj=0x723919f0 self=0xa7a28000
  | sysTid=2197 nice=-2 cgrp=default sched=0/0 handle=0xabb1e4a4
  | state=S schedstat=( 0 0 0 ) utm=320 stm=99 core=2 HZ=100
  | stack=0xbe447000-0xbe449000 stackSize=8MB
  | held mutexes=
  at com.android.server.am.ActivityManagerService.broadcastIntent(ActivityManagerService.java:20018)
  - waiting to lock <0x0316e620> (a com.android.server.am.ActivityManagerService) held by thread 81
  at android.app.ActivityManager.broadcastStickyIntent(ActivityManager.java:4175)
  at android.app.ActivityManager.broadcastStickyIntent(ActivityManager.java:4165)
  at com.android.server.BatteryService$9.run(BatteryService.java:578)
  at android.os.Handler.handleCallback(Handler.java:790)
  at android.os.Handler.dispatchMessage(Handler.java:99)
  at android.os.Looper.loop(Looper.java:164)
  at com.android.server.SystemServer.run(SystemServer.java:435)
  at com.android.server.SystemServer.main(SystemServer.java:278)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:438)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:787)

ANRもこのロックであるべきであり,2つのtraces解析によれば,PermissionDialogReqQueue自身のロックが解放されず,timeoutがwatch dogをトリガしたためであると判断できる.
しかし、実際には、この2回目のlogの意味は大きくありません.このときシステムANRは、システムがなぜANRが現れたのか、つまり1回目のtracesのlogが後のdebugで重要な要素を果たす可能性があるからです.

3、原因を探す
PermissionDialogReqQueue,java 100行get()関数を見てみましょう.

        public int get() {
            synchronized (this) {
                try {
                    wait();
                } catch (InterruptedException e) {
                    //ignore
                }
            }
            Log.d(TAG, "result from permission dialog is " + mResult);
            return mResult;
        }

論理的には、ここではwaitでdialogが結果を返すのを待っています.set関数のときnotify:

        public void set(int res) {
            synchronized (this) {
                mResult = res;
                notifyAll();
            }
        }

論理的に処理するのは問題ないはずですが、dialogが30秒以内にクリックすると、notify()は以前持っていたロックを外します.しかし、現象的には、dialogがポップアップされた後、AMSインタフェースの呼び出しによりdialogカードが死んでしまい、ロックが正常に解放されず、最終的にWatchDogがsystemを再起動した.
この問題で私は疑問に思っています.論理的にはokはAMSでロックしようとしたときにdialogが引っかかってしまいました.その後、dialogと同時にAMSのインタフェースを呼び出してメインスレッドが死んだのではないかと疑っていました.何度も挫折してdialogをサブスレッドにshow(AndroidサブスレッドでUIの詳細を更新)しようとしましたが、成功しました.原因を探し続けています.

thinkphpテンプレートクラスを簡単に処理する方法

Centosマルチバージョンphp共存