Android 入门 - 使用日志

http://blog.csdn.net/szzhaom/article/details/21995495
日志是程序调试及查错的必备工具，由于Android不是运行在开发者的电脑上，而是运行在模拟器或手机上，需要借助一些工具才能查看到日志信息。

1、常用工具

1.1 Eclipse Logcat

在Eclipse下安装ADT工具后，就可以用Logcat插件来直观方便的查看Android系统的运行日志。其实，该工具只是抓取Android系统中的/dev/log/main文件的信息，并直观的显示到Eclipse界面中。只要模拟器一运行，在Eclipse中的Logcat插件就可以看到模拟器的运行日志。
默认情况下，Logcat只显示最近5000条日志，可以通过preferences -> Android ->Logcat来调整最多可以显示的日志条数。
eclipseLogcat工具还可以定制过滤器快速查看，或输入关键字查询日志，非常方便。

1.2 adb logcat

adb logcat是Android Sdk自带的日志查看工具，具体用法参看：Android官网的读写日志。命令行格式如下：

1. # adb logcat [] ... [] ...  

下面例举几个常用命令：
a）带时间查看

1. # adb logcat -v time  

b）查看所有的警告以上日志

1. # adb logcat -v time *:W  

c）查看MyApp所有的警告以上的日志

1. # adb logcat -v time MyApp:W  

d) MyApp所有的警告以上的日志输出到文件中

1. # adb logcat -v time -f /data/local/mylog.log MyApp:W  

要注意：/data/local/mylog.log并非开发者电脑上的文件，而是模拟器（手机）上的文件。

1.3 Adb shell

adb 是Android SDK自带的工具，adbshell可以连接至模拟器（手机），直接操作模拟器（手机），相当于一个linux term，只有拥有权限，就可以运行全部的Linux命令。

1. # adb shell  
2. root@generic:/ #   

a）查看Logcat日志

1. root@generic:/ # logcat  

与前面描述的adb logcat操作相同。

b）查看内核日志

1. root@generic:/ # dmesg  

dmesg是内核中的一个命令，可以查看内核日志，当然，你也可以用 cat/proc/kmsg。不同的是，dmesg只读取缓冲区中的内核日志，而cat /proc/kmsg则可以原始的、完整的日志文件。

2、日志实现

开发Andorid应用的日志最常用的是用户空间日志，开发Android驱动程序和内核的日志则为内核日志。这里作一简单介绍。

2.1 内核日志

内核日志保存在/proc/kmsg文件中，如何写内核日志呢？用printk函数，详情可参见：内核日志：API及实现。这里简单介绍如何使用及简单代码分析。

#include

printk( KERN_INFO " soft_cursor ingored.\n" );

KERN_INFO是定义的宏，就是代表字符串:"<6>"，中间没有逗号，C编译器会自动将两个串联在一起的字符串组合成一个字符串，所以，不要误认为KERN_INFO是一个参数。上面语句打印的实际信息为"<6>soft_cursor ingored.\n"。

printk函数只打印文本信息，没有时间等其他字段，查看一下printk.c源代码：

1. # cd /Volumes/androkd-kernel/source/goldfish  
2. # vi kernel/printk.c  

找到如下代码：

...
#if defined(CONFIG_PRINTK_TIME)
static bool printk_time = 1;
#else
static bool printk_time = 0;
#endif
module_param_named(time, printk_time, bool, S_IRUGO | S_IWUSR);

static bool always_kmsg_dump;
...

从上面的代码可以看出：只有定义了CONFIG_PRINTK_TIME的情况下，才会打印时间。我们可以直接修改printk.c，但既然有配置项，就将配置项加入再重新编译就OK了。我们采取Android 入门 - 定制开机画面一文中的方法，将CONFIG_PRINTK_TIME加入到配置并重新编译内核。

1. # vi arch/arm/configs/goldfish_armv7_defconfig  

在文件末尾加入：

1. CONFIG_PRINTK_TIME=y  

按 wq保存退出。

