Android 信號處理面面觀 之 trace 文件含義(轉)

在前一章 Android 信號處理面面觀 之 信號定義、行為和來源  中，我們討論過，Android 應用在收到異常終止信號（SIGQUIT）時，沒有遵循傳統 UNIX信號模型的默認行為 （終止 + core ）。而是打印出trace 文件來，以利於記錄應用異常終止的原因。 本文就重點分析 trace 文件是怎么產生的，並詳細解釋trace文件的各個字段的含義。

 

一. TRACE 文件的產生

Trace文件是 android davik 虛擬機在收到異常終止信號 （SIGQUIT）時產生的。 最經常的觸發條件是 android應用中產生了 FC （force close）。由於是該文件的產生是在 DVM里，所以只有運行 dvm實例的進程（如普通的java應用，java服務等）才會產生該文件，android 本地應用 （native app，指 運行在 android lib層，用c/c++編寫的linux應用、庫、服務等）在收到 SIGQUIT時是不會產生 trace文件的。

如上文Android 信號處理面面觀 之 信號定義、行為和來源所述，我們可以在終端通過adb發送SIGQUIT給應用來生成trace文件。

 

二. TRACE文件的實現

相關實現在以下幾個文件中：

dalvik/vm/init.h [.c]

davik/vm/SignalCatcher.h[.c]

dalvik/vm/Thread.h[.c]

Android ICS 實現文件后綴是 .cpp。

 

實現過程分以下幾步：

Step #1:  DVM初始化時，設置信號屏蔽字，屏蔽要特殊處理的信號(SIGQUIT, SIGUSR1, SIGUSR2)。由於信號處理方式是進程范圍起作用的， 這意味着該進程里所有的線程都將屏蔽該信號。 實現代碼在init.c中如下：

int dvmStartup(int argc, const char* const argv[], bool ignoreUnrecognized,
    JNIEnv* pEnv)
{
    ...
    /* configure signal handling */
    if (!gDvm.reduceSignals)
        blockSignals();
    ...
}

blockSignals()的實現很簡答，它是通過 sigprocmask() 函數調用實現的，代碼在init.c如下：

/*
 * Configure signals.  We need to block SIGQUIT so that the signal only
 * reaches the dump-stack-trace thread.
 *
 * This can be disabled with the "-Xrs" flag.
 */
static void blockSignals()
{
    sigset_t mask;
    int cc;

    sigemptyset(&mask);
    sigaddset(&mask, SIGQUIT);
    sigaddset(&mask, SIGUSR1);      // used to initiate heap dump
#if defined(WITH_JIT) && defined(WITH_JIT_TUNING)
    sigaddset(&mask, SIGUSR2);      // used to investigate JIT internals
#endif
    //sigaddset(&mask, SIGPIPE);
    cc = sigprocmask(SIG_BLOCK, &mask, NULL);
    assert(cc == 0);
}

Step #2： DVM 生成單獨的信號處理線程，用來對三個信號做特殊處理 （init.c）：

/*
 * Do non-zygote-mode initialization.  This is done during VM init for
 * standard startup, or after a "zygote fork" when creating a new process.
 */
bool dvmInitAfterZygote(void)
{
    ...
    /* start signal catcher thread that dumps stacks on SIGQUIT */
    if (!gDvm.reduceSignals && !gDvm.noQuitHandler) {
        if (!dvmSignalCatcherStartup())
            return false;
    }
    ...
}

dvmSignalCatcherStartup() 實現在 SignalCatcher.c 中：

/*
 * Crank up the signal catcher thread.
 *
 * Returns immediately.
 */
bool dvmSignalCatcherStartup(void)
{
    gDvm.haltSignalCatcher = false;

    if (!dvmCreateInternalThread(&gDvm.signalCatcherHandle,
                "Signal Catcher", signalCatcherThreadStart, NULL))
        return false;

    return true;
}

我們看到，DVM調用dvmCreateInternalThread()來生成一個新的內部線程 來專門處理dvm進程里的信號。 后面我們會看到，dvmCreateInternalThread()其實是使用pthread_create()來產生新的線程。 該線程的處理函數是 signalCatcherThreadStart()。  （dvm里所謂的 內部線程，就是用來幫助dvm實現本身使用的線程，比如 信號處理線程，binder線程，Compiler線程，JDWP線程等，而不是應用程序申請的線程。 在后面我們計划用專門的一章來討論DVM線程模式）

signalCatcherThreadStart() 實現框架如下：

/*
 * Sleep in sigwait() until a signal arrives.
 */
