Logging，Debuging和TroubleShooting

From64KB
128 阅读14分钟

前一章学习了如何使用JNI在Java和native代码之间互相调用。在进一步进入NDK API开发之前，需要熟悉调试、问题处理相关技能。在本章中将会学到以下知识点：

  1. 介绍Android Loggin framework
  2. 通过IDE和命令行debug native代码
  3. 分析crash堆栈
  4. 使用CheckJNI模式来定位问题
  5. 使用libc和Valgrind来定位内存问题
  6. 使用strace来监控native代码执行

Logging

Logging是问题定位最重要的工具之一，但是它使用起来非常棘手。因为移动平台开发和实际运行是在两个设备上。Android有一个系统级的logging framework提供了Android 系统和应用的log。同时也提供了一系列查看和过滤log的工具，例如logcat等。

Framework

Android logging framework是在内核中的一个模块名为logger。由于Android平台会产生大量的Log，这就导致了查看和分析这些log会分厂困难。为了简化这个过程，Android logging framework把log分成了4个log buffer：
  1. Main: Main application log信息
  2. Events：系统事件
  3. Radio：射频相关日志信息
  4. System：底层系统debug信息

这四个buffer在/dev/log系统文件夹下作为四个伪设备。由于I/O操作在移动平台上非常占用资源，log信息不会被持久化存储，它们只会保存在内存中。为了控制log信息在内存中的占用，logger模块把这些数据放在固定大小的buffer中。Main, Radio 和 System log在64KB log buffer中以自由文本的格式保存。Event log携带了额外的信息

在256KB log buffer中以二进制形式保存。

Native Logging API

开发者不需要直接和内核中的logger模块交互。Android runtime提供了一系列API供Java和native代码调用logger模块。native 代码通过`android/log.h` 头文件来调用logging API。为了调用相关的API就需要在native代码中导入这个头文件： 
#include <android/log.h>

为了导入正确的头文件，Android.mk文件需要做一些修改来动态的链接log library。可以通过LOCAL_LDLIBS 这个系统变量来做到这一点。需要注意的是，这个变量必须放在include $(BUILD_SHARED_LIBRARY) 的前面，否则无效：

 LOCAL_MODULE := hello-jni 
 ... 
LOCAL_LDLIBS += −llog
 ... 
 include $(BUILD_SHARED_LIBRARY)

Log Message

每个传入logger module的log 结构体都有以下几块构成：
  1. Priority: 用于指明log信息的严重等级，可以是verbose, debug, info, warining, error 或者fatal。这些等级在android/log.h 中定义：
 typedef enum android_LogPriority { 
 ... 
 ANDROID_LOG_VERBOSE, 
 ANDROID_LOG_DEBUG, 
 ANDROID_LOG_INFO, 
 ANDROID_LOG_WARN, 
 ANDROID_LOG_ERROR, 
 ANDROID_LOG_FATAL, 
 ... 
 } android_LogPriority;
  1. Tag: 用于表明log信息的所属模块。logcat和DDMS可以通过tag来过滤相关log。这个tag应当是一个比较小的值
  2. Message：携带真实log信息的文本。每个换行符自动append到消息的结尾。由于环形缓冲区非常小，所以保证Message占用小也非常重要。

Logging Functions

`android/log.h` 头文件也声明了一系列方法用于native代码发送log：
  1. __android_log_write:发送一条简单string的log。这个方法需要三个参数log priority，log tag和log message：
 __android_log_write(ANDROID_LOG_WARN, "hello-jni", "Warning log.");
  1. <font style="color:rgb(19,20,19);">__android_log_print</font>：发送一条格式化后的String为log。需要传入4个参数log priority，log tag，string格式和string格式中指定的变量。具体的string格式定义可以参照ANSI C中<font style="color:rgb(19,20,19);">printf</font>文档：
 __android_log_print(ANDROID_LOG_ERROR, "hello-jni",
                     "Failed with errno %d", errno);
  1. <font style="color:rgb(19,20,19);">__android_log_vprint</font> : 和<font style="color:rgb(19,20,19);">__android_log_print</font>类似，但是额外的参数以<font style="color:rgb(19,20,19);">va_list</font>的形式传递，而不是print的一系列参数。这个会在需要传入可变个数的参数时非常有用：
 void log_verbose(const char* format, ...) 
 { 
     va_list args; 
     va_start(args, format); 
    __android_log_vprint(ANDROID_LOG_VERBOSE, "hello-jni", format, args);
     va_end(args); 
 } 
 ... 
 void example() 
 { 
     log_verbose("Errno is now %d", errno); 
 }
  1. __android_log_assert:可以用于log断言错误。和其他方法相比，这个方法少了priority参数，因为这个方法始终是fatal级别的。如果debugger 是attach状态的，这个方法会在当前进程产生一个SIGTRAP 来让debugger获取更多的信息和检查：
 if (0 != errno) 
 { 
 __android_log_assert("0 != errno", "hello-jni", 
 "There is an error."); 
 }

