android log机制 输出log,Android log 机制 - logd 如何接收 log 数据（下）
写入 log 数据时，我们先通过 socket 读取客户端 log，然后调用 logBuffer->log 函数写入 log 缓冲并唤醒读 log 的客户端。由于每种类型的 log 数据都有总量限制，写入数据后可能需要删除旧数据。由于篇幅关系，删除旧数据这一部分下一篇再讲。
读取数据
上一篇中我们知道，当有数据可读的时候，SocketListener 会回调子类的 onDataAvailable()。对于 LogListener 来说，就是在这个函数里面完成对 log 的读取的。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78// system/core/logd/LogListener.cpp
bool LogListener::onDataAvailable(SocketClient* cli) {
static bool name_set;
if (!name_set) {
prctl(PR_SET_NAME, "logd.writer");
name_set = true;
}
char buffer[sizeof_log_id_t + sizeof(uint16_t) + sizeof(log_time) +
LOGGER_ENTRY_MAX_PAYLOAD];
struct iovec iov = { buffer, sizeof(buffer) };
alignas(4) char control[CMSG_SPACE(sizeof(struct ucred))];
struct msghdr hdr = {
NULL, 0, &iov, 1, control, sizeof(control), 0,
};
int socket = cli->getSocket();
// To clear the entire buffer is secure/safe, but this contributes to 1.68%
// overhead under logging load. We are safe because we check counts.
// memset(buffer, 0, sizeof(buffer));
ssize_t n = recvmsg(socket, &hdr, 0);
if (n <= (ssize_t)(sizeof(android_log_header_t))) {
return false;
}
struct ucred* cred = NULL;
struct cmsghdr* cmsg = CMSG_FIRSTHDR(&hdr);
while (cmsg != NULL) {
if (cmsg->cmsg_level == SOL_SOCKET &&
cmsg->cmsg_type == SCM_CREDENTIALS) {
cred = (struct ucred*)CMSG_DATA(cmsg);
break;
}
cmsg = CMSG_NXTHDR(&hdr, cmsg);
}
if (cred == NULL) {
return false;
}
if (cred->uid == AID_LOGD) {
// ignore log messages we send to ourself.
// Such log messages are often generated by libraries we depend on
// which use standard Android logging.
return false;
}
android_log_header_t* header =
reinterpret_cast(buffer);
if (/* header->id < LOG_ID_MIN || */ header->id >= LOG_ID_MAX ||
header->id == LOG_ID_KERNEL) {
return false;
}
if ((header->id == LOG_ID_SECURITY) &&
(!__android_log_security() ||
!clientHasLogCredentials(cred->uid, cred->gid, cred->pid))) {
return false;
}
char* msg = ((char*)buffer) + sizeof(android_log_header_t);
n -= sizeof(android_log_header_t);
// NB: hdr.msg_flags & MSG_TRUNC is not tested, silently passing a
// truncated message to the logs.
if (logbuf->log((log_id_t)header->id, header->realtime, cred->uid,
cred->pid, header->tid, msg,
((size_t)n <= USHRT_MAX) ? (unsigned short)n : USHRT_MAX) >=
0) {
reader->notifyNewLog();
}
return true;
}
prctl 系统调用用于设置进程相关的一些东西。这里使用 PR_SET_NAME 设置了线程的名字为 logd.writer。
接下来使用 recvmsg 从 socket 里读取数据。对网络编程不熟悉的读者，可以参考 《UNIX 网络编程》，卷1。需要注意的是，LogListener 创建的 socket 是 dgram，客户不需要连接。传递给 onDataAvailable() 的这个 socket，就是我们自己创建的那一个。
由于我们创建 socket 时打开了 SO_PASSCRED 选项，这里我们可以读取一个用于表示客户端身份的 struct ucred。
执行一些基本判断后，调用 logbuf->log 将数据写入 LogBuffer。
此时可能有客户端在等待读取数据，于是也调用 reader->notifyNewLog()。关于 LogReader，后面我们再讨论。下面看 LogBuffer 的 log 函数。
写入 LogBuffer
log 的写入主要是一下 4 个步骤：
根据 tag 和优先级判断该 log 是否可以写入
使用一个状态机去除重复的 log
写入 log
如果需要，删除一些 log 以避免 log 数据过多
下面我们一步一步来看。
1. 根据 tag 和优先级判断该 log 是否可以写入1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31// system/core/logd/LogBuffer.cpp
int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
pid_t tid, const char* msg, unsigned short len) {
if ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
return -EINVAL;
}
LogBufferElement* elem =
new LogBufferElement(log_id, realtime, uid, pid, tid, msg, len);
if (log_id != LOG_ID_SECURITY) {
int prio = ANDROID_LOG_INFO;
const char* tag = nullptr;
if (log_id == LOG_ID_EVENTS) {
tag = tagToName(elem->getTag());
} else {
prio = *msg;
tag = msg + 1;
}
if (!__android_log_is_loggable(prio, tag, ANDROID_LOG_VERBOSE)) {
// Log traffic received to total
pthread_mutex_lock(&mLogElementsLock);
stats.add(elem);
stats.subtract(elem);
pthread_mutex_unlock(&mLogElementsLock);
delete elem;
return -EACCES;
}
}
// ...
}
这里唯一需要注意的是，如果 log_id 是 LOG_ID_EVENTS，优先级 prio == ANDROID_LOG_INFO。
2. 使用一个状态机去除重复的 log
状态机这部分是最复杂的，幸运的是，程序员已经帮我们写好了注释，看看注释，知道它做了什么就好。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154// system/core/logd/LogBuffer.cpp
int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
pid_t tid, const char* msg, unsigned short len) {
// ...
pthread_mutex_lock(&mLogElementsLock);
LogBufferElement* currentLast = lastLoggedElements[log_id];
if (currentLast) {
LogBufferElement* dropped = droppedElements[log_id];
unsigned short count = dropped ? dropped->getDropped() : 0;
//
// State Init
// incoming:
// dropped = nullptr
// currentLast = nullptr;
// elem = incoming message
// outgoing:
// dropped = nullptr -> State 0
// currentLast = copy of elem
// log elem
// State 0
// incoming:
// count = 0
// dropped = nullptr
// currentLast = copy of last message
// elem = incoming message
// outgoing: if match != DIFFERENT
// dropped = copy of first identical message -> State 1
// currentLast = reference to elem
// break: if match == DIFFERENT
// dropped = nullptr -> State 0
// delete copy of last message (incoming currentLast)
// currentLast = copy of elem
// log elem
// State 1
// incoming:
// count = 0
// dropped = copy of first identical message
// currentLast = reference to last held-back incoming
// message
// elem = incoming message
// outgoing: if match == SAME
// delete copy of first identical message (dropped)
// dropped = reference to last held-back incoming
// message set to chatty count of 1 -> State 2
// currentLast = reference to elem
// outgoing: if match == SAME_LIBLOG
// dropped = copy of first identical message -> State 1
// take sum of currentLast and elem
// if sum overflows:
// log currentLast
// currentLast = reference to elem
// else
// delete currentLast
// currentLast = reference to elem, sum liblog.
// break: if match == DIFFERENT
// delete dropped
// dropped = nullptr -> State 0
// log reference to last held-back (currentLast)
// currentLast = copy of elem
// log elem
// State 2
// incoming:
// count = chatty count
// dropped = chatty message holding count
// currentLast = reference to last held-back incoming
// message.
// dropped = chatty message holding count
// elem = incoming message
// outgoing: if match != DIFFERENT
// delete chatty message holding count
// dropped = reference to last held-back incoming
// message, set to chatty count + 1
// currentLast = reference to elem
// break: if match == DIFFERENT
// log dropped (chatty message)
// dropped = nullptr -> State 0
// log reference to last held-back (currentLast)
// currentLast = copy of elem
// log elem
//
enum match_type match = identical(elem, currentLast);
if (match != DIFFERENT) {
if (dropped) {
// Sum up liblog tag messages?
if ((count == 0) /* at Pass 1 */ && (match == SAME_LIBLOG)) {
android_log_event_int_t* event =
reinterpret_cast(
const_cast(currentLast->getMsg()));
//
// To unit test, differentiate with something like:
// event->header.tag = htole32(CHATTY_LOG_TAG);
// here, then instead of delete currentLast below,
// log(currentLast) to see the incremental sums form.
//
uint32_t swab = event->payload.data;
unsigned long long total = htole32(swab);
event = reinterpret_cast(
const_cast(elem->getMsg()));
swab = event->payload.data;
lastLoggedElements[LOG_ID_EVENTS] = elem;
total += htole32(swab);
// check for overflow
if (total >= UINT32_MAX) {
log(currentLast);
pthread_mutex_unlock(&mLogElementsLock);
return len;
}
stats.add(currentLast);
stats.subtract(currentLast);
delete currentLast;
swab = total;
event->payload.data = htole32(swab);
pthread_mutex_unlock(&mLogElementsLock);
return len;
}
if (count == USHRT_MAX) {
log(dropped);
count = 1;
} else {
delete dropped;
++count;
}
}
if (count) {
stats.add(currentLast);
stats.subtract(currentLast);
currentLast->setDropped(count);
}
droppedElements[log_id] = currentLast;
lastLoggedElements[log_id] = elem;
pthread_mutex_unlock(&mLogElementsLock);
return len;
}
if (dropped) { // State 1 or 2
if (count) { // State 2
log(dropped); // report chatty
} else { // State 1
delete dropped;
}
droppedElements[log_id] = nullptr;
log(currentLast); // report last message in the series
} else { // State 0
delete currentLast;
}
}
lastLoggedElements[log_id] = new LogBufferElement(*elem);
log(elem);
pthread_mutex_unlock(&mLogElementsLock);
return len;
}
可以看到，实际的 log 写入动作，是由另一个 log 函数来完成的。
3. 写入 log1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63// system/core/logd/LogBuffer.cpp
// assumes mLogElementsLock held, owns elem, will look after garbage collection
void LogBuffer::log(LogBufferElement* elem) {
// cap on how far back we will sort in-place, otherwise append
static uint32_t too_far_back = 5; // five seconds
// Insert elements in time sorted order if possible
// NB: if end is region locked, place element at end of list
LogBufferElementCollection::iterator it = mLogElements.end();
LogBufferElementCollection::iterator last = it;
// 让 it 指向列表的最后一个元素
if (__predict_true(it != mLogElements.begin())) --it;
if (__predict_false(it == mLogElements.begin()) ||
__predict_true((*it)->getRealTime() <= elem->getRealTime()) ||
__predict_false((((*it)->getRealTime().tv_sec - too_far_back) >
elem->getRealTime().tv_sec) &&
(elem->getLogId() != LOG_ID_KERNEL) &&
((*it)->getLogId() != LOG_ID_KERNEL))) {
mLogElements.push_back(elem);
} else {
log_time end = log_time::EPOCH;
bool end_set = false;
bool end_always = false;
LogTimeEntry::lock();
LastLogTimes::iterator times = mTimes.begin();
while (times != mTimes.end()) {
LogTimeEntry* entry = (*times);
if (entry->owned_Locked()) {
if (!entry->mNonBlock) {
end_always = true;
break;
}
// it passing mEnd is blocked by the following checks.
if (!end_set || (end <= entry->mEnd)) {
end = entry->mEnd;
end_set = true;
}
}
times++;
}
if (end_always || (end_set && (end > (*it)->getRealTime()))) {
mLogElements.push_back(elem);
} else {
// should be short as timestamps are localized near end()
do {
last = it;
if (__predict_false(it == mLogElements.begin())) {
break;
}
--it;
} while (((*it)->getRealTime() > elem->getRealTime()) &&
(!end_set || (end <= (*it)->getRealTime())));
mLogElements.insert(last, elem);
}
LogTimeEntry::unlock();
}
stats.add(elem);
maybePrune(elem->getLogId());
}
__predict_true 和 __predict_false 用来提示编译器对应的判断很可能是 true/false，类似于 Linux 内核的 likely/unlikely。如果判断正确，可以得到很大的性能提升。
客户端使用 Unix-domain socket 来写入 log，读出来的时候，很可能就已经按时间顺序排好，这个时候，只需要把 LogBufferElement 插入列表末尾就可以了。
万一很不幸的，上面的判断失败了，就只能从后往前遍历列表，找到一个合适的位置来插入 LogBufferElement。这个过程类似于插入排序。
关于 mTimes，后面我们看 LogReader 的时候还会再详细分析它，现在我们只需要知道，一个读客户端对应着 mTimes 里的一项。当对应的客户端在读 log 时，entry->owned_Locked() 返回 true。
如果 !entry->mNonBlock 为真，说明有客户端在阻塞地读取 log，此时我们只能把新的 log 放入列表的末尾。考虑这样一种比较极端的情况，它已经读取了所有的 log 并等待新的 log，我们又没有把新的 log 放入列表的末尾，就会导致客户端无法读取新写入的这条 log，毕竟，此时它应该读列表最后面的 log。
另一种和上面类似的情形是，有客户端在读 log，并且它读到的最后一条 log 已经超过了我们正要写入的 log。此时最简单的做法就是把新 log 放到末尾，这样客户才能读取到新写入的 log。
4. 如果需要，删除一些 log 以避免 log 数据过多
添加 log 后，调用 maybePrune，根据 log 总量判断是否需要删除一些 log。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29// system/core/logd/LogBuffer.cpp
// Prune at most 10% of the log entries or maxPrune, whichever is less.
//
// mLogElementsLock must be held when this function is called.
void LogBuffer::maybePrune(log_id_t id) {
size_t sizes = stats.sizes(id);
unsigned long maxSize = log_buffer_size(id);
if (sizes > maxSize) {
size_t sizeOver = sizes - ((maxSize * 9) / 10);
size_t elements = stats.realElements(id);
size_t minElements = elements / 100;
if (minElements < minPrune) {
minElements = minPrune;
}
unsigned long pruneRows = elements * sizeOver / sizes;
if (pruneRows < minElements) {
pruneRows = minElements;
}
if (pruneRows > maxPrune) {
pruneRows = maxPrune;
}
prune(id, pruneRows);
}
}
// system/core/logd/LogBuffer.h
static constexpr size_t minPrune = 4;
static constexpr size_t maxPrune = 256;
如果 id 类型的 log 超过了总量限制，就删除 10% 的 log。在这个前提下，所删除的 log 调试大于 minElements 和 minPrune，小于 maxPrune。
其中，minElements 是所有 id 类型的 log 的总条数的百分之一。
当每条 log 都很大、log 总量又很小，限制最小值可以避免总是需要剔除旧 log。如果 log 每条很小，限制最大数目可以避免删除过多的 log。
实际的删除工作由 prune 方法完成，由于篇幅关系，prune 单独作为一篇，后面再来了解。它的实现并不影响 log 写入逻辑，log 的写入到这里就算告一段落。