statsd: parse the new format of stats log

+ Changed how we construct LogEvent, now it's based on the context from log_msg
  without making a copy of the list.

+ All stats logs now have the same event tag, the atom id is the first elem in the log.

Test: statsd_test
Change-Id: I4419380f2ee1c2b2155d427b9f2adb78883b337f
This commit is contained in:
Yao Chen
2017-11-13 20:42:25 -08:00
parent efe5f129ad
commit 80235403d2
13 changed files with 171 additions and 146 deletions

View File

@@ -71,10 +71,9 @@ bool CpuTimePerUidFreqPuller::Pull(const int tagId, vector<shared_ptr<LogEvent>>
do {
timeMs = std::stoull(pch);
auto ptr = make_shared<LogEvent>(android::util::CPU_TIME_PER_UID_FREQ_PULLED, timestamp);
auto elemList = ptr->GetAndroidLogEventList();
*elemList << uid;
*elemList << idx;
*elemList << timeMs;
ptr->write(uid);
ptr->write(idx);
ptr->write(timeMs);
ptr->init();
data->push_back(ptr);
VLOG("uid %lld, freq idx %d, sys time %lld", (long long)uid, idx, (long long)timeMs);

View File

@@ -66,10 +66,9 @@ bool CpuTimePerUidPuller::Pull(const int tagId, vector<shared_ptr<LogEvent>>* da
uint64_t sysTimeMs = std::stoull(pch);
auto ptr = make_shared<LogEvent>(android::util::CPU_TIME_PER_UID_PULLED, timestamp);
auto elemList = ptr->GetAndroidLogEventList();
*elemList << uid;
*elemList << userTimeMs;
*elemList << sysTimeMs;
ptr->write(uid);
ptr->write(userTimeMs);
ptr->write(sysTimeMs);
ptr->init();
data->push_back(ptr);
VLOG("uid %lld, user time %lld, sys time %lld", (long long)uid, (long long)userTimeMs, (long long)sysTimeMs);

View File

@@ -93,11 +93,10 @@ bool ResourcePowerManagerPuller::Pull(const int tagId, vector<shared_ptr<LogEven
auto statePtr = make_shared<LogEvent>(
android::util::POWER_STATE_PLATFORM_SLEEP_STATE_PULLED, timestamp);
auto elemList = statePtr->GetAndroidLogEventList();
*elemList << state.name;
*elemList << state.residencyInMsecSinceBoot;
*elemList << state.totalTransitions;
*elemList << state.supportedOnlyInSuspend;
statePtr->write(state.name);
statePtr->write(state.residencyInMsecSinceBoot);
statePtr->write(state.totalTransitions);
statePtr->write(state.supportedOnlyInSuspend);
statePtr->init();
data->push_back(statePtr);
VLOG("powerstate: %s, %lld, %lld, %d", state.name.c_str(),
@@ -106,11 +105,10 @@ bool ResourcePowerManagerPuller::Pull(const int tagId, vector<shared_ptr<LogEven
for (auto voter : state.voters) {
auto voterPtr =
make_shared<LogEvent>(android::util::POWER_STATE_VOTER_PULLED, timestamp);
auto elemList = voterPtr->GetAndroidLogEventList();
*elemList << state.name;
*elemList << voter.name;
*elemList << voter.totalTimeInMsecVotedForSinceBoot;
*elemList << voter.totalNumberOfTimesVotedSinceBoot;
voterPtr->write(state.name);
voterPtr->write(voter.name);
voterPtr->write(voter.totalTimeInMsecVotedForSinceBoot);
voterPtr->write(voter.totalNumberOfTimesVotedSinceBoot);
voterPtr->init();
data->push_back(voterPtr);
VLOG("powerstatevoter: %s, %s, %lld, %lld", state.name.c_str(),
@@ -141,13 +139,12 @@ bool ResourcePowerManagerPuller::Pull(const int tagId, vector<shared_ptr<LogEven
const PowerStateSubsystemSleepState& state = subsystem.states[j];
auto subsystemStatePtr = make_shared<LogEvent>(
android::util::POWER_STATE_SUBSYSTEM_SLEEP_STATE_PULLED, timestamp);
auto elemList = subsystemStatePtr->GetAndroidLogEventList();
*elemList << subsystem.name;
*elemList << state.name;
*elemList << state.residencyInMsecSinceBoot;
*elemList << state.totalTransitions;
*elemList << state.lastEntryTimestampMs;
*elemList << state.supportedOnlyInSuspend;
subsystemStatePtr->write(subsystem.name);
subsystemStatePtr->write(state.name);
subsystemStatePtr->write(state.residencyInMsecSinceBoot);
subsystemStatePtr->write(state.totalTransitions);
subsystemStatePtr->write(state.lastEntryTimestampMs);
subsystemStatePtr->write(state.supportedOnlyInSuspend);
subsystemStatePtr->init();
data->push_back(subsystemStatePtr);
VLOG("subsystemstate: %s, %s, %lld, %lld, %lld",

View File

@@ -29,21 +29,72 @@ using std::ostringstream;
using std::string;
using android::util::ProtoOutputStream;
// We need to keep a copy of the android_log_event_list owned by this instance so that the char*
// for strings is not cleared before we can read them.
LogEvent::LogEvent(log_msg& msg) : mList(msg) {
init(msg.entry_v1.sec * NS_PER_SEC + msg.entry_v1.nsec, &mList);
LogEvent::LogEvent(log_msg& msg) {
android_log_context context =
create_android_log_parser(msg.msg() + sizeof(uint32_t), msg.len() - sizeof(uint32_t));
mTimestampNs = msg.entry_v1.sec * NS_PER_SEC + msg.entry_v1.nsec;
mContext = NULL;
init(context);
}
LogEvent::LogEvent(int tag, uint64_t timestampNs) : mList(tag), mTimestampNs(timestampNs) {
}
LogEvent::~LogEvent() {
LogEvent::LogEvent(int32_t tagId, uint64_t timestampNs) {
mTimestampNs = timestampNs;
mTagId = tagId;
mContext = create_android_logger(1937006964); // the event tag shared by all stats logs
if (mContext) {
android_log_write_int32(mContext, tagId);
}
}
void LogEvent::init() {
mList.convert_to_reader();
init(mTimestampNs, &mList);
if (mContext) {
const char* buffer;
size_t len = android_log_write_list_buffer(mContext, &buffer);
// turns to reader mode
mContext = create_android_log_parser(buffer, len);
init(mContext);
}
}
bool LogEvent::write(int32_t value) {
if (mContext) {
return android_log_write_int32(mContext, value) >= 0;
}
return false;
}
bool LogEvent::write(uint32_t value) {
if (mContext) {
return android_log_write_int32(mContext, value) >= 0;
}
return false;
}
bool LogEvent::write(uint64_t value) {
if (mContext) {
return android_log_write_int64(mContext, value) >= 0;
}
return false;
}
bool LogEvent::write(const string& value) {
if (mContext) {
return android_log_write_string8_len(mContext, value.c_str(), value.length()) >= 0;
}
return false;
}
bool LogEvent::write(float value) {
if (mContext) {
return android_log_write_float32(mContext, value) >= 0;
}
return false;
}
LogEvent::~LogEvent() {
if (mContext) {
android_log_destroy(&mContext);
}
}
/**
@@ -51,22 +102,25 @@ void LogEvent::init() {
* The goal is to do as little preprocessing as possible, because we read a tiny fraction
* of the elements that are written to the log.
*/
void LogEvent::init(int64_t timestampNs, android_log_event_list* reader) {
mTimestampNs = timestampNs;
mTagId = reader->tag();
void LogEvent::init(android_log_context context) {
mElements.clear();
android_log_list_element elem;
// TODO: The log is actually structured inside one list. This is convenient
// because we'll be able to use it to put the attribution (WorkSource) block first
// without doing our own tagging scheme. Until that change is in, just drop the
// list-related log elements and the order we get there is our index-keyed data
// structure.
int i = 0;
do {
elem = android_log_read_next(reader->context());
elem = android_log_read_next(context);
switch ((int)elem.type) {
case EVENT_TYPE_INT:
// elem at [0] is EVENT_TYPE_LIST, [1] is the tag id. If we add WorkSource, it would
// be the list starting at [2].
if (i == 1) {
mTagId = elem.data.int32;
break;
}
case EVENT_TYPE_FLOAT:
case EVENT_TYPE_STRING:
case EVENT_TYPE_LONG:
@@ -81,13 +135,10 @@ void LogEvent::init(int64_t timestampNs, android_log_event_list* reader) {
default:
break;
}
i++;
} while ((elem.type != EVENT_TYPE_UNKNOWN) && !elem.complete);
}
android_log_event_list* LogEvent::GetAndroidLogEventList() {
return &mList;
}
int64_t LogEvent::GetLong(size_t key, status_t* err) const {
if (key < 1 || (key - 1) >= mElements.size()) {
*err = BAD_INDEX;

View File

@@ -21,6 +21,7 @@
#include <android/util/ProtoOutputStream.h>
#include <log/log_event_list.h>
#include <log/log_read.h>
#include <private/android_logger.h>
#include <utils/Errors.h>
#include <memory>
@@ -45,12 +46,9 @@ public:
explicit LogEvent(log_msg& msg);
/**
* Constructs a LogEvent with the specified tag and creates an android_log_event_list in write
* mode. Obtain this list with the getter. Make sure to call init() before attempting to read
* any of the values. This constructor is useful for unit-testing since we can't pass in an
* android_log_event_list since there is no copy constructor or assignment operator available.
* Constructs a LogEvent with synthetic data for testing. Must call init() before reading.
*/
explicit LogEvent(int tag, uint64_t timestampNs);
explicit LogEvent(int32_t tagId, uint64_t timestampNs);
~LogEvent();
@@ -75,6 +73,17 @@ public:
bool GetBool(size_t key, status_t* err) const;
float GetFloat(size_t key, status_t* err) const;
/**
* Write test data to the LogEvent. This can only be used when the LogEvent is constructed
* using LogEvent(tagId, timestampNs). You need to call init() before you can read from it.
*/
bool write(uint32_t value);
bool write(int32_t value);
bool write(uint64_t value);
bool write(int64_t value);
bool write(const string& value);
bool write(float value);
/**
* Return a string representation of this event.
*/
@@ -90,13 +99,6 @@ public:
*/
KeyValuePair GetKeyValueProto(size_t key) const;
/**
* A pointer to the contained log_event_list.
*
* @return The android_log_event_list contained within.
*/
android_log_event_list* GetAndroidLogEventList();
/**
* Used with the constructor where tag is passed in. Converts the log_event_list to read mode
* and prepares the list for reading.
@@ -113,16 +115,11 @@ private:
/**
* Parses a log_msg into a LogEvent object.
*/
void init(const log_msg& msg);
/**
* Parses a log_msg into a LogEvent object.
*/
void init(int64_t timestampNs, android_log_event_list* reader);
void init(android_log_context context);
vector<android_log_list_element> mElements;
// Need a copy of the android_log_event_list so the strings are not cleared.
android_log_event_list mList;
android_log_context mContext;
uint64_t mTimestampNs;

View File

@@ -165,15 +165,15 @@ bool matchesSimple(const SimpleLogEntryMatcher& simpleMatcher, const LogEvent& e
matcherCase == KeyValueMatcher::ValueMatcherCase::kGtFloat) {
// Float fields
status_t err = NO_ERROR;
bool val = event.GetFloat(key, &err);
float val = event.GetFloat(key, &err);
if (err == NO_ERROR) {
if (matcherCase == KeyValueMatcher::ValueMatcherCase::kLtFloat) {
if (!(cur.lt_float() <= val)) {
if (!(val < cur.lt_float())) {
allMatched = false;
break;
}
} else if (matcherCase == KeyValueMatcher::ValueMatcherCase::kGtFloat) {
if (!(cur.gt_float() >= val)) {
if (!(val > cur.gt_float())) {
allMatched = false;
break;
}

View File

@@ -27,7 +27,7 @@ using namespace android::os::statsd;
using std::unordered_map;
using std::vector;
const int TAG_ID = 123;
const int32_t TAG_ID = 123;
const int FIELD_ID_1 = 1;
const int FIELD_ID_2 = 2;
const int FIELD_ID_3 = 2;
@@ -43,8 +43,6 @@ TEST(LogEntryMatcherTest, TestSimpleMatcher) {
simpleMatcher->set_tag(TAG_ID);
LogEvent event(TAG_ID, 0);
// Convert to a LogEvent
event.init();
// Test
@@ -63,10 +61,8 @@ TEST(LogEntryMatcherTest, TestBoolMatcher) {
// Set up the event
LogEvent event(TAG_ID, 0);
auto list = event.GetAndroidLogEventList();
*list << true;
*list << false;
event.write(true);
event.write(false);
// Convert to a LogEvent
event.init();
@@ -99,9 +95,7 @@ TEST(LogEntryMatcherTest, TestStringMatcher) {
// Set up the event
LogEvent event(TAG_ID, 0);
auto list = event.GetAndroidLogEventList();
*list << "some value";
event.write("some value");
// Convert to a LogEvent
event.init();
@@ -121,9 +115,8 @@ TEST(LogEntryMatcherTest, TestMultiFieldsMatcher) {
// Set up the event
LogEvent event(TAG_ID, 0);
auto list = event.GetAndroidLogEventList();
*list << 2;
*list << 3;
event.write(2);
event.write(3);
// Convert to a LogEvent
event.init();
@@ -153,9 +146,7 @@ TEST(LogEntryMatcherTest, TestIntComparisonMatcher) {
// Set up the event
LogEvent event(TAG_ID, 0);
auto list = event.GetAndroidLogEventList();
*list << 11;
event.write(11);
event.init();
// Test
@@ -201,8 +192,6 @@ TEST(LogEntryMatcherTest, TestIntComparisonMatcher) {
EXPECT_FALSE(matchesSimple(*simpleMatcher, event));
}
#if 0
TEST(LogEntryMatcherTest, TestFloatComparisonMatcher) {
// Set up the matcher
LogEntryMatcher matcher;
@@ -212,22 +201,28 @@ TEST(LogEntryMatcherTest, TestFloatComparisonMatcher) {
auto keyValue = simpleMatcher->add_key_value_matcher();
keyValue->mutable_key_matcher()->set_key(FIELD_ID_1);
LogEvent event;
event.tagId = TAG_ID;
LogEvent event1(TAG_ID, 0);
keyValue->set_lt_float(10.0);
event.floatMap[FIELD_ID_1] = 10.1;
EXPECT_FALSE(matchesSimple(*simpleMatcher, event));
event.floatMap[FIELD_ID_1] = 9.9;
EXPECT_TRUE(matchesSimple(*simpleMatcher, event));
event1.write(10.1f);
event1.init();
EXPECT_FALSE(matchesSimple(*simpleMatcher, event1));
LogEvent event2(TAG_ID, 0);
event2.write(9.9f);
event2.init();
EXPECT_TRUE(matchesSimple(*simpleMatcher, event2));
LogEvent event3(TAG_ID, 0);
event3.write(10.1f);
event3.init();
keyValue->set_gt_float(10.0);
event.floatMap[FIELD_ID_1] = 10.1;
EXPECT_TRUE(matchesSimple(*simpleMatcher, event));
event.floatMap[FIELD_ID_1] = 9.9;
EXPECT_FALSE(matchesSimple(*simpleMatcher, event));
EXPECT_TRUE(matchesSimple(*simpleMatcher, event3));
LogEvent event4(TAG_ID, 0);
event4.write(9.9f);
event4.init();
EXPECT_FALSE(matchesSimple(*simpleMatcher, event4));
}
#endif
// Helper for the composite matchers.
void addSimpleMatcher(SimpleLogEntryMatcher* simpleMatcher, int tag, int key, int val) {

View File

@@ -36,10 +36,9 @@ TEST(UidMapTest, TestIsolatedUID) {
sp<UidMap> m = new UidMap();
StatsLogProcessor p(m, nullptr);
LogEvent addEvent(android::util::ISOLATED_UID_CHANGED, 1);
android_log_event_list* list = addEvent.GetAndroidLogEventList();
*list << 100; // parent UID
*list << 101; // isolated UID
*list << 1; // Indicates creation.
addEvent.write(100); // parent UID
addEvent.write(101); // isolated UID
addEvent.write(1); // Indicates creation.
addEvent.init();
EXPECT_EQ(101, m->getParentUidOrSelf(101));
@@ -48,10 +47,9 @@ TEST(UidMapTest, TestIsolatedUID) {
EXPECT_EQ(100, m->getParentUidOrSelf(101));
LogEvent removeEvent(android::util::ISOLATED_UID_CHANGED, 1);
list = removeEvent.GetAndroidLogEventList();
*list << 100; // parent UID
*list << 101; // isolated UID
*list << 0; // Indicates removal.
removeEvent.write(100); // parent UID
removeEvent.write(101); // isolated UID
removeEvent.write(0); // Indicates removal.
removeEvent.init();
p.OnLogEvent(removeEvent);
EXPECT_EQ(101, m->getParentUidOrSelf(101));

View File

@@ -46,10 +46,9 @@ SimpleCondition getWakeLockHeldCondition(bool countNesting, bool defaultFalse,
}
void makeWakeLockEvent(LogEvent* event, int uid, const string& wl, int acquire) {
auto list = event->GetAndroidLogEventList();
*list << uid; // uid
*list << wl;
*list << acquire;
event->write(uid); // uid
event->write(wl);
event->write(acquire);
event->init();
}

View File

@@ -138,15 +138,13 @@ TEST(CountMetricProducerTest, TestEventsWithSlicedCondition) {
link->add_key_in_condition()->set_key(2);
LogEvent event1(1, bucketStartTimeNs + 1);
auto list = event1.GetAndroidLogEventList();
*list << "111"; // uid
event1.write("111"); // uid
event1.init();
ConditionKey key1;
key1["APP_IN_BACKGROUND_PER_UID"] = "2:111|";
LogEvent event2(1, bucketStartTimeNs + 10);
auto list2 = event2.GetAndroidLogEventList();
*list2 << "222"; // uid
event2.write("222"); // uid
event2.init();
ConditionKey key2;
key2["APP_IN_BACKGROUND_PER_UID"] = "2:222|";

View File

@@ -95,15 +95,13 @@ TEST(EventMetricProducerTest, TestEventsWithSlicedCondition) {
link->add_key_in_condition()->set_key(2);
LogEvent event1(1, bucketStartTimeNs + 1);
auto list = event1.GetAndroidLogEventList();
*list << "111"; // uid
event1.write("111"); // uid
event1.init();
ConditionKey key1;
key1["APP_IN_BACKGROUND_PER_UID"] = "2:111|";
LogEvent event2(1, bucketStartTimeNs + 10);
auto list2 = event2.GetAndroidLogEventList();
*list2 << "222"; // uid
event2.write("222"); // uid
event2.init();
ConditionKey key2;
key2["APP_IN_BACKGROUND_PER_UID"] = "2:222|";

View File

@@ -64,9 +64,8 @@ TEST(ValueMetricProducerTest, TestNonDimensionalEvents) {
vector<shared_ptr<LogEvent>> allData;
allData.clear();
shared_ptr<LogEvent> event = make_shared<LogEvent>(tagId, bucketStartTimeNs + 1);
auto list = event->GetAndroidLogEventList();
*list << 1;
*list << 11;
event->write(1);
event->write(11);
event->init();
allData.push_back(event);
@@ -89,9 +88,8 @@ TEST(ValueMetricProducerTest, TestNonDimensionalEvents) {
allData.clear();
event = make_shared<LogEvent>(tagId, bucket2StartTimeNs + 1);
list = event->GetAndroidLogEventList();
*list << 1;
*list << 22;
event->write(1);
event->write(22);
event->init();
allData.push_back(event);
valueProducer.onDataPulled(allData);
@@ -110,9 +108,8 @@ TEST(ValueMetricProducerTest, TestNonDimensionalEvents) {
allData.clear();
event = make_shared<LogEvent>(tagId, bucket3StartTimeNs + 1);
list = event->GetAndroidLogEventList();
*list << 1;
*list << 33;
event->write(1);
event->write(33);
event->init();
allData.push_back(event);
valueProducer.onDataPulled(allData);
@@ -159,9 +156,8 @@ TEST(ValueMetricProducerTest, TestEventsWithNonSlicedCondition) {
int64_t bucket3StartTimeNs = bucketStartTimeNs + 2 * bucketSizeNs;
data->clear();
shared_ptr<LogEvent> event = make_shared<LogEvent>(tagId, bucketStartTimeNs + 10);
auto list = event->GetAndroidLogEventList();
*list << 1;
*list << 100;
event->write(1);
event->write(100);
event->init();
data->push_back(event);
return true;
@@ -174,9 +170,8 @@ TEST(ValueMetricProducerTest, TestEventsWithNonSlicedCondition) {
int64_t bucket3StartTimeNs = bucketStartTimeNs + 2 * bucketSizeNs;
data->clear();
shared_ptr<LogEvent> event = make_shared<LogEvent>(tagId, bucket2StartTimeNs + 10);
auto list = event->GetAndroidLogEventList();
*list << 1;
*list << 120;
event->write(1);
event->write(120);
event->init();
data->push_back(event);
return true;
@@ -201,9 +196,8 @@ TEST(ValueMetricProducerTest, TestEventsWithNonSlicedCondition) {
vector<shared_ptr<LogEvent>> allData;
allData.clear();
shared_ptr<LogEvent> event = make_shared<LogEvent>(tagId, bucket2StartTimeNs + 1);
auto list = event->GetAndroidLogEventList();
*list << 1;
*list << 110;
event->write(1);
event->write(110);
event->init();
allData.push_back(event);
valueProducer.onDataPulled(allData);
@@ -253,14 +247,12 @@ TEST(ValueMetricProducerTest, TestPushedEventsWithoutCondition) {
bucketStartTimeNs, pullerManager);
shared_ptr<LogEvent> event1 = make_shared<LogEvent>(tagId, bucketStartTimeNs + 10);
auto list = event1->GetAndroidLogEventList();
*list << 1;
*list << 10;
event1->write(1);
event1->write(10);
event1->init();
shared_ptr<LogEvent> event2 = make_shared<LogEvent>(tagId, bucketStartTimeNs + 10);
auto list2 = event2->GetAndroidLogEventList();
*list2 << 1;
*list2 << 20;
event2->write(1);
event2->write(20);
event2->init();
valueProducer.onMatchedLogEvent(1 /*log matcher index*/, *event1, false);
// has one slice

View File

@@ -107,6 +107,8 @@ write_stats_log_cpp(FILE* out, const Atoms& atoms)
fprintf(out, "namespace android {\n");
fprintf(out, "namespace util {\n");
fprintf(out, "// the single event tag id for all stats logs\n");
fprintf(out, "const static int kStatsEventTag = 1937006964;\n");
// Print write methods
fprintf(out, "\n");
@@ -115,7 +117,7 @@ write_stats_log_cpp(FILE* out, const Atoms& atoms)
int argIndex;
fprintf(out, "void\n");
fprintf(out, "stats_write(int code");
fprintf(out, "stats_write(int32_t code");
argIndex = 1;
for (vector<java_type_t>::const_iterator arg = signature->begin();
arg != signature->end(); arg++) {
@@ -126,7 +128,8 @@ write_stats_log_cpp(FILE* out, const Atoms& atoms)
fprintf(out, "{\n");
argIndex = 1;
fprintf(out, " android_log_event_list event(code);\n");
fprintf(out, " android_log_event_list event(kStatsEventTag);\n");
fprintf(out, " event << code;\n");
for (vector<java_type_t>::const_iterator arg = signature->begin();
arg != signature->end(); arg++) {
if (*arg == JAVA_TYPE_STRING) {
@@ -204,8 +207,7 @@ write_stats_log_header(FILE* out, const Atoms& atoms)
fprintf(out, "//\n");
for (set<vector<java_type_t>>::const_iterator signature = atoms.signatures.begin();
signature != atoms.signatures.end(); signature++) {
fprintf(out, "void stats_write(int code");
fprintf(out, "void stats_write(int32_t code ");
int argIndex = 1;
for (vector<java_type_t>::const_iterator arg = signature->begin();
arg != signature->end(); arg++) {