控制Logging

和Java中对应的log一样，native的logging API只是简单的执行向内核logger module发射log信息。在真实开发环境中，不可能在release和debug模式中使用相同的log输出。不幸的是，Android logging API并没有提供通过优先级屏蔽log的相关功能。这明显不如Log4J或者Log4CXX。Android logging framework把控制日志输出的工作交到了开发者手中。和Java中有Proguard可以混淆代码对比，native 代码工作就比较麻烦了。

Log封装

本章将会介绍一个基于预处理的方式解决控制log的问题。这就需要在hello-jni native工程中做一些修改。新建一个`my_log.h` 的头文件： 
#include <android/log.h>

#define MY_LOG_LEVEL_VERBOSE 1
#define MY_LOG_LEVEL_DEBUG 2
#define MY_LOG_LEVEL_INFO 3
#define MY_LOG_LEVEL_WARNING 4
#define MY_LOG_LEVEL_ERROR 5
#define MY_LOG_LEVEL_FATAL 6
#define MY_LOG_LEVEL_SILENT 7

#ifndef MY_LOG_TAG
//__FILE__:内置宏，代表代码所在文件
#define MY_LOG_TAG __FILE__
#endif

#ifndef MY_LOG_LEVEL
#define MY_LOG_LEVEL MY_LOG_LEVEL_VERBOSE
#endif

#define MY_LOG_NOOP (void) 0