static void* signalCatcherThreadStart(void* arg)
{
    ...
    /* set up mask with signals we want to handle */
    sigemptyset(&mask);
    sigaddset(&mask, SIGQUIT);
    sigaddset(&mask, SIGUSR1);
#if defined(WITH_JIT) && defined(WITH_JIT_TUNING)
    sigaddset(&mask, SIGUSR2);
#endif
    ...
    while (true) {
    ...
loop:
        cc = sigwait(&mask, &rcvd);
        ...
        switch (rcvd) {
        case SIGQUIT:
            handleSigQuit();
            break;
        case SIGUSR1:
            handleSigUsr1();
            break;
#if defined(WITH_JIT) && defined(WITH_JIT_TUNING)
        case SIGUSR2:
            handleSigUsr2();
            break;
#endif
        ...
}

它首先設置我們要處理的信號集(SIGQUIT, SIGUSR1, SIGUSR2), 然后 調用 sigwait()。 我們知道sigwait()會在當前的線程里 重新 打開 指定的信號屏蔽字屏蔽的信號集。  在剛才的分析中，我們看到，dvm在啟動時，首先在整個進程里設置信號屏蔽字屏蔽掉三個信號，sigwait()的調用，使的這三個信號只在 SignalCatcher線程里響應。

至此我們已經能夠看到，dvm對三個信號分別所做的特殊用途：

1. SIGUSR1 被用來 做手工垃圾收集。處理函數是 HandleSigUsr1()

static void handleSigUsr1(void)
{
    LOGI("SIGUSR1 forcing GC (no HPROF)\n");
    dvmCollectGarbage(false);
}

2. SIGUSR2 被用來做 JIT的調試。如果JIT下編譯時打開，收到SIGUSR2是dvm會dump出相關的調試信息。處理邏輯如下：

#if defined(WITH_JIT) && defined(WITH_JIT_TUNING)
/*
 * Respond to a SIGUSR2 by dumping some JIT stats and possibly resetting
 * the code cache.
 */
static void handleSigUsr2(void)
{
    static int codeCacheResetCount = 0;
    if ((--codeCacheResetCount & 7) == 0) {
        gDvmJit.codeCacheFull = true;
    } else {
        dvmCompilerDumpStats();
        /* Stress-test unchain all */
        dvmJitUnchainAll();
        LOGD("Send %d more signals to rest the code cache",
             codeCacheResetCount & 7);
    }
}
#endif

由於以上兩個信號都僅用於DVM的內部實現的調試，本文不作詳細的分析。讀者可以在終端通過adb發送 SIGUSR1 和SIGUSR2信號來觀察它的行為。

 

3.  SIGQUIT 用來 輸出trace文件，以記錄異常終止是dvm的上下文信息.

SIGQUIT的處理函數如下所示：

static void handleSigQuit(void)
{   ...
    dvmSuspendAllThreads(SUSPEND_FOR_STACK_DUMP);

    if (gDvm.stackTraceFile == NULL) {
        /* just dump to log */
        DebugOutputTarget target;
        dvmCreateLogOutputTarget(&target, ANDROID_LOG_INFO, LOG_TAG);
        dvmDumpAllThreadsEx(&target, true);
    } else {
        /* write to memory buffer */
        FILE* memfp = open_memstream(&traceBuf, &traceLen);
        if (memfp == NULL) {
            LOGE("Unable to create memstream for stack traces\n");
            traceBuf = NULL;        /* make sure it didn't touch this */
            /* continue on */
        } else {
            logThreadStacks(memfp);
            fclose(memfp);
        }
    }

#if defined(WITH_JIT) && defined(WITH_JIT_TUNING)
    dvmCompilerDumpStats();
#endif

    dvmResumeAllThreads(SUSPEND_FOR_STACK_DUMP);

    if (traceBuf != NULL) {
        int fd = open(gDvm.stackTraceFile, O_WRONLY | O_APPEND | O_CREAT, 0666);
        if (fd < 0) {
            LOGE("Unable to open stack trace file '%s': %s\n",
                gDvm.stackTraceFile, strerror(errno));
        } else {
        ...
        }
    ...
}

它首先查看有木有指定 trace輸出文件，沒有就將trace信息打印到log里。如果有，就先將trace信息打印到內存文件中，然后再講改內存文件內容輸出到指定trace文件中。

有些讀者肯能覺得奇怪，為什么指定了trace文件后，不直接打印trace信息到trace文件中呢。 原因是 trace文件實際上記錄的是當前運行的所有的線程的上下文信息。他需要 暫停所有的線程才能輸出。 dvmSuspendAllThreads(SUSPEND_FOR_STACK_DUMP);的調用正式這個目的。可以看出，這個操作代價是很高的，它把當前所有的線程都停了下來。執行的時間越短，對正常運行的線程的影響越小。 輸出信息到內存比直接到外部文件要快得多。所以 dvm采取了先輸出到內存，馬上恢復線程程，然后就可以慢慢的輸出到外部文件里了。

而這真正的輸出信息實現在 logThreadStacks()中：

static void logThreadStacks(FILE* fp)
{
    dvmPrintDebugMessage(&target,
        "\n\n----- pid %d at %04d-%02d-%02d %02d:%02d:%02d -----\n",
        pid, ptm->tm_year + 1900, ptm->tm_mon+1, ptm->tm_mday,
        ptm->tm_hour, ptm->tm_min, ptm->tm_sec);
    printProcessName(&target);
    dvmPrintDebugMessage(&target, "\n");
    dvmDumpAllThreadsEx(&target, true);
    fprintf(fp, "----- end %d -----\n", pid);
}

該函數打印了trace文件的框架，其輸出類似如下所示：

----- pid 503 at 2011-11-21 21:59:12 -----
Cmd line: com.android.phone

<Thread_info>

----- end 503 -----

它顯示當前dvm進程的進程id，名字，輸出的時間。最重要的所有線程的上下文信息是有函數 dvmDumpAllThreadsEx()里實現的，該函數定義在 thread.c里：

void dvmDumpAllThreadsEx(const DebugOutputTarget* target, bool grabLock)
{
    Thread* thread;

    dvmPrintDebugMessage(target, "DALVIK THREADS:\n");

#ifdef HAVE_ANDROID_OS
    dvmPrintDebugMessage(target,
        "(mutexes: tll=%x tsl=%x tscl=%x ghl=%x hwl=%x hwll=%x)\n",
        gDvm.threadListLock.value,
        gDvm._threadSuspendLock.value,
        gDvm.threadSuspendCountLock.value,
        gDvm.gcHeapLock.value,
        gDvm.heapWorkerLock.value,
        gDvm.heapWorkerListLock.value);
#endif

    if (grabLock)
        dvmLockThreadList(dvmThreadSelf());

    thread = gDvm.threadList;
    while (thread != NULL) {
        dvmDumpThreadEx(target, thread, false);

        /* verify link */
        assert(thread->next == NULL || thread->next->prev == thread);

        thread = thread->next;
    }

    if (grabLock)
        dvmUnlockThreadList();
}

它的輸出格式如下：

DALVIK THREADS:
(mutexes: tll=0 tsl=0 tscl=0 ghl=0 hwl=0 hwll=0)
"main" prio=5 tid=1 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x400246a0 self=0x12770
  | sysTid=503 nice=0 sched=0/0 cgrp=default handle=-1342909272
  | schedstat=( 15165039025 12197235258 23068 ) utm=182 stm=1334 core=0
  at android.os.MessageQueue.nativePollOnce(Native Method)
  at android.os.MessageQueue.next(MessageQueue.java:119)
  at android.os.Looper.loop(Looper.java:122)
  at android.app.ActivityThread.main(ActivityThread.java:4134)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:491)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:841)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:599)
  at dalvik.system.NativeStart.main(Native Method)

