Android event日誌列印原理
阿新 • • 發佈：2019-01-25
基於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 通過字面意思，就能得到不少資訊量，比如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<String, Integer> sTagCodes = null;
private static HashMap<Integer, String> 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<Event> 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<String, Integer>();
sTagNames = new HashMap<Integer, String>();
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.am
2719 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 Responding
30008 am_anr (User|1|5),(pid|1|5),(Package Name|3),(Flags|1|5),(reason|3)
# Activity launch time
30009 am_activity_launch_time (User|1|5),(Token|1|5),(Component Name|3),(time|2|3)
# Application process bound to work
30010 am_proc_bound (User|1|5),(PID|1|5),(Process Name|3)
# Application process died
30011 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 activity
30013 am_pause_activity (User|1|5),(Token|1|5),(Component Name|3)
# Application process has been started
30014 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 bad
30015 am_proc_bad (User|1|5),(UID|1|5),(Process Name|3)
# An application process that was bad is now marked as good
30016 am_proc_good (User|1|5),(UID|1|5),(Process Name|3)
# Reporting to applications that memory is low
30017 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 created
30030 am_create_service (User|1|5),(Service Record|1|5),(Name|3),(UID|1|5),(PID|1|5)
# A service is being destroyed
30031 am_destroy_service (User|1|5),(Service Record|1|5),(PID|1|5)
# A process has crashed too many times, it is being cleared
30032 am_process_crashed_too_much (User|1|5),(Name|3),(PID|1|5)
# An unknown process is trying to attach to the activity manager
30033 am_drop_process (PID|1|5)
# A service has crashed too many times, it is being stopped
30034 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 away
30035 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 lost
30036 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 start
30037 am_process_start_timeout (User|1|5),(PID|1|5),(UID|1|5),(Process Name|3)
# Unhandled exception
30039 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() called
30040 am_wtf (User|1|5),(PID|1|5),(Process Name|3),(Flags|1|5),(Tag|3),(Message|3)
# User switched
30041 am_switch_user (id|1|5)
# Activity fully drawn time
30042 am_activity_fully_drawn_time (User|1|5),(Token|1|5),(Component Name|3),(time|2|3)
# Activity focused
30043 am_focused_activity (User|1|5),(Component Name|3)
# Home Stack brought to front or rear
30044 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 receiver
30045 am_pre_boot (User|1|5),(Package|3)
# Report collection of global memory state
30046 am_meminfo (CachedKb|2|2),(FreeKb|2|2),(ZramKb|2|2),(KernelKb|2|2),(NativeKb|2|2)
# Report collection of memory used by a process
30047 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
# (<name>|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.(<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 |
| 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 activity
30013 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。