1. # make goldfish_armv7_defconfig  
2. # make -j16  

编译过程很快完成。运行后用adb shell查看？时间信息已经加入：

1. # adb shell  
2. # root@generic:/ # dmesg  
3.   
4. ...  
5. <6>[    3.140000] binder: 48:48 transaction failed 29189, size 0-0  
6. <3>[    3.210000] init: cannot find '/system/etc/install-recovery.sh', disabling 'flash_recovery'  
7. <5>[    3.210000] type=1405 audit(1395383323.310:5): bool=in_qemu val=1 old_val=0 auid=4294967295 ses=4294967295  
8. ...  
9.               

上面时间是距离CPU启动时间的间隔秒数，如何换算时间呢？在Android源代码中，未找到cpu_clock函数，此函数只在内核源码中有（未经权威确认），所以，无法知道当前的cpu_clock是多少，也就没法精确计算具体的时间，经过一翻折腾，还是认为直接修改源代码，把时间直接改成能够打印的时间。

# vi kernel/printk.c

....
#define CREATE_TRACE_POINTS
#include
//一面一行为新增代码
#include
/*
 * Architectures can override it:
 */
void asmlinkage __attribute__((weak)) early_printk(const char *fmt, ...)
{
}
....
asmlinkage int vprintk(const char *fmt, va_list args)
{
    ...
    if (printk_time) {
            /* Add the current time stamp */
            char tbuf[50], *tp;
            unsigned tlen;
            struct timespec ts = current_kernel_time();
            // 下面的代码为注释代码
            /*unsigned long long t;
            unsigned long nanosec_rem;

            t = cpu_clock(printk_cpu);
            nanosec_rem = do_div(t, 1000000000);
            tlen = sprintf(tbuf, "[%5lu.%06lu] ",
                            (unsigned long) t,
                            nanosec_rem / 1000);*/
            //下面一行为新增代码
            tlen = sprintf(tbuf,"[%12lu.%09lu] ",ts.tv_sec,ts.tv_nsec);
            for (tp = tbuf; tp < tbuf + tlen; tp++)
                    emit_log_char(*tp);
            printed_len += tlen;
    }
    ...
}

这样打印出来的时间，就可以格式成可以直观显示的时间了，时间是以秒为单位，精确到纳秒级。如下面所示：

1. ...  
2. <6>[           0.360000023] 8021q: 802.1Q VLAN Support v1.8  
3. <6>[           0.360000023] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 0  
4. <6>[  1395585751.500000001] goldfish_rtc goldfish_rtc: setting system clock to 2014-03-23 14:42:31 UTC (1395585751)  
5. <6>[  1395585751.500000001] Freeing init memory: 304K  
6. ...  
7.           

你可能注意到了，前面会有一段时间为0，这是因为系统刚启动，尚未设置时间，在设置系统时间之后，时间就正确了。说明：曾尝试用do_gettimeofday来获取时间，但直接造成系统不开机了，何解？是不是未设置系统时间之前，不能调用do_gettimeofday，会造成死锁？欢迎专家指导。
Linux的时间在内核空间和用户空间是不一样的。time,ctime等熟悉的函数只能在用户空间使用，这里不再纠结了，在显示时，我们可能通过一些手段来解决掉。
注意：dmesg.c是用klogctl函数取内核日志的，该函数是在读取缓冲区中的日志，这样效率很高，但存在的问题是，如果内核日志的大小超出的缓冲区的限制，则老日志会被挤出，只留下最近的日志。dmesg.c中的默认大小的：128KB。但这个值可以通过内核编译选项配置：CONFIG_LOG_BUF_SHIFT，值为12到21，表示内核缓冲区最小为2的12次方（4KB），最大为2的21次方（2048KB）。

为了更方便的查看内核日志，我们可以修改dmesg，该文件在Andorid源码（非内核源码）的system/core/toolbox/dmesg.c，这个文件非常简单，修改很容易，这里不再赘述。

2.2 用户空间日志

