首先,让我们看一看AndroidLog的格式。下面这段log是以所谓的long格式打印出来的。从前面Logcat的介绍中可以知道,long格式会把时间,标签等作为单独的一行显示。
[ 12-09 21:39:35.510 396: 416 I/ActivityManager ]
Start procnet.coollet.infzmreader:umengService_v1 for service
net.coollet.infzmreader/com.umeng.message.
UmengService:pid=21745 uid=10039 gids={50039, 3003, 1015,1028}
[ 12-09 21:39:35.518 21745:21745I/dalvikvm ]
Turning on JNI app bug workarounds fortarget SDK version 8...
[ 12-09 21:39:35.611 21745:21745D/AgooService ]
onCreate()
我们以第一行为例:12-09 是日期,21:39:35.510是时间396是进程号,416是线程号;I代表log优先级,ActivityManager是log标逗洞签。
在应用开发中,这些信息的作用可能不是很大。但是在系统开发中,这些都是很重要的辅助信息。开发工程师分析的log很多都是由测试工程师抓取的,所以可能有些log根本就不是当时出错的log。如果出现这种情况,无论你怎么分析都不太可能得出正确的结论。如何能最大限度的避免这种情况呢?笔者就要求测试工程师报bug时必须填上bug发生的时间。这样结合log里的时间戳信息就能大致判断是否是发生错误时的log。而且根据测试工程师提供的bug发生时间点,开发工程师可以在长长的log信息中快速的定位错误的位置,缩小分析的范围。
同时我们也要注意,时间信息在log分析中可能被错误的使用。例如:在分析多线程相关的问题时,我们有时需要根据两段不同线程中log语句执行的先后顺序来判断错误发生的原因,但是我们不能以两段log在log文件中出现的先后做为判断的条件,这是因为在小段时间内两个线程输出log的先后是随机的,log打印的先后顺序并不完全等同于执行的顺序。那么我们是否能以log的时间戳来判断呢?同样是不可以,因为这个时间戳实际上是系统打印输出log时的时间,并不是调用log函数时的时间。遇到这种情况唯一的办法是在输出log前,调用系统时间函数获取当时时间,然后再通过log信息打印输出。这样虽然麻烦一点,但是只有这样取得的时间才是可靠的,才能做为我们判断的依据。
另外一种误用log中时间戳的情况是用它来分析程序的性能。一个有多年工作经验的工程师拿着他的性能分析结果给笔者看,但是笔者对这份和实际情况相差很远的报告表示怀疑,于是询问这位工程师是如何得出结论的。他的回答让笔者很惊讶,他计算所采用的数据就是log信息前面的时间戳。前面我们已经讲过,log前面时间戳和调用log函数的时间并不相同,这是由于系统缓冲log信息引起的,而且这两个时间的时间差并不固定。所以用log信息前附告激带的时间戳来计算两段log间代码的性能会有比较大的误差。正确的方法还是上面提到袜指袜的:在程序中获取系统时间然后打印输出,利用我们打印的时间来计算所花费的时间。
了解了时间,我们再谈谈进程Id和线程Id,它们也是分析log时很重要的依据。我们看到的log文件,不同进程的log信息实际上是混杂在一起输出的,这给我们分析log带来了很大的麻烦。有时即使是一个函数内的两条相邻的log,也会出现不同进程的log交替输出的情况,也就是A进程的第一条log后面跟着的是B进程的第二条log,对于这样的组合如果不细心分析,就很容易得出错误的结论。这时一定要仔细看log前面的进程Id,把相同Id的log放到一起看。