至此， 我們可以很清楚的 解析 trace文件中 thread信息的含義了：

1. 第一行是 固定的頭, 指明下面的都是 當前運行的 dvm thread ：“DALVIK THREADS:”

2. 第二行輸出的是該 進程里各種線程互斥量的值。（具體的互斥量的作用在 dalvik 線程一章 單獨陳述）

3. 第三行輸出分別是 線程的名字（“main”），線程優先級（“prio=5”），線程id（“tid=1”） 以及線程的 類型（“NATIVE”）

4. 第四行分別是線程所述的線程組 （“main”），線程被正常掛起的次處（“sCount=1”），線程因調試而掛起次數（”dsCount=0“），當前線程所關聯的java線程對象（”obj=0x400246a0“）以及該線程本身的地址（“self=0x12770”）。

5. 第五行 顯示 線程調度信息。 分別是該線程在linux系統下得本地線程id （“ sysTid=503”），線程的調度有優先級（“nice=0”），調度策略（sched=0/0），優先組屬（“cgrp=default”）以及 處理函數地址（“handle=-1342909272”）

6 第六行 顯示更多該線程當前上下文，分別是 調度狀態（從 /proc/[pid]/task/[tid]/schedstat讀出）（“schedstat=( 15165039025 12197235258 23068 )”），以及該線程運行信息 ，它們是 線程用戶態下使用的時間值(單位是jiffies）（“utm=182”）， 內核態下得調度時間值（“stm=1334”），以及最后運行改線程的cup標識（“core=0”）；

7.后面幾行輸出 該線程 調用棧。

 

有了以上信息，我們便更容易分析出app是為什么被異常終止的了。我們會在單獨的一章分析， 怎樣利用trace文件里的信息尋找app異常終止的原因。敬請期待