From 1736ba467fcf8bb520eb5590dab786c55e3c12a4 Mon Sep 17 00:00:00 2001 From: Ruchir Rastogi Date: Mon, 4 Nov 2019 14:37:13 -0800 Subject: [PATCH] First pass at parsing new socket encoding scheme New parsing logic can be turned on using the DNEW_ENCODING_SCHEME flag. Currently, we do not support parsing annotations or errors. To simplify the LogEvent constructor, we remove the creation of log_msg objects within StatsSocketListener. This change to the LogEvent constructor also forced us to modify the LogEvent benchmarking code. Test: m -j128 Test: bit statsd_test:* (passes when flag is off) Test: atest StatsdHostTestCases (passes when flag is off) Test: bit statsd_benchmark:* Change-Id: I827b72f46a617dbc5194ad778fcf7c3d794efb7b --- cmds/statsd/Android.bp | 7 +- cmds/statsd/benchmark/log_event_benchmark.cpp | 53 ++--- cmds/statsd/src/logd/LogEvent.cpp | 203 +++++++++++++++++- cmds/statsd/src/logd/LogEvent.h | 72 ++++++- .../statsd/src/socket/StatsSocketListener.cpp | 19 +- 5 files changed, 289 insertions(+), 65 deletions(-) diff --git a/cmds/statsd/Android.bp b/cmds/statsd/Android.bp index 360ddd44955aa..2d3c26c648d22 100644 --- a/cmds/statsd/Android.bp +++ b/cmds/statsd/Android.bp @@ -168,6 +168,7 @@ cc_binary { "-Os", // "-g", // "-O0", + // "-DNEW_ENCODING_SCHEME", ], product_variables: { @@ -325,7 +326,8 @@ cc_benchmark { "-Wno-unused-function", // Bug: http://b/29823425 Disable -Wvarargs for Clang update to r271374 - "-Wno-varargs" + "-Wno-varargs", + // "-DNEW_ENCODING_SCHEME", ], static_libs: [ @@ -334,8 +336,9 @@ cc_benchmark { shared_libs: [ "libgtest_prod", - "libstatslog", "libprotobuf-cpp-lite", + "libstatslog", + "libstatssocket", ], } diff --git a/cmds/statsd/benchmark/log_event_benchmark.cpp b/cmds/statsd/benchmark/log_event_benchmark.cpp index 26034695906b4..bdfdb2e00ac0b 100644 --- a/cmds/statsd/benchmark/log_event_benchmark.cpp +++ b/cmds/statsd/benchmark/log_event_benchmark.cpp @@ -16,55 +16,30 @@ #include #include "benchmark/benchmark.h" #include "logd/LogEvent.h" +#include "stats_event.h" namespace android { namespace os { namespace statsd { -using std::vector; +static size_t createAndParseStatsEvent(uint8_t* msg) { + struct stats_event* event = stats_event_obtain(); + stats_event_set_atom_id(event, 100); + stats_event_write_int32(event, 2); + stats_event_write_float(event, 2.0); + stats_event_build(event); -/* Special markers for android_log_list_element type */ -static const char EVENT_TYPE_LIST_STOP = '\n'; /* declare end of list */ -static const char EVENT_TYPE_UNKNOWN = '?'; /* protocol error */ - -static const char EVENT_TYPE_INT = 0; -static const char EVENT_TYPE_LONG = 1; -static const char EVENT_TYPE_STRING = 2; -static const char EVENT_TYPE_LIST = 3; -static const char EVENT_TYPE_FLOAT = 4; - -static const int kLogMsgHeaderSize = 28; - -static void write4Bytes(int val, vector* buffer) { - buffer->push_back(static_cast(val)); - buffer->push_back(static_cast((val >> 8) & 0xFF)); - buffer->push_back(static_cast((val >> 16) & 0xFF)); - buffer->push_back(static_cast((val >> 24) & 0xFF)); -} - -static void getSimpleLogMsgData(log_msg* msg) { - vector buffer; - // stats_log tag id - write4Bytes(1937006964, &buffer); - buffer.push_back(EVENT_TYPE_LIST); - buffer.push_back(2); // field counts; - buffer.push_back(EVENT_TYPE_INT); - write4Bytes(10 /* atom id */, &buffer); - buffer.push_back(EVENT_TYPE_INT); - write4Bytes(99 /* a value to log*/, &buffer); - buffer.push_back(EVENT_TYPE_LIST_STOP); - - msg->entry.len = buffer.size(); - msg->entry.hdr_size = kLogMsgHeaderSize; - msg->entry.sec = time(nullptr); - std::copy(buffer.begin(), buffer.end(), msg->buf + kLogMsgHeaderSize); + size_t size; + uint8_t* buf = stats_event_get_buffer(event, &size); + memcpy(msg, buf, size); + return size; } static void BM_LogEventCreation(benchmark::State& state) { - log_msg msg; - getSimpleLogMsgData(&msg); + uint8_t msg[LOGGER_ENTRY_MAX_PAYLOAD]; + size_t size = createAndParseStatsEvent(msg); while (state.KeepRunning()) { - benchmark::DoNotOptimize(LogEvent(msg)); + benchmark::DoNotOptimize(LogEvent(msg, size, /*uid=*/ 1000)); } } BENCHMARK(BM_LogEventCreation); diff --git a/cmds/statsd/src/logd/LogEvent.cpp b/cmds/statsd/src/logd/LogEvent.cpp index 262921e5163c3..67022a078b015 100644 --- a/cmds/statsd/src/logd/LogEvent.cpp +++ b/cmds/statsd/src/logd/LogEvent.cpp @@ -35,16 +35,21 @@ using android::util::ProtoOutputStream; using std::string; using std::vector; -LogEvent::LogEvent(log_msg& msg) { - mContext = - create_android_log_parser(msg.msg() + sizeof(uint32_t), msg.len() - sizeof(uint32_t)); - mLogdTimestampNs = msg.entry.sec * NS_PER_SEC + msg.entry.nsec; - mLogUid = msg.entry.uid; +// Msg is expected to begin at the start of the serialized atom -- it should not +// include the android_log_header_t or the StatsEventTag. +LogEvent::LogEvent(uint8_t* msg, uint32_t len, uint32_t uid) + : mBuf(msg), + mRemainingLen(len), + mLogdTimestampNs(time(nullptr)), + mLogUid(uid) +{ +#ifdef NEW_ENCODING_SCHEME + initNew(); +# else + mContext = create_android_log_parser((char*)msg, len); init(mContext); - if (mContext) { - // android_log_destroy will set mContext to NULL - android_log_destroy(&mContext); - } + if (mContext) android_log_destroy(&mContext); // set mContext to NULL +#endif } LogEvent::LogEvent(const LogEvent& event) { @@ -438,6 +443,186 @@ bool LogEvent::write(const AttributionNodeInternal& node) { return false; } +void LogEvent::parseInt32(int32_t* pos, int32_t depth, bool* last) { + int32_t value = readNextValue(); + addToValues(pos, depth, value, last); +} + +void LogEvent::parseInt64(int32_t* pos, int32_t depth, bool* last) { + int64_t value = readNextValue(); + addToValues(pos, depth, value, last); +} + +void LogEvent::parseString(int32_t* pos, int32_t depth, bool* last) { + int32_t numBytes = readNextValue(); + if ((uint32_t)numBytes > mRemainingLen) { + mValid = false; + return; + } + + string value = string((char*)mBuf, numBytes); + mBuf += numBytes; + mRemainingLen -= numBytes; + addToValues(pos, depth, value, last); +} + +void LogEvent::parseFloat(int32_t* pos, int32_t depth, bool* last) { + float value = readNextValue(); + addToValues(pos, depth, value, last); +} + +void LogEvent::parseBool(int32_t* pos, int32_t depth, bool* last) { + // cast to int32_t because FieldValue does not support bools + int32_t value = (int32_t)readNextValue(); + addToValues(pos, depth, value, last); +} + +void LogEvent::parseByteArray(int32_t* pos, int32_t depth, bool* last) { + int32_t numBytes = readNextValue(); + if ((uint32_t)numBytes > mRemainingLen) { + mValid = false; + return; + } + + vector value(mBuf, mBuf + numBytes); + mBuf += numBytes; + mRemainingLen -= numBytes; + addToValues(pos, depth, value, last); +} + +void LogEvent::parseKeyValuePairs(int32_t* pos, int32_t depth, bool* last) { + int32_t numPairs = readNextValue(); + + for (pos[1] = 1; pos[1] <= numPairs; pos[1]++) { + last[1] = (pos[1] == numPairs); + + // parse key + pos[2] = 1; + parseInt32(pos, 2, last); + + // parse value + last[2] = true; + uint8_t typeId = getTypeId(readNextValue()); + switch (typeId) { + case INT32_TYPE: + pos[2] = 2; // pos[2] determined by index of type in KeyValuePair in atoms.proto + parseInt32(pos, 2, last); + break; + case INT64_TYPE: + pos[2] = 3; + parseInt64(pos, 2, last); + break; + case STRING_TYPE: + pos[2] = 4; + parseString(pos, 2, last); + break; + case FLOAT_TYPE: + pos[2] = 5; + parseFloat(pos, 2, last); + break; + default: + mValid = false; + } + } + + pos[1] = pos[2] = 1; + last[1] = last[2] = false; +} + +void LogEvent::parseAttributionChain(int32_t* pos, int32_t depth, bool* last) { + int32_t numNodes = readNextValue(); + for (pos[1] = 1; pos[1] <= numNodes; pos[1]++) { + last[1] = (pos[1] == numNodes); + + // parse uid + pos[2] = 1; + parseInt32(pos, 2, last); + + // parse tag + pos[2] = 2; + last[2] = true; + parseString(pos, 2, last); + } + + pos[1] = pos[2] = 1; + last[1] = last[2] = false; +} + + +// This parsing logic is tied to the encoding scheme used in StatsEvent.java and +// stats_event.c +void LogEvent::initNew() { + int32_t pos[] = {1, 1, 1}; + bool last[] = {false, false, false}; + + // Beginning of buffer is OBJECT_TYPE | NUM_FIELDS | TIMESTAMP | ATOM_ID + uint8_t typeInfo = readNextValue(); + if (getTypeId(typeInfo) != OBJECT_TYPE) mValid = false; + + uint8_t numElements = readNextValue(); + if (numElements < 2 || numElements > 127) mValid = false; + + typeInfo = readNextValue(); + if (getTypeId(typeInfo) != INT64_TYPE) mValid = false; + mElapsedTimestampNs = readNextValue(); + numElements--; + + typeInfo = readNextValue(); + if (getTypeId(typeInfo) != INT32_TYPE) mValid = false; + mTagId = readNextValue(); + numElements--; + + + for (pos[0] = 1; pos[0] <= numElements && mValid; pos[0]++) { + typeInfo = readNextValue(); + uint8_t typeId = getTypeId(typeInfo); + + last[0] = (pos[0] == numElements); + + // TODO(b/144373276): handle errors passed to the socket + // TODO(b/144373257): parse annotations + switch(typeId) { + case BOOL_TYPE: + parseBool(pos, 0, last); + break; + case INT32_TYPE: + parseInt32(pos, 0, last); + break; + case INT64_TYPE: + parseInt64(pos, 0, last); + break; + case FLOAT_TYPE: + parseFloat(pos, 0, last); + break; + case BYTE_ARRAY_TYPE: + parseByteArray(pos, 0, last); + break; + case STRING_TYPE: + parseString(pos, 0, last); + break; + case KEY_VALUE_PAIRS_TYPE: + parseKeyValuePairs(pos, 0, last); + break; + case ATTRIBUTION_CHAIN_TYPE: + parseAttributionChain(pos, 0, last); + break; + default: + mValid = false; + } + } + + if (mRemainingLen != 0) mValid = false; + mBuf = nullptr; +} + +uint8_t LogEvent::getTypeId(uint8_t typeInfo) { + return typeInfo & 0x0F; // type id in lower 4 bytes +} + +uint8_t LogEvent::getNumAnnotations(uint8_t typeInfo) { + return (typeInfo >> 4) & 0x0F; +} + /** * The elements of each log event are stored as a vector of android_log_list_elements. * The goal is to do as little preprocessing as possible, because we read a tiny fraction diff --git a/cmds/statsd/src/logd/LogEvent.h b/cmds/statsd/src/logd/LogEvent.h index f1f45a2d3bc71..8406cc0a7de17 100644 --- a/cmds/statsd/src/logd/LogEvent.h +++ b/cmds/statsd/src/logd/LogEvent.h @@ -24,6 +24,7 @@ #include #include #include +#include "stats_event.h" #include #include @@ -69,9 +70,9 @@ struct InstallTrainInfo { class LogEvent { public: /** - * Read a LogEvent from a log_msg. + * Read a LogEvent from the socket */ - explicit LogEvent(log_msg& msg); + explicit LogEvent(uint8_t* msg, uint32_t len, uint32_t uid); /** * Creates LogEvent from StatsLogEventWrapper. @@ -206,6 +207,10 @@ public: return &mValues; } + bool isValid() { + return mValid; + } + inline LogEvent makeCopy() { return LogEvent(*this); } @@ -216,6 +221,69 @@ private: */ LogEvent(const LogEvent&); + + /** + * Parsing function for new encoding scheme. + */ + void initNew(); + + void parseInt32(int32_t* pos, int32_t depth, bool* last); + void parseInt64(int32_t* pos, int32_t depth, bool* last); + void parseString(int32_t* pos, int32_t depth, bool* last); + void parseFloat(int32_t* pos, int32_t depth, bool* last); + void parseBool(int32_t* pos, int32_t depth, bool* last); + void parseByteArray(int32_t* pos, int32_t depth, bool* last); + void parseKeyValuePairs(int32_t* pos, int32_t depth, bool* last); + void parseAttributionChain(int32_t* pos, int32_t depth, bool* last); + + /** + * mBuf is a pointer to the current location in the buffer being parsed. + * Because the buffer lives on the StatsSocketListener stack, this pointer + * is only valid during the LogEvent constructor. It will be set to null at + * the end of initNew. + */ + uint8_t* mBuf; + + uint32_t mRemainingLen; // number of valid bytes left in the buffer being parsed + bool mValid = true; // stores whether the event we received from the socket is valid + + /** + * Side-effects: + * If there is enough space in buffer to read value of type T + * - move mBuf past the value that was just read + * - decrement mRemainingLen by size of T + * Else + * - set mValid to false + */ + template + T readNextValue() { + T value; + if (mRemainingLen < sizeof(T)) { + mValid = false; + value = 0; // all primitive types can successfully cast 0 + } else { + value = *((T*)mBuf); + mBuf += sizeof(T); + mRemainingLen -= sizeof(T); + } + return value; + } + + template + void addToValues(int32_t* pos, int32_t depth, T& value, bool* last) { + Field f = Field(mTagId, pos, depth); + // do not decorate last position at depth 0 + for (int i = 1; i < depth; i++) { + if (last[i]) f.decorateLastPos(i); + } + + Value v = Value(value); + mValues.push_back(FieldValue(f, v)); + } + + uint8_t getTypeId(uint8_t typeInfo); + uint8_t getNumAnnotations(uint8_t typeInfo); + /** * Parses a log_msg into a LogEvent object. */ diff --git a/cmds/statsd/src/socket/StatsSocketListener.cpp b/cmds/statsd/src/socket/StatsSocketListener.cpp index b59d88dc1cea9..4308a1107039b 100755 --- a/cmds/statsd/src/socket/StatsSocketListener.cpp +++ b/cmds/statsd/src/socket/StatsSocketListener.cpp @@ -39,8 +39,6 @@ namespace android { namespace os { namespace statsd { -static const int kLogMsgHeaderSize = 28; - StatsSocketListener::StatsSocketListener(std::shared_ptr queue) : SocketListener(getLogSocket(), false /*start listen*/), mQueue(queue) { } @@ -95,7 +93,7 @@ bool StatsSocketListener::onDataAvailable(SocketClient* cli) { cred->uid = DEFAULT_OVERFLOWUID; } - char* ptr = ((char*)buffer) + sizeof(android_log_header_t); + uint8_t* ptr = ((uint8_t*)buffer) + sizeof(android_log_header_t); n -= sizeof(android_log_header_t); // When a log failed to write to statsd socket (e.g., due ot EBUSY), a special message would @@ -124,18 +122,13 @@ bool StatsSocketListener::onDataAvailable(SocketClient* cli) { } } - log_msg msg; - - msg.entry.len = n; - msg.entry.hdr_size = kLogMsgHeaderSize; - msg.entry.sec = time(nullptr); - msg.entry.pid = cred->pid; - msg.entry.uid = cred->uid; - - memcpy(msg.buf + kLogMsgHeaderSize, ptr, n + 1); + // move past the 4-byte StatsEventTag + uint8_t* msg = ptr + sizeof(uint32_t); + uint32_t len = n - sizeof(uint32_t); + uint32_t uid = cred->uid; int64_t oldestTimestamp; - if (!mQueue->push(std::make_unique(msg), &oldestTimestamp)) { + if (!mQueue->push(std::make_unique(msg, len, uid), &oldestTimestamp)) { StatsdStats::getInstance().noteEventQueueOverflow(oldestTimestamp); }