Android(安卓)event日志打印原理
16lz
2021-01-24
基于android 7.0代码，分析Event日志的打印原理
近期准备重新梳理一遍Activity的启动流程，其中通过Event日志分析是一个重要的工具。
我们在调试分析Android的过程中，经常会查看EventLog，它非常简洁明了地展现当前Activity各种状态，当然不至于此，比如还有window、surfaceFlinger、battery等其他的信息。
如果在终端中输入：logcat -b events，就能够输出大量类似下面的日志信息：
07-02 01:38:27.718 3623 3636 I am_home_stack_moved: [0,0,1,1,startingNewTask]07-02 01:38:27.719 3623 3636 I wm_task_moved: [6,1,0]07-02 01:38:27.722 3623 3636 I am_create_task: [0,7]07-02 01:38:27.722 3623 3636 I am_create_activity: [0,224793551,7,com.android.settings/.Settings,android.intent.action.MAIN,NULL,NULL,807403520]07-02 01:38:27.723 3623 3636 I wm_task_created: [7,1]07-02 01:38:27.723 3623 3636 I wm_task_moved: [7,1,1]07-02 01:38:27.724 3623 3636 I am_pause_activity: [0,59336324,com.bbk.launcher2/.Launcher]07-02 01:38:27.728 3623 3636 I am_home_stack_moved: [0,0,1,1,startedActivity setFocusedActivity]07-02 01:38:27.728 3623 3636 I wm_task_moved: [7,1,1]07-02 01:38:27.735 3623 3636 I am_focused_activity: [0,com.android.settings/.Settings]07-02 01:38:27.746 4621 4621 I am_on_paused_called: [0,com.bbk.launcher2.Launcher]07-02 01:38:27.751 3623 4576 I am_restart_activity: [0,224793551,7,com.android.settings/.Settings]07-02 01:38:28.062 3623 3666 I am_activity_launch_time: [0,224793551,com.android.settings/.Settings,315,315]通过字面意思，就能得到不少信息量，比如am_create_activity，创建activity，但是后面括号中内容的具体含义，其实有很高的价值。既然Event日志辣么辣么重要，辣么Event日志是如何打印的呢？
在Android源码中，是通过如下语句打印出event日志的：（这里我以ActivityStackSupervisor.java文件说明，其它文件方法一样）
...import android.util.EventLog;...public final class ActivityStackSupervisor implements DisplayListener { ... void moveHomeStack(boolean toFront, String reason, ActivityStack lastFocusedStack) { ... EventLog.writeEvent(EventLogTags.AM_HOME_STACK_MOVED, mCurrentUser, toFront ? 1 : 0, stacks.get(topNdx).getStackId(), mFocusedStack == null ? -1 : mFocusedStack.getStackId(), reason); ... } ...}EventLog.writeEvent android_util_EventLog_writeEvent_Array //android_util_EventLog.cpp android_bWriteLog // system/core/include/log/Log.h在使用上很简单，但是其具体的实现的话，那就需要研究一下源码了。这里先来看看event tag吧。
1. Event TAG
[===>frameworks/base/core/java/android/util/EventLog.java]
public class EventLog { //代替frameworks/base/core/java/android/util/EventLogTags.java文件 /** @hide */ public EventLog() {} private static final String TAG = "EventLog"; private static final String TAGS_FILE = "/system/etc/event-log-tags"; private static final String COMMENT_PATTERN = "^\\s*(#.*)?$"; private static final String TAG_PATTERN = "^\\s*(\\d+)\\s+(\\w+)\\s*(\\(.*\\))?\\s*$"; private static HashMap sTagCodes = null; private static HashMap sTagNames = null; /** A previously logged event read from the logs. Instances are thread safe. */ public static final class Event { ... } public static native int writeEvent(int tag, int value); public static native int writeEvent(int tag, long value); public static native int writeEvent(int tag, float value); public static native int writeEvent(int tag, String str); public static native int writeEvent(int tag, Object... list); public static native void readEvents(int[] tags, Collection output) throws IOException; public static String getTagName(int tag) { readTagsFile(); return sTagNames.get(tag); } /** * Get the event type tag code associated with an event name. * @param name of event to look up * @return the tag code, or -1 if no tag has that name */ public static int getTagCode(String name) { readTagsFile(); ... } /** * Read TAGS_FILE, populating sTagCodes and sTagNames, if not already done. */ private static synchronized void readTagsFile() { if (sTagCodes != null && sTagNames != null) return; sTagCodes = new HashMap(); sTagNames = new HashMap(); Pattern comment = Pattern.compile(COMMENT_PATTERN); Pattern tag = Pattern.compile(TAG_PATTERN); BufferedReader reader = null; String line; try { reader = new BufferedReader(new FileReader(TAGS_FILE), 256); while ((line = reader.readLine()) != null) { if (comment.matcher(line).matches()) continue; Matcher m = tag.matcher(line); if (!m.matches()) { Log.wtf(TAG, "Bad entry in " + TAGS_FILE + ": " + line); continue; } try { int num = Integer.parseInt(m.group(1)); String name = m.group(2); sTagCodes.put(name, num); sTagNames.put(num, name); } catch (NumberFormatException e) { Log.wtf(TAG, "Error in " + TAGS_FILE + ": " + line, e); } } } catch (IOException e) { Log.wtf(TAG, "Error reading " + TAGS_FILE, e); // Leave the maps existing but unpopulated } finally { try { if (reader != null) reader.close(); } catch (IOException e) {} } }} 注意到public类EventLog中的所有变量、接口、内部类及内部类的所有变量、接口都是static静态的，因此，在构造EventLog类的时候，这些static接口都会被执行一遍。
Event Tag是通过readTagsFile读取解析/system/etc/event-log-tags文件内容，并将相关信息保存在sTagCodes、sTagNames两个HashMap中，其中sTagNames存储的是Tag Name。
在代码中，有多处地方都可以有EventLogTags.logtags文件：
******@******:~/Google_7.0.0$ find -name "EventLogTags.logtags"./frameworks/native/services/surfaceflinger/EventLog/EventLogTags.logtags./frameworks/base/core/java/android/speech/tts/EventLogTags.logtags./frameworks/base/core/java/android/content/EventLogTags.logtags./frameworks/base/core/java/android/webkit/EventLogTags.logtags./frameworks/base/core/java/com/android/internal/logging/EventLogTags.logtags./frameworks/base/packages/SettingsProvider/src/com/android/providers/settings/EventLogTags.logtags./frameworks/base/packages/SystemUI/src/com/android/systemui/EventLogTags.logtags./frameworks/base/services/core/java/com/android/server/EventLogTags.logtags./frameworks/base/services/core/java/com/android/server/am/EventLogTags.logtags./frameworks/opt/telephony/src/java/com/android/internal/telephony/EventLogTags.logtags./system/core/libsysutils/EventLogTags.logtags./packages/apps/Settings/src/com/android/settings/EventLogTags.logtags./packages/apps/QuickSearchBox/src/com/android/quicksearchbox/EventLogTags.logtags./packages/providers/CalendarProvider/src/com/android/providers/calendar/EventLogTags.logtags./packages/providers/ContactsProvider/src/com/android/providers/contacts/EventLogTags.logtags./packages/services/Telephony/src/com/android/phone/EventLogTags.logtags python脚本build/tools/java-event-log-tags.py则负责将EventLogTags.logtags以及调用转化为java文件，或者是将java文件中的writeEvent调用转为标准的java调用，以及生成system/etc/event-log-tags文件(对于使用来说，分析这个python文件没有多大意义)。
以frameworks/base/services/core/java/com/android/server/am/EventLogTags.logtags文件为例，该文件编译过程中通过python脚本生成的对应java文件在out目录中：
out/target/common/obj/JAVA_LIBRARIES/services.core_intermediates/src/com/android/server/am/EventLogTags.java下面看看logcat -b events是怎么读取并显示event log的：
int main(int argc, char **argv){ using namespace android; ... for (;;) { int ret; ... ret = getopt_long(argc, argv, ":cdDLt:T:gG:sQf:r:n:v:b:BSpP:m:e:", long_options, &option_index); if (ret < 0) { break; } switch (ret) { ... case 'b': { if (strcmp(optarg, "default") == 0) { ... break; } if (strcmp(optarg, "all") == 0) { ... break; } bool binary = !(strcmp(optarg, "events") && strcmp(optarg, "security")); if (devices) { dev = devices; while (dev->next) { if (!strcmp(optarg, dev->device)) { dev = NULL; break; } dev = dev->next; } if (dev) { dev->next = new log_device_t(optarg, binary); } } else { devices = new log_device_t(optarg, binary); } g_devCount++; } break; case 'B': g_printBinary = 1; break; ... default: logcat_panic(true, "Unrecognized Option %c\n", optopt); break; } } ... if (g_logRotateSizeKBytes != 0 && g_outputFileName == NULL) { logcat_panic(true, "-r requires -f as well\n"); } setupOutput(); if (hasSetLogFormat == 0) { const char* logFormat = getenv("ANDROID_PRINTF_LOG"); if (logFormat != NULL) { err = setLogFormat(logFormat); if (err < 0) { fprintf(stderr, "invalid format in ANDROID_PRINTF_LOG '%s'\n", logFormat); } } else { setLogFormat("threadtime"); } } if (forceFilters) { err = android_log_addFilterString(g_logformat, forceFilters); if (err < 0) { logcat_panic(false, "Invalid filter expression in logcat args\n"); } } else if (argc == optind) { // Add from environment variable char *env_tags_orig = getenv("ANDROID_LOG_TAGS"); if (env_tags_orig != NULL) { err = android_log_addFilterString(g_logformat, env_tags_orig); if (err < 0) { logcat_panic(true, "Invalid filter expression in ANDROID_LOG_TAGS\n"); } } } else { // Add from commandline for (int i = optind ; i < argc ; i++) { err = android_log_addFilterString(g_logformat, argv[i]); if (err < 0) { logcat_panic(true, "Invalid filter expression '%s'\n", argv[i]); } } } dev = devices; if (tail_time != log_time::EPOCH) { logger_list = android_logger_list_alloc_time(mode, tail_time, pid); } else { logger_list = android_logger_list_alloc(mode, tail_lines, pid); } const char *openDeviceFail = NULL; const char *clearFail = NULL; const char *setSizeFail = NULL; const char *getSizeFail = NULL; // We have three orthogonal actions below to clear, set log size and // get log size. All sharing the same iteration loop. while (dev) { ... dev = dev->next; } // report any errors in the above loop and exit if (printStatistics || getPruneList) { size_t len = 8192; char *buf; for (int retry = 32; (retry >= 0) && ((buf = new char [len])); delete [] buf, buf = NULL, --retry) { if (getPruneList) { android_logger_get_prune_list(logger_list, buf, len); } else { android_logger_get_statistics(logger_list, buf, len); } buf[len-1] = '\0'; if (atol(buf) < 3) { delete [] buf; buf = NULL; break; } size_t ret = atol(buf) + 1; if (ret <= len) { len = ret; break; } len = ret; } if (!buf) { logcat_panic(false, "failed to read data"); } // remove trailing FF char *cp = buf + len - 1; *cp = '\0'; bool truncated = *--cp != '\f'; if (!truncated) { *cp = '\0'; } // squash out the byte count cp = buf; if (!truncated) { while (isdigit(*cp)) { ++cp; } if (*cp == '\n') { ++cp; } } printf("%s", cp); delete [] buf; return EXIT_SUCCESS; } dev = NULL; log_device_t unexpected("unexpected", false); while (!g_maxCount || (g_printCount < g_maxCount)) { ... if (g_printBinary) { ... } else { processBuffer(dev, &log_msg); } } android_logger_list_free(logger_list); return EXIT_SUCCESS;}在system/core/logcat/logcat.cpp的main函数里头，如果参数带-b events的话，g_printBinary为false，binary会是true，然后回去读取event tag maps：
android::g_eventTagMap = android_openEventTagMap(EVENT_TAG_MAP_FILE);
其中是EVENT_TAG_MAP_FILE就是system/etc/event-log-tags。
ActivityManager
[===>frameworks/base/services/core/java/com/android/server/am/EventLogTags.logtags]
# See system/core/logcat/event.logtags for a description of the format of this file.option java_package com.android.server.am2719 configuration_changed (config mask|1|5)2721 cpu (total|1|6),(user|1|6),(system|1|6),(iowait|1|6),(irq|1|6),(softirq|1|6)# ActivityManagerService.systemReady() starts:3040 boot_progress_ams_ready (time|2|3)# ActivityManagerService calls enableScreenAfterBoot():3050 boot_progress_enable_screen (time|2|3)# Do not change these names without updating the checkin_events setting in# google3/googledata/wireless/android/provisioning/gservices.config !!## An activity is being finished:30001 am_finish_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3),(Reason|3)# A task is being brought to the front of the screen:30002 am_task_to_front (User|1|5),(Task|1|5)# An existing activity is being given a new intent:30003 am_new_intent (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3),(Action|3),(MIME Type|3),(URI|3),(Flags|1|5)# A new task is being created:30004 am_create_task (User|1|5),(Task ID|1|5)# A new activity is being created in an existing task: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)# An activity has been resumed into the foreground but was not already running:30006 am_restart_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3)# An activity has been resumed and is now in the foreground:30007 am_resume_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3)# Application Not Responding30008 am_anr (User|1|5),(pid|1|5),(Package Name|3),(Flags|1|5),(reason|3)# Activity launch time30009 am_activity_launch_time (User|1|5),(Token|1|5),(Component Name|3),(time|2|3)# Application process bound to work30010 am_proc_bound (User|1|5),(PID|1|5),(Process Name|3)# Application process died30011 am_proc_died (User|1|5),(PID|1|5),(Process Name|3)# The Activity Manager failed to pause the given activity.30012 am_failed_to_pause (User|1|5),(Token|1|5),(Wanting to pause|3),(Currently pausing|3)# Attempting to pause the current activity30013 am_pause_activity (User|1|5),(Token|1|5),(Component Name|3)# Application process has been started30014 am_proc_start (User|1|5),(PID|1|5),(UID|1|5),(Process Name|3),(Type|3),(Component|3)# An application process has been marked as bad30015 am_proc_bad (User|1|5),(UID|1|5),(Process Name|3)# An application process that was bad is now marked as good30016 am_proc_good (User|1|5),(UID|1|5),(Process Name|3)# Reporting to applications that memory is low30017 am_low_memory (Num Processes|1|1)# An activity is being destroyed:30018 am_destroy_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3),(Reason|3)# An activity has been relaunched, resumed, and is now in the foreground:30019 am_relaunch_resume_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3)# An activity has been relaunched:30020 am_relaunch_activity (User|1|5),(Token|1|5),(Task ID|1|5),(Component Name|3)# The activity's onPause has been called.30021 am_on_paused_called (User|1|5),(Component Name|3)# The activity's onResume has been called.30022 am_on_resume_called (User|1|5),(Component Name|3)# Kill a process to reclaim memory.30023 am_kill (User|1|5),(PID|1|5),(Process Name|3),(OomAdj|1|5),(Reason|3)# Discard an undelivered serialized broadcast (timeout/ANR/crash)30024 am_broadcast_discard_filter (User|1|5),(Broadcast|1|5),(Action|3),(Receiver Number|1|1),(BroadcastFilter|1|5)30025 am_broadcast_discard_app (User|1|5),(Broadcast|1|5),(Action|3),(Receiver Number|1|1),(App|3)# A service is being created30030 am_create_service (User|1|5),(Service Record|1|5),(Name|3),(UID|1|5),(PID|1|5)# A service is being destroyed30031 am_destroy_service (User|1|5),(Service Record|1|5),(PID|1|5)# A process has crashed too many times, it is being cleared30032 am_process_crashed_too_much (User|1|5),(Name|3),(PID|1|5)# An unknown process is trying to attach to the activity manager30033 am_drop_process (PID|1|5)# A service has crashed too many times, it is being stopped30034 am_service_crashed_too_much (User|1|5),(Crash Count|1|1),(Component Name|3),(PID|1|5)# A service is going to be restarted after its process went away30035 am_schedule_service_restart (User|1|5),(Component Name|3),(Time|2|3)# A client was waiting for a content provider, but its process was lost30036 am_provider_lost_process (User|1|5),(Package Name|3),(UID|1|5),(Name|3)# The activity manager gave up on a new process taking too long to start30037 am_process_start_timeout (User|1|5),(PID|1|5),(UID|1|5),(Process Name|3)# Unhandled exception30039 am_crash (User|1|5),(PID|1|5),(Process Name|3),(Flags|1|5),(Exception|3),(Message|3),(File|3),(Line|1|5)# Log.wtf() called30040 am_wtf (User|1|5),(PID|1|5),(Process Name|3),(Flags|1|5),(Tag|3),(Message|3)# User switched30041 am_switch_user (id|1|5)# Activity fully drawn time30042 am_activity_fully_drawn_time (User|1|5),(Token|1|5),(Component Name|3),(time|2|3)# Activity focused30043 am_focused_activity (User|1|5),(Component Name|3)# Home Stack brought to front or rear30044 am_home_stack_moved (User|1|5),(To Front|1|5),(Top Stack Id|1|5),(Focused Stack Id|1|5),(Reason|3)# Running pre boot receiver30045 am_pre_boot (User|1|5),(Package|3)# Report collection of global memory state30046 am_meminfo (CachedKb|2|2),(FreeKb|2|2),(ZramKb|2|2),(KernelKb|2|2),(NativeKb|2|2)# Report collection of memory used by a process30047 am_pss (Pid|1|5),(UID|1|5),(Process Name|3),(PssKb|2|2),(UssKb|2|2)system/core/logcat/event.logtags部分文件
# 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.## Tag numbers are decimal integers, from 0 to 2^31. (Let's leave the# negative values alone for now.)## Tag names are one or more ASCII letters and numbers or underscores, i.e.# "[A-Z][a-z][0-9]_". Do not include spaces or punctuation (the former# impacts log readability, the latter makes regex searches more annoying).## Tag numbers and names are separated by whitespace. Blank lines and lines# starting with '#' are ignored.## Optionally, after the tag names can be put a description for the value(s)# of the tag. Description are in the format# (|data type[|data unit]) # Multiple values are separated by commas.## The data type is a number from the following values:# 1: int# 2: long# 3: string# 4: list# 5: float## The data unit is a number taken from the following list:# 1: Number of objects# 2: Number of bytes# 3: Number of milliseconds# 4: Number of allocations# 5: Id# 6: Percent# Default value for data of type int/long is 2 (bytes).## TODO: generate ".java" and ".h" files with integer constants from this file.(
| data type | 数据类型 |
|---|---|
| 1 | int |
| 2 | long |
| 3 | string |
| 4 | list |
| 5 | float |
| data unit | 数据单位 |
|---|---|
| 1 | Number of objects |
| 2 | Number of bytes |
| 3 | Number of milliseconds |
| 4 | Number of allocations |
| 5 | Id |
| 6 | Percent |
光这么说，可能比较模糊，已具体的event日志来说明。
07-02 11:23:09.712 933 1870 I am_pause_activity: [0,123715054,com.XXX.launcher2/.Launcher]结合EventLogTags.logtags文件中关于am_pause_activity的信息
# Attempting to pause the current activity30013 am_pause_activity (User|1|5),(Token|1|5),(Component Name|3)我们可以知道该event日志描述的是:com.XXX.launcher2/.Launcher被pause，User Id为0(int类型)，Token Id为123715054(int类型)，Component name为com.XXX.launcher2/.Launcher。
更多相关文章
- Android(安卓)实用技巧 --- 命令godir
- android eclipse xml不自动代码提示
- Android(安卓)Studio自动生成带系统签名的apk
- android音频编辑之音频合成
- 深入分析Android(安卓)(build/core/*.mk脚本)
- Android(安卓)WiFi Direct文件传输
- 使用TraceView进行方法跟踪
- Android中的文件扫描
- Android(安卓)java.lang.NoClassDefFoundError:*报错的处理