这个日志就是用Logcat能够查看的日志了，Android（非内核）提供两种日志接口：C接口和Java接口。
a）C/C++语言接口
头文件：system/core/include/android/log.h

1. # cd /Volumes/android/source  
2. # vi system/core/include/android/log.h  

代码如下：

...
/*
 * Android log priority values, in ascending priority order.
 */
typedef enum android_LogPriority {
    ANDROID_LOG_UNKNOWN = 0,
    ANDROID_LOG_DEFAULT,    /* only for SetMinPriority() */
    ANDROID_LOG_VERBOSE,
    ANDROID_LOG_DEBUG,
    ANDROID_LOG_INFO,
    ANDROID_LOG_WARN,
    ANDROID_LOG_ERROR,
    ANDROID_LOG_FATAL,
    ANDROID_LOG_SILENT,     /* only for SetMinPriority(); must be last */
} android_LogPriority;

/*
 * Send a simple string to the log.
 */
int __android_log_write(int prio, const char *tag, const char *text);

/*
 * Send a formatted string to the log, used like printf(fmt,...)
 */
int __android_log_print(int prio, const char *tag,  const char *fmt, ...)
#if defined(__GNUC__)
    __attribute__ ((format(printf, 3, 4)))
#endif
    ;

/*
 * A variant of __android_log_print() that takes a va_list to list
 * additional parameters.
 */
int __android_log_vprint(int prio, const char *tag,
                         const char *fmt, va_list ap);

/*
 * Log an assertion failure and SIGTRAP the process to have a chance
 * to inspect it, if a debugger is attached. This uses the FATAL priority.
 */
void __android_log_assert(const char *cond, const char *tag,
                          const char *fmt, ...)
#if defined(__GNUC__)
    __attribute__ ((noreturn))
    __attribute__ ((format(printf, 3, 4)))
#endif
    ;
...

文件中定义了LOG级别android_LogPriority，并给出了几个函数来写日志：__android_log_write：写日志
__android_log_print：带格式化输出日志
__android_log_vprint：带格式化输出日志
网上有资料说，在system/core/include/cutils/log.h文件中做了相应的宏封装，但在我的源代码中，只有一句话：#include，这什么情况？原来源码移至system/core/include/log/log.h了，这两个文件等价。这个头文件定义了几个常用的宏：

• LOGV - 输出ANDROID_LOG_VERBOSE级别日志
• LOGD - 输出ANDROID_LOG_DEBUG级别日志
• LOGI - 输出ANDROID_LOG_INFO级别日志
• LOGW - 输出ANDROID_LOG_WARN级别日志
• LOGE - 输出ANDROID_LOG_ERROR级别日志
• LOGF - 输出ANDROID_LOG_FATAL级别日志
• LOGS - 输出ANDROID_LOG_SILENT级别日志

我们可以直接使用以上宏。用法举例：

#include
...
LOGD("MyTag","My message!");//输出调试信息

b）Java接口
Java接口和C的宏定义类似，源文件：frameworks/base/core/java/android/util/Log.java中。这里不再具体分析，使用很简单。

import java.android.util.Log;
...
Log.d("MyTag","My message!");//输出调试信息

网上有些文章提到，修改android/system/core/logcat/logcat.cpp，使logcat工具能直接查看内核日志的信息，我尝试过，没有一个能用。其实，要做到也可以：
1.不能使用klogctl，需要直接操作/proc/kmsg，原因上面已经有描述，因为klogctl只读取内核日志缓冲区中的日志。每次重新运行logcat命令，有可能得到的内核日志不一样，因为超过缓冲区后，超出部门的老日志会被挤出，也就无法显示了。
2.需要处理两份日志（内核空间日志和用户空间日志）的时间排序，否则，显示的时间可能对不上，这样的话，即使能够同时显示两类日志也没有意义。要完成这个操作，基本完全改变了logcat的原有逻辑。
我自己也修改过代码，实现了相关同步显示的代码，最终，我放弃了这样的想法，愿意钻研的朋友可以自己尝试，但我建议你重新写一个logcat，这样也许还快些。