2014年3月24日星期一

Android 入门 - 使用日志

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

1、常用工具

1.1 Eclipse Logcat

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

1.2 adb logcat

adb logcat是Android Sdk自带的日志查看工具，具体用法参看：Android官网的读写日志。命令行格式如下：
# adb logcat [<option>] ... [<filter-spec>] ...
下面例举几个常用命令：

a）带时间查看 
# adb logcat -v time
b）查看所有的警告以上日志
# adb logcat -v time *:W
c）查看MyApp所有的警告以上的日志 
# adb logcat -v time MyApp:W
d) MyApp所有的警告以上的日志输出到文件中 
# adb logcat -v time -f /data/local/mylog.log MyApp:W
要注意：/data/local/mylog.log并非开发者电脑上的文件，而是模拟器（手机）上的文件。

1.3 Adb shell

adb 是Android SDK自带的工具，adb shell可以连接至模拟器（手机），直接操作模拟器（手机），相当于一个linux term，只有拥有权限，就可以运行全部的Linux命令。
# adb shell
root@generic:/ #
a）查看Logcat日志 
root@generic:/ # logcat
与前面描述的adb logcat操作相同。

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

2、日志实现

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

2.1 内核日志

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

printk( KERN_INFO " soft_cursor ingored.\n" );
KERN_INFO是定义的宏，就是代表字符串:"<6>"，中间没有逗号，C编译器会自动将两个串联在一起的字符串组合成一个字符串，所以，不要误认为KERN_INFO是一个参数。上面语句打印的实际信息为"<6> soft_cursor ingored.\n"。
printk函数只打印文本信息，没有时间等其他字段，查看一下printk.c源代码：
# cd /Volumes/androkd-kernel/source/goldfish
# 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加入到配置并重新编译内核。 
# vi arch/arm/configs/goldfish_armv7_defconfig
在文件末尾加入：
CONFIG_PRINTK_TIME=y

按 wq 保存退出。 

# make goldfish_armv7_defconfig
# make -j16
编译过程很快完成。运行后用adb shell查看？时间信息已经加入：
# adb shell
# root@generic:/ # dmesg

...
<6>[    3.140000] binder: 48:48 transaction failed 29189, size 0-0
<3>[    3.210000] init: cannot find '/system/etc/install-recovery.sh', disabling 'flash_recovery'
<5>[    3.210000] type=1405 audit(1395383323.310:5): bool=in_qemu val=1 old_val=0 auid=4294967295 ses=4294967295
...
上面蓝色的部分是表示时间距离CPU启动时间的间隔秒数，如何换算时间呢？在Android源代码中，未找到cpu_clock函数，此函数只在内核源码中有（未经权威确认），所以，无法知道当前的cpu_clock是多少，也就没法精确计算具体的时间，经过一翻折腾，还是认为直接修改源代码，把时间直接改成能够打印的时间。
# vi kernel/printk.c

....
#define CREATE_TRACE_POINTS
#include <trace/events/printk.h>
//一面一行为新增代码
#include <linux/time.h>
/*
 * 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;
    }
 ...
}
蓝色部分为新增代码，绿色部分为注释掉的代码。这样打印出来的时间，就可以格式成可以直观显示的时间了，时间是以秒为单位，精确到纳秒级。如下面所示：
...
<6>[           0.360000023] 8021q: 802.1Q VLAN Support v1.8
<6>[           0.360000023] VFP support v0.3: implementor 41 architecture 3 part 30 variant c rev 0
<6>[  1395585751.500000001] goldfish_rtc goldfish_rtc: setting system clock to 2014-03-23 14:42:31 UTC (1395585751)
<6>[  1395585751.500000001] Freeing init memory: 304K
...
你可能注意到了，前面会有一段时间为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
# cd /Volumes/android/source
# 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 <log/log.h>，这什么情况？原来源码移至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 <log/log.h>
...
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，这样也许还快些。

发帖者 时间：

没有评论:

发表评论

订阅： 博文评论 (Atom)