Android 分析EventLog

一.查看EventLog

使用命令：
logcat -b events

二.logtags生成

2.1开机event log分析

1.获取开机时的event log：

logcat -b events | grep boot_progress

输出：

I boot_progress_start: 20726
I boot_progress_preload_start: 23255
I boot_progress_preload_end: 26806
I boot_progress_system_run: 27135
I boot_progress_pms_start: 27946
I boot_progress_pms_system_scan_start: 28447
I boot_progress_pms_data_scan_start: 29647
I boot_progress_pms_scan_end: 29958
I boot_progress_pms_ready: 30910
I boot_progress_ams_ready: 35811
I boot_progress_enable_screen: 38542

boot_progress_start表示Linux kernel启动到Zygote进程启动的时间，包含从kernel启动到Init启动Zygote的时间，接下来我们就以boot_progress_start为例来分析这条日志是如何输出的。

2.boot_progress_start是哪里输出的？

在/system/core/logcat/event.logtags找到了boot_progress_start的定义

# The entries in this file map a sparse set of log tag numbers to tag names.
# This is installed on the device, in /system/etc, and parsed by logcat.
  ...
# Device boot timings.  We include monotonic clock values because the
# intrinsic event log times are wall-clock.
#
# Runtime starts:
3000 boot_progress_start (time|2|3)

从注释可以看出这个logtags文件是用于日志标记号映射到标记名，并且安装在/system/etc下。在/system/etc下查找到event-log-tags文件，我们看下event-log-tags是如何生成的。

在build/soong/java/gen.go下：

pctx.SourcePathVariable("logtagsCmd", "build/tools/java-event-log-tags.py")
pctx.SourcePathVariable("mergeLogtagsCmd", "build/tools/merge-event-log-tags.py")

java-event-log-tags.py：生成一个java类，其中包含给定输入文件中每个事件日志标记的常量。
merge-event-log-tags.py：将零个或多个事件日志标记文件合并在一起，生成一个单独的输出文件，去掉注释。检查没有标签号冲突，如果有就失败。

我们知道boot_progress对应的id是3000,去framework下查找
grep -rn 3000
base/core/jni/AndroidRuntime.cpp:994:           const int LOG_BOOT_PROGRESS_START = 3000;

看下代码
void AndroidRuntime::start(const char* className, const Vector<String8>& options, bool zygote)
{
	...
	const int LOG_BOOT_PROGRESS_START = 3000;
    LOG_EVENT_LONG(LOG_BOOT_PROGRESS_START,  ns2ms(systemTime(SYSTEM_TIME_MONOTONIC)));
}

同样，我们在
frameworks/base/core/java/com/android/internal/os/ZygoteInit.java找到了
EventLog.writeEvent(LOG_BOOT_PROGRESS_PRELOAD_START, SystemClock.uptimeMillis());

2.2应用启动event log分析

1.获取应用启动event log

logcat -b events | grep am_

输出:

I am_create_task: [0,364]
I am_create_activity: [0,165832734,364,com.android.settings/.Settings,android.intent.action.MAIN,NULL,NULL,270532608]
I am_focused_stack: [0,1,0,startedActivity setFocusedActivity]
I am_focused_activity: [0,com.android.settings/.Settings,startedActivity]
I am_pause_activity: [0,102587883,com.android.launcher3/.Launcher]
I am_on_paused_called: [0,com.android.launcher3.Launcher,handlePauseActivity]
I am_restart_activity: [0,165832734,364,com.android.settings/.Settings]
I am_on_resume_called: [0,com.android.settings.Settings,LAUNCH_ACTIVITY]
I am_activity_launch_time: [0,165832734,com.android.settings/.Settings,825,825]
I am_stop_activity: [0,102587883,com.android.launcher3/.Launcher]
I am_on_stop_called: [0,com.android.launcher3.Launcher,handleStopActivity]
I am_pss  : [5733,10023,com.android.launcher3,12664832,9179136,0]

接下来我们以am_create_activity为例，分析log的输出，以及log的含义。

2.am_create_activity在哪里输出的

前面讲到java-event-log-tags.py会将logtags文件转换成java文件

• 1.先在/out/target/common/目录下查找am_create_activity

find . -name EventLogTags.java | xargs grep am_create_activity
找到了：
./obj/JAVA_LIBRARIES/services.core_intermediates/src/java/com/android/server/am/EventLogTags.java:  /** 30005 am_create_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3),(Action|3),(MIME Type|3),(URI|3),(Flags|1|5) */

看下这个文件：
/** 30005 am_create_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3),(Action|3),(MIME Type|3),(URI|3),(Flags|1|5) */
public static final int AM_CREATE_ACTIVITY = 30005;

public static void writeAmCreateActivity(int user, int token, int taskId, String componentName, String action, String mimeType, String uri, int flag    s) {
	android.util.EventLog.writeEvent(AM_CREATE_ACTIVITY, user, token, taskId, componentName, action, mimeType, uri, flags);
}

• 2.接下来去framework下查找哪里使用了writeAmCreateActivity

grep -rn writeAmCreateActivity

没有查找到，那就查AM_CREATE_ACTIVITY

grep -rn AM_CREATE_ACTIVITY
输出：
services/core/java/com/android/server/am/ActivityStarter.java:1242:                EventLogTags.AM_CREATE_ACTIVITY, mStartActivity, mStartActivity.task);

看下代码：
ActivityStack.logStartActivity(EventLogTags.AM_CREATE_ACTIVITY, mStartActivity, mStartActivity.task);

再来看下logStartActivity方法：

static final void logStartActivity(int tag, ActivityRecord r,
            TaskRecord task) {
      final Uri data = r.intent.getData();
      final String strData = data != null ? data.toSafeString() : null;

      EventLog.writeEvent(tag,
               r.userId, System.identityHashCode(r), task.taskId,
               r.shortComponentName, r.intent.getAction(),
               r.intent.getType(), strData, r.intent.getFlags());
}

3.输出log表示什么

由上面的输出行代码，再来看看

[0,165832734,364,com.android.settings/.Settings,android.intent.action.MAIN,NULL,NULL,270532608]
这就明白了
userId=0
identityHashCode=0,165832734
taskId=364
shortComponentName=com.android.settings/.Settings

上面的方式是通过查找代码来看出log含义。其实如果只是看log含义不需要这么麻烦，在/system/etc/event-log-tags可以看到

30005 am_create_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3),(Action|3),(MIME Type|3),(URI|3),(Flags|1|5)

这里的数字是什么意思呢？在framework下查找：

find . -name *.logtags | xargs grep am_create_activity
输出：
./services/core/java/com/android/server/am/EventLogTags.logtags:30005 am_create_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3),(Action|3),(MIME Type|3),(URI|3),(Flags|1|5)

这个文件开头就告诉我们去system/core/logcat/event.logtags看文件格式的描述

前面在分析开启启动log时，我们就看过这个文件。此时，我们再来看看。这个文件告诉我们描述格式是：

(<name>|data type[|data unit])

• data type表示:

  1: int
  2: long
  3: string
  4: list
  5: float
  

• data unit表示:

  1: Number of objects
  2: Number of bytes  # int/long类型数据的默认值是2(字节)。
  3: Number of milliseconds
  4: Number of allocations
  5: Id
  6: Percent
  

• 实例分析
  (User|1|5)表示:User是一个int类型的id
  (Component Name|3)表示是一个string