//__LINE__:内置宏，代表代码所在行号
//__PRETTY_FUNCTION__:内置宏，代表方法名称
//"(%s:%u) %s: " fmt: 其中"(%s:%u) %s: "用于显示后面三个宏定义的文件、行号和方法名称，显示在fmt之前
//##__VA_ARGS__: GCC扩展语法，__VA_ARGS__用于处理可变参数，##在__VA_ARGS__之前是为了在__VA_ARGS__为空时
// 移除前面的逗号，这是必要的，因为如果没有提供可变参数，逗号会导致 语法错误
//使用方法:
//MY_LOG_PRINT(ANDROID_LOG_INFO, "This is a test log message.");
//MY_LOG_PRINT(ANDROID_LOG_ERROR, "Error code: %d", errorCode);
#define MY_LOG_PRINT(level, fmt, ...) \
        __android_log_print(level, MY_LOG_TAG,"(%s:%u) %s: " fmt, \
        __FILE__, __LINE__,__PRETTY_FUNCTION__,##__VA_ARGS__)

#if MY_LOG_LEVEL_VERBOSE >= MY_LOG_LEVEL
#define MY_LOG_VERBOSE(fmt, ...) MY_LOG_PRINT(ANDROID_LOG_VERBOSE,fmt,##__VA_ARGS__)
#else
#define MY_LOG_VERBOSE(...) MY_LOG_NOOP
#endif

#if MY_LOG_LEVEL_DEBUG >= MY_LOG_LEVEL
#define MY_LOG_DEBUG(fmt, ...) MY_LOG_PRINT(ANDROID_LOG_DEBUG,fmt,##__VA_ARGS__)
#else
#define MY_LOG_DEBUG(...) MY_LOG_NOOP
#endif

#if MY_LOG_LEVEL_INFO >= MY_LOG_LEVEL
#define MY_LOG_INFO(fmt, ...) MY_LOG_PRINT(ANDROID_LOG_INFO,fmt,##__VA_ARGS__)
#else
#define MY_LOG_INFO(...) MY_LOG_NOOP
#endif

#if MY_LOG_LEVEL_WARNING >= MY_LOG_LEVEL
#define MY_LOG_WARNING(fmt, ...) MY_LOG_PRINT(ANDROID_LOG_WARNING,fmt,##__VA_ARGS__)
#else
#define MY_LOG_WARNING(...) MY_LOG_NOOP
#endif

#if MY_LOG_LEVEL_ERROR >= MY_LOG_LEVEL
#define MY_LOG_ERROR(fmt, ...) MY_LOG_PRINT(ANDROID_LOG_ERROR,fmt,##__VA_ARGS__)
#else
#define MY_LOG_ERROR(...) MY_LOG_NOOP
#endif

#if MY_LOG_LEVEL_FATAL >= MY_LOG_LEVEL
#define MY_LOG_FATAL(fmt, ...) MY_LOG_PRINT(ANDROID_LOG_FATAL,fmt,##__VA_ARGS__)
#else
#define MY_LOG_FATAL(...) MY_LOG_NOOP
#endif

#if MY_LOG_LEVEL_FATAL >= MY_LOG_LEVEL
#define MY_LOG_ASSERT(expression, fmt, ...) \
            if(!(expression))                         \
            {                                         \
                __android_log_assert(#expression,MY_LOG_TAG, \
                fmt,##__VA_ARGS__                         \
            )}
#else
#define  MY_LOG_ASSERT(...) MY_LOG_NOOP
#endif

my_log.h 头文件中定义了一系列基础的native代码log预处理指令。这些预处理指令分装了Android log方法，并且允许在编译时动态的开关调整。

增加Logging

现在可以在native代码中增加logging了。首先把`my_log.h` 头文件导入目标C文件： 
 #include "my_log.h"

 jstring 
 Java_com_example_hellojni_HelloJni_stringFromJNI( JNIEnv* env, 
 jobject thiz ) 
 { 
 MY_LOG_VERBOSE("The stringFromJNI is called.");
 
 MY_LOG_DEBUG("env=%p thiz=%p", env, thiz);
 
 MY_LOG_ASSERT(0 != env, "JNIEnv cannot be NULL.");
 
 MY_LOG_INFO("Returning a new string.");
 
 return (*env)->NewStringUTF(env, "Hello from JNI !"); 
 }

更新Android.mk

现在可以通过在Android.mk中配置tag和level值来控制日志输出了。
Log Tag
通过在Android.mk中配置MY_LOG_TAG可以自定义tag的值： 
 # Define the log tag 
 MY_LOG_TAG := \"hello-jni\"
Log Level
通过在Android.mk中根据release还是debug配置MY_LOG_LEVEL来控制日志输出： 
 LOCAL_MODULE := hello-jni 
 ... 
 # Define the log tag 
 MY_LOG_TAG := \"hello-jni\" 
 
# Define the default logging level based build type
ifeq ($(APP_OPTIM),release)
 MY_LOG_LEVEL := MY_LOG_LEVEL_ERROR
else
 MY_LOG_LEVEL := MY_LOG_LEVEL_VERBOSE
endif

通过APP_OPTIM是否为release来给level赋值相应的等级，进而可以控制日志输出。

应用Loggin configuration
定义完MY_LOG_TAG和MY_LOG_LEVEL后，需要将变量的值应用到module中： 
 LOCAL_MODULE := hello-jni 
 ... 
 # Define the log tag 
 MY_LOG_TAG := hello-jni 
 
 # Define the default logging level based build type 
 ifeq ($(APP_OPTIM),release) 
 MY_LOG_LEVEL := MY_LOG_LEVEL_ERROR 
 else 
 MY_LOG_LEVEL := MY_LOG_LEVEL_VERBOSE 
 endif 
 
# Appending the compiler flags
LOCAL_CFLAGS += −DMY_LOG_TAG=$(MY_LOG_TAG)
LOCAL_CFLAGS += −DMY_LOG_LEVEL=$(MY_LOG_LEVEL)
 
# Dynamically linking with the log library
LOCAL_LDLIBS += −llog

Debugging

Logging可以在运行程序的时候把内部信息暴露出来。当在解决具体问题的时候，log信息的颗粒度可能不能满足定位问题需求。植入更多的log也许可以解决这个问题。但是如果能够attach一个debugger来更加直观的观察程序的状态会非常高效。Android NDK支持通过GNU Debugger(GDB)来调试native代码。

前置要求

为了调试native代码，需要满足以下条件：
  1. Native代码需要通过ndk-build命令或者IDE通过Android Development Tools编译。NDK build system会生成一系列用于远程调试的文件。
  2. 应用必须被置于debuggable状态。即AndroidManifest.xml中的android:debuggable 属性必须为true：
<?xml version="1.0" encoding="utf-8"?> 
<manifest xmlns:android=" http://schemas.android.com/apk/res/android " 
  package="com.example.hellojni" 
  android:versionCode="1" 
  android:versionName="1.0"> 
  ... 
  <application android:label="@string/app_name"
    android:debuggable="true">
    ... 
  </application> 
</manifest>
  1. Android系统版本必须大于等于2.2（大雾...）

ndk-gdb脚本在上述条件中有不满足的时候提供了很多错误处理和内容丰富的输出信息来提示开发者。

Debug Session设置

ndk-gdb脚本会在开发者尝试debug native代码的时候配置好debug session相关配置。但是了解debug session配置过程中步骤和细节对于了解debug native代码非常有用。下图显示了debug session创建的过程：

ndk-gdb脚本通过ADB使用Application manager来启动目标应用。Application manager把请求转发给Zygote进程。

Zygote，也被成为“app 进程”，这个进程在是Android系统启动时启动的核心进程之一。他在Android中的作用就是启动Dalvik虚拟机和初始化Android核心服务。作为一个移动操作系统，Android系统需要保持启动应用时长足够小来提供良好的用户体验。为了达到这个目的，从Zygote fork一个进程而不是从头开始新建一个进程。fork就是复制一个已有的进程，复制的进程和父进程有同样的内存信息，但是后续两个进程独立执行。

这时，应用已经启动并且正在执行代码。值得注意的是debug session此时还没有建立。

注意：由于Zygote运行的方式，GDB不能启动应用，只能attach到一个已经存在的应用进程。如果想要在attach GDB之后再执行某些代码，可以通过Java Debugger在某个前面的逻辑打上断点。

一旦获取到了应用的进程ID，ndk-gdb脚本在Android上启动GDB Server并且将它attach到正在运行的应用上。ndk-gdb脚本通过ADB端口转发来使得GDB Server能够被发起调试的设备访问到。然后，ndk-gdb会拷贝debug需要的二进制给Zygote并且在GDB client启动之前拷贝shared library到发起调试的设备。在二进制拷贝完成后，ndk-gdb脚本启动GDB client这时debug session就处于寄货状态。这样就可以开始调试了。

Debugging 例子

IDE例子就不举了，和普通Java差异不大。

有用的GDB命令

1. break : 在where指定的地方设置一个break point。这个where可以是一个方法名，一个 文件名或者一个文件中的行号如file.c:10 2. enable/disable/delete <#>: enable，disable和delete 指定号码的断点。#是一个代表断点的数字 3. clear：清除所有断点 4. next：前往 下一个指令 5. continue： 继续执行native代码 6. backtrace：显示方法调用堆栈 7. backtrace full：显示调用堆栈中每一帧中的本地变量 8. print : 打印what的值，what可以是一个变量、表达式、内存地址或者一个寄存器 9. display : 和print一样，但是可以在后续每一步指令执行后都显示what的值 10. what is :显示variable的类型 11. info threads: list所有运行的线程 12. thread : 切换调试线程 13. help：显示命令帮助 14. quit：退出调试session

注意：退出GDB 时会提示终止应用。

问题处理

Log和Debug可以查看应用运行过程中和运行时的各种状态。但是如果发生了异常，如何定位呢？通过适当的工具和技巧会提高问题解决速度。

堆栈分析

可以手动创造一个异常，然后观察生成的堆栈来更好的了解堆栈分析，可以看下如下代码： 
static jstring func1( JNIEnv* env ) 
{ 
    /* BUG BEGIN */ 
    env = 0; 
    /* BUG END */ 

    return (*env)->NewStringUTF(env, "Hello from JNI !"); 
}

jstring 
 Java_com_example_hellojni_HelloJni_stringFromJNI( JNIEnv* env, 
                                                  jobject thiz ) 
{ 
    return func1(env); 
}

由于把env置为0，代码运行到这里会产生一个crash。可以看一下产生的crash日志（随手写的，和上面的代码并不一致）：

以#开头的表示调用堆栈。#00表示发生crash的地方，上一个方法是#01，以此类推。pc后面跟的数字是代码的地址。如上图所示崩溃发生在00000000000257d0，前一个调用的方法是 Java_com_example_nativeexe_MainActivity_stringFromJNI。尽管pc 00000000000257d0并没有太多信息，但是通过使用适当的工具可以通过这个pc来定位出现异常的文件和行号。Android NDK通过ndk-stack工具将stack trace翻译成为真实的文件名称和行号。详细使用方法参见：developer.android.com/ndk/guides/…

JNI扩展检查

默认情况下JNI方法只会做很少的错误检查。这些错误会导致crash。Android提供了JNI方法调用检查扩展，称为CheckJNI。当打开这个功能的时候，JVM和JNIEnv在调用实际实现方法切换方法函数表的时候会进行额外的检查。CheckJNI可以检查如下问题：
  1. 尝试分配一个负size的array
  2. 传给JNI方法的异常或空指针
  3. 传递类名称时语法错误
  4. 在临界区调用JIN
  5. 传给NewDirectByteBuffer异常参数
  6. 在即将发生异常的时候调用JNI
  7. 在错误的线程使用JNIEnv接口指针
  8. Field 类型和SetField不匹配
  9. Method 类型和CallMethod不匹配
  10. 在错误的引用类型上调用DeleteGlobalRef/DeleteLocalRef
  11. 给ReleaseArrayElement方法传递错误的释放模式参数
  12. native 方法返回不兼容的类型
  13. 传递给JNI方法的不合法UTF-8字符串

默认情况下，CheckJNI只在模拟器上开启，在真实设备上由于性能问题不开启。

打开CheckJNI

通过如下ADB指令打开CheckJNI： 
 adb shell setprop debug.checkjni 1

这执行这个指令后打开的App就会打开CheckJNI功能。可以通过日志中CheckJNI is ON 确认是否打开。

可以通过下面的例子看一下CheckJNI打开后的效果：

jstring 
 Java_com_example_hellojni_HelloJni_stringFromJNI( JNIEnv* env, 
                                                  jobject thiz ) 
{ 
    jintArray javaArray = (*env)->NewIntArray(env, -1);

    return (*env)->NewStringUTF(env, "Hello from JNI !"); 
}

上面的代码创建了一个负size的int array。在实际运行中，会在日志中看到 JNI WARNING: negative jsize (NewIntArray) 并且中断执行。

内存问题

如果没有合适的工具，内存问题极难定位处理。在本章中将会介绍两种分析内存的方法。

使用Libc Debug Mode

libc debug mode在模拟器上可以用于查找内存问题。为了打开libc debug mode，需要使用如下命令： 
 adb shell setprop libc.debug.malloc 1 
 adb shell stop 
 adb shell start

libc debug mode支持的值有：

  1. 1-执行内存泄漏检测
  2. 5-填充已分配内存来检测溢出
  3. 10-填充内存并添加哨兵来检测溢出

可以通过下面的代码看一下Libc debug mode的效果：

jstring 
 Java_com_example_hellojni_HelloJni_stringFromJNI( JNIEnv* env, 
                                                  jobject thiz ) 
{ 
    char* buffer; 
    size_t i; 

    buffer = (char*) malloc(1024); 
    for (i = 0; i < 1025; i++) 
    { 
        buffer[i] = 'a'; 
    } 

    free(buffer); 

    return (*env)->NewStringUTF(env, "Hello from JNI !"); 
}

分配了1024个char内存，但是循环中使用1025个。这会导致超出分配的size，引起内存异常占用。通过如下指令：

 adb shell setprop libc.debug.malloc 10 
 adb shell stop 
 adb shell start

在模拟器上运行应用。会看到如下log并终止执行：

I/libc (3817): app_process using MALLOC_DEBUG = 10 (sentinels, fill)

E/libc (3818): *** FREE CHECK: buffer 0xa5218, size=1024, corrupted 1 bytes after 
allocation
E/libc (3828): call stack
E/libc (3828): 0: 40069f1c
E/libc (3828): 1: 40069fe4
...

Valgrind

Libc debug mode允许检查一些基础的内存问题。通过Valgrind可以作更深入的分析。这是一个开源的内存debug、内存泄漏检测和分析工具。

安装

参见：[https://valgrind.org/](https://valgrind.org/)

具体使用方法暂不介绍，需要注意的是，在使用Valgrind时，Android应用运行会十分缓慢，如果出现ANR，需要点击等待来给这个工具更多分析时间。

Strace

在某些情况下，需要在没有debugger和log的情况下监控应用执行的每一步。Strace可以被用来达成这个目标。这是一个拦截、记录应用调用system calls和收到的signal非常有用的工具。每一个系统调用的、参数和返回值都会被打印。需要注意，这个需要在模拟器上使用。

先看下面的样例代码：

#include <unistd.h>
... 
    jstring 
 Java_com_example_hellojni_HelloJni_stringFromJNI( JNIEnv* env, 
                                                  jobject thiz )
{ 
    getpid();
    getuid();

    return (*env)->NewStringUTF(env, "Hello from JNI !"); 
}

在模拟器上运行上述代码，打开terminal。输入如下命令：

 adb shell ps | grep com.example.hellojni

获取应用的进程ID。

执行如下指令：

 adb shell strace –v –p <Process ID>

这时strace会attach到应用进程上。显示如下log：

可以看到所有的系统调用都会打印出来。

avatar
文章
阅读
粉丝