openkylin
/
platform_system_core
mirror of https://gitee.com/openkylin/platform_system_core.git
9
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge "logd: record multiple duplicate messages as chatty" 

am: d0ee73932f

Change-Id: I4e3d6695d33f01b066bb9706e77daf7223f3ab11
This commit is contained in:
Mark Salyzyn 2016-12-16 22:16:56 +00:00 committed by android-build-merger
parent 9e9c49f2d8 d0ee73932f
commit ad3f07d25e
10 changed files with 262 additions and 42 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

4
logd/LogAudit.cpp
View File

@ -34,6 +34,7 @@
#include "LogBuffer.h"
#include "LogKlog.h"
#include "LogReader.h"
#include "LogUtils.h"
#define KMSG_PRIORITY(PRI) \
'<', \
@ -117,7 +118,8 @@ int LogAudit::logPrint(const char *fmt, ...) {
if (avcl) {
char *avcr = strstr(str, avc);
skip = avcr && !strcmp(avcl + strlen(avc), avcr + strlen(avc));
skip = avcr && !fastcmp<strcmp>(avcl + strlen(avc),
avcr + strlen(avc));
if (skip) {
++count;
free(last_str);

111
logd/LogBuffer.cpp
View File

@ -33,6 +33,7 @@
#include "LogBuffer.h"
#include "LogKlog.h"
#include "LogReader.h"
#include "LogUtils.h"
#ifndef __predict_false
#define __predict_false(exp) __builtin_expect((exp) != 0, 0)
@ -110,9 +111,65 @@ LogBuffer::LogBuffer(LastLogTimes *times):
mTimes(*times) {
pthread_mutex_init(&mLogElementsLock, NULL);
log_id_for_each(i) {
lastLoggedElements[i] = NULL;
droppedElements[i] = NULL;
}
init();
}
LogBuffer::~LogBuffer() {
log_id_for_each(i) {
delete lastLoggedElements[i];
delete droppedElements[i];
}
}
static bool identical(LogBufferElement* elem, LogBufferElement* last) {
// is it mostly identical?
// if (!elem) return false;
unsigned short lenl = elem->getMsgLen();
if (!lenl) return false;
// if (!last) return false;
unsigned short lenr = last->getMsgLen();
if (!lenr) return false;
// if (elem->getLogId() != last->getLogId()) return false;
if (elem->getUid() != last->getUid()) return false;
if (elem->getPid() != last->getPid()) return false;
if (elem->getTid() != last->getTid()) return false;
// last is more than a minute old, stop squashing identical messages
if (elem->getRealTime().nsec() >
(last->getRealTime().nsec() + 60 * NS_PER_SEC)) return false;
// Identical message
const char* msgl = elem->getMsg();
const char* msgr = last->getMsg();
if ((lenl == lenr) && !fastcmp<memcmp>(msgl, msgr, lenl)) return true;
// audit message (except sequence number) identical?
static const char avc[] = "): avc: ";
if (last->isBinary()) {
if (fastcmp<memcmp>(msgl, msgr,
sizeof(android_log_event_string_t) -
sizeof(int32_t))) return false;
msgl += sizeof(android_log_event_string_t);
lenl -= sizeof(android_log_event_string_t);
msgr += sizeof(android_log_event_string_t);
lenr -= sizeof(android_log_event_string_t);
}
const char *avcl = android::strnstr(msgl, lenl, avc);
if (!avcl) return false;
lenl -= avcl - msgl;
const char *avcr = android::strnstr(msgr, lenr, avc);
if (!avcr) return false;
lenr -= avcr - msgr;
if (lenl != lenr) return false;
return !fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc), lenl);
}
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) {
@ -145,14 +202,57 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
}
pthread_mutex_lock(&mLogElementsLock);
LogBufferElement* currentLast = lastLoggedElements[log_id];
if (currentLast) {
LogBufferElement *dropped = droppedElements[log_id];
unsigned short count = dropped ? dropped->getDropped() : 0;
if (identical(elem, currentLast)) {
if (dropped) {
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) {
log(dropped);
droppedElements[log_id] = NULL;
}
if (count) {
log(currentLast);
} else {
delete currentLast;
}
}
lastLoggedElements[log_id] = new LogBufferElement(*elem);
log(elem);
pthread_mutex_unlock(&mLogElementsLock);
return len;
}
// assumes mLogElementsLock held, owns elem, will look after garbage collection
void LogBuffer::log(LogBufferElement* elem) {
// 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;
while (last != mLogElements.begin()) {
--it;
if ((*it)->getRealTime() <= realtime) {
if ((*it)->getRealTime() <= elem->getRealTime()) {
break;
}
last = it;
@ -169,7 +269,7 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
LastLogTimes::iterator times = mTimes.begin();
while(times != mTimes.end()) {
LogTimeEntry *entry = (*times);
LogTimeEntry* entry = (*times);
if (entry->owned_Locked()) {
if (!entry->mNonBlock) {
end_always = true;
@ -187,17 +287,14 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
|| (end_set && (end >= (*last)->getSequence()))) {
mLogElements.push_back(elem);
} else {
mLogElements.insert(last,elem);
mLogElements.insert(last, elem);
}
LogTimeEntry::unlock();
}
stats.add(elem);
maybePrune(log_id);
pthread_mutex_unlock(&mLogElementsLock);
return len;
maybePrune(elem->getLogId());
}
// Prune at most 10% of the log entries or maxPrune, whichever is less.

5
logd/LogBuffer.h
View File

@ -99,10 +99,15 @@ class LogBuffer {
bool monotonic;
LogBufferElement* lastLoggedElements[LOG_ID_MAX];
LogBufferElement* droppedElements[LOG_ID_MAX];
void log(LogBufferElement* elem);
public:
LastLogTimes &mTimes;
explicit LogBuffer(LastLogTimes *times);
~LogBuffer();
void init();
bool isMonotonic() { return monotonic; }

15
logd/LogBufferElement.cpp
View File

@ -50,6 +50,19 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
0;
}
LogBufferElement::LogBufferElement(const LogBufferElement &elem) :
mTag(elem.mTag),
mUid(elem.mUid),
mPid(elem.mPid),
mTid(elem.mTid),
mSequence(elem.mSequence),
mRealTime(elem.mRealTime),
mMsgLen(elem.mMsgLen),
mLogId(elem.mLogId) {
mMsg = new char[mMsgLen];
memcpy(mMsg, elem.mMsg, mMsgLen);
}
LogBufferElement::~LogBufferElement() {
delete [] mMsg;
}
@ -157,8 +170,6 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer,
mDropped, (mDropped > 1) ? "s" : "");
size_t hdrLen;
// LOG_ID_SECURITY not strictly needed since spam filter not activated,
// but required for accuracy.
if (isBinary()) {
hdrLen = sizeof(android_log_event_string_t);
} else {

2
logd/LogBufferElement.h
View File

@ -59,6 +59,7 @@ public:
LogBufferElement(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, pid_t tid,
const char *msg, unsigned short len);
LogBufferElement(const LogBufferElement &elem);
virtual ~LogBufferElement();
bool isBinary(void) const {
@ -79,6 +80,7 @@ public:
return mDropped = value;
}
unsigned short getMsgLen() const { return mMsg ? mMsgLen : 0; }
const char* getMsg() const { return mMsg; }
uint64_t getSequence(void) const { return mSequence; }
static uint64_t getCurrentSequence(void) { return sequence.load(memory_order_relaxed); }
log_time getRealTime(void) const { return mRealTime; }

48
logd/LogKlog.cpp
View File

@ -306,19 +306,15 @@ static const char suspendStr[] = "PM: suspend entry ";
static const char resumeStr[] = "PM: suspend exit ";
static const char suspendedStr[] = "Suspended for ";
static const char *strnstr(const char *s, size_t len, const char *needle) {
const char* android::strnstr(const char* s, size_t len, const char* needle) {
char c;
if (!len) {
return NULL;
}
if (!len) return NULL;
if ((c = *needle++) != 0) {
size_t needleLen = strlen(needle);
do {
do {
if (len <= needleLen) {
return NULL;
}
if (len <= needleLen) return NULL;
--len;
} while (*s++ != c);
} while (fastcmp<memcmp>(s, needle, needleLen));
@ -349,25 +345,25 @@ void LogKlog::sniffTime(log_time &now,
return;
}
const char *b;
if (((b = strnstr(cp, len, suspendStr)))
const char* b;
if (((b = android::strnstr(cp, len, suspendStr)))
&& ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
len -= b - cp;
calculateCorrection(now, b, len);
} else if (((b = strnstr(cp, len, resumeStr)))
} else if (((b = android::strnstr(cp, len, resumeStr)))
&& ((size_t)((b += sizeof(resumeStr) - 1) - cp) < len)) {
len -= b - cp;
calculateCorrection(now, b, len);
} else if (((b = strnstr(cp, len, healthd)))
} else if (((b = android::strnstr(cp, len, healthd)))
&& ((size_t)((b += sizeof(healthd) - 1) - cp) < len)
&& ((b = strnstr(b, len -= b - cp, battery)))
&& ((b = android::strnstr(b, len -= b - cp, battery)))
&& ((size_t)((b += sizeof(battery) - 1) - cp) < len)) {
// NB: healthd is roughly 150us late, so we use it instead to
// trigger a check for ntp-induced or hardware clock drift.
log_time real(CLOCK_REALTIME);
log_time mono(CLOCK_MONOTONIC);
correction = (real < mono) ? log_time::EPOCH : (real - mono);
} else if (((b = strnstr(cp, len, suspendedStr)))
} else if (((b = android::strnstr(cp, len, suspendedStr)))
&& ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
len -= b - cp;
log_time real;
@ -466,18 +462,14 @@ static int parseKernelPrio(const char **buf, size_t len) {
// Passed the entire SYSLOG_ACTION_READ_ALL buffer and interpret a
// compensated start time.
void LogKlog::synchronize(const char *buf, size_t len) {
const char *cp = strnstr(buf, len, suspendStr);
void LogKlog::synchronize(const char* buf, size_t len) {
const char* cp = android::strnstr(buf, len, suspendStr);
if (!cp) {
cp = strnstr(buf, len, resumeStr);
if (!cp) {
return;
}
cp = android::strnstr(buf, len, resumeStr);
if (!cp) return;
} else {
const char *rp = strnstr(buf, len, resumeStr);
if (rp && (rp < cp)) {
cp = rp;
}
const char* rp = android::strnstr(buf, len, resumeStr);
if (rp && (rp < cp)) cp = rp;
}
do {
@ -491,7 +483,7 @@ void LogKlog::synchronize(const char *buf, size_t len) {
log_time now;
sniffTime(now, &cp, len - (cp - buf), true);
const char *suspended = strnstr(buf, len, suspendedStr);
const char* suspended = android::strnstr(buf, len, suspendedStr);
if (!suspended || (suspended > cp)) {
return;
}
@ -581,12 +573,12 @@ static const char *strnrchr(const char *s, size_t len, char c) {
// logd.klogd:
// return -1 if message logd.klogd: <signature>
//
int LogKlog::log(const char *buf, size_t len) {
if (auditd && strnstr(buf, len, " audit(")) {
int LogKlog::log(const char* buf, size_t len) {
if (auditd && android::strnstr(buf, len, " audit(")) {
return 0;
}
const char *p = buf;
const char* p = buf;
int pri = parseKernelPrio(&p, len);
log_time now;
@ -594,7 +586,7 @@ int LogKlog::log(const char *buf, size_t len) {
// sniff for start marker
const char klogd_message[] = "logd.klogd: ";
const char *start = strnstr(p, len - (p - buf), klogd_message);
const char* start = android::strnstr(p, len - (p - buf), klogd_message);
if (start) {
uint64_t sig = strtoll(start + sizeof(klogd_message) - 1, NULL, 10);
if (sig == signature.nsec()) {

13
logd/LogStatistics.cpp
View File

@ -71,8 +71,17 @@ void LogStatistics::add(LogBufferElement *element) {
mSizes[log_id] += size;
++mElements[log_id];
mSizesTotal[log_id] += size;
++mElementsTotal[log_id];
if (element->getDropped()) {
++mDroppedElements[log_id];
} else {
// When caller adding a chatty entry, they will have already
// called add() and subtract() for each entry as they are
// evaluated and trimmed, thus recording size and number of
// elements, but we must recognize the manufactured dropped
// entry as not contributing to the lifetime totals.
mSizesTotal[log_id] += size;
++mElementsTotal[log_id];
}
if (log_id == LOG_ID_KERNEL) {
return;

4
logd/LogStatistics.h
View File

@ -265,7 +265,7 @@ struct UidEntry : public EntryBaseDropped {
if (pid != element->getPid()) {
pid = -1;
}
EntryBase::add(element);
EntryBaseDropped::add(element);
}
std::string formatHeader(const std::string &name, log_id_t id) const;
@ -419,7 +419,7 @@ struct TagEntry : public EntryBaseDropped {
if (pid != element->getPid()) {
pid = -1;
}
EntryBase::add(element);
EntryBaseDropped::add(element);
}
std::string formatHeader(const std::string &name, log_id_t id) const;

3
logd/LogUtils.h
View File

@ -40,6 +40,9 @@ char *tidToName(pid_t tid);
// Furnished in main.cpp. Thread safe.
const char *tagToName(size_t *len, uint32_t tag);
// Furnished by LogKlog.cpp.
const char* strnstr(const char* s, size_t len, const char* needle);
}
// Furnished in LogCommand.cpp

99
logd/tests/logd_test.cpp
View File

@ -778,3 +778,102 @@ TEST(logd, SNDTIMEO) {
close(fd);
}
static inline int32_t get4LE(const char* src)
{
return src[0] | (src[1] << 8) | (src[2] << 16) | (src[3] << 24);
}
void __android_log_btwrite_multiple__helper(int count) {
log_time ts(CLOCK_MONOTONIC);
struct logger_list *logger_list;
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, 0)));
log_time ts1(CLOCK_MONOTONIC);
pid_t pid = fork();
if (pid == 0) {
// child
for (int i = count; i; --i) {
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
usleep(100);
}
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1)));
usleep(1000000);
_exit(0);
}
siginfo_t info{};
ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
int expected_count = (count < 2) ? count : 2;
int expected_chatty_count = (count <= 2) ? 0 : 1;
int expected_expire_count = (count < 2) ? 0 : (count - 2);
count = 0;
int second_count = 0;
int chatty_count = 0;
int expire_count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
if ((log_msg.entry.pid != pid) ||
(log_msg.entry.len < (4 + 1 + 8)) ||
(log_msg.id() != LOG_ID_EVENTS)) continue;
char *eventData = log_msg.msg();
if (!eventData) continue;
uint32_t tag = get4LE(eventData);
if ((eventData[4] == EVENT_TYPE_LONG) && (log_msg.entry.len == (4 + 1 + 8))) {
if (tag != 0) continue;
log_time tx(eventData + 4 + 1);
if (ts == tx) {
++count;
} else if (ts1 == tx) {
++second_count;
}
} else if (eventData[4] == EVENT_TYPE_STRING) {
// chatty
if (tag != 1004) continue;
++chatty_count;
// int len = get4LE(eventData + 4 + 1);
const char *cp = strstr(eventData + 4 + 1 + 4, " expire ");
if (!cp) continue;
unsigned val = 0;
sscanf(cp, " expire %u lines", &val);
expire_count += val;
}
}
EXPECT_EQ(expected_count, count);
EXPECT_EQ(1, second_count);
EXPECT_EQ(expected_chatty_count, chatty_count);
EXPECT_EQ(expected_expire_count, expire_count);
android_logger_list_close(logger_list);
}
TEST(logd, multiple_test_1) {
__android_log_btwrite_multiple__helper(1);
}
TEST(logd, multiple_test_2) {
__android_log_btwrite_multiple__helper(2);
}
TEST(logd, multiple_test_3) {
__android_log_btwrite_multiple__helper(3);
}
TEST(logd, multiple_test_10) {
__android_log_btwrite_multiple__helper(10);
}