Merge "First pass at parsing new socket encoding scheme" (c1270020) · Commits · e / os / android_frameworks_base

cmds/statsd/Android.bp

+5 −2

Original line number	Diff line number	Diff line
		@@ -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",
		],
		}

cmds/statsd/benchmark/log_event_benchmark.cpp

+15 −40

Original line number	Diff line number	Diff line
		@@ -16,55 +16,30 @@
		#include <vector>
		#include "benchmark/benchmark.h"
		#include "logd/LogEvent.h"
		#include "stats_event.h"

		namespace android {
		namespace os {
		namespace statsd {

		using std::vector;

		/* 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<char>* buffer) {
		buffer->push_back(static_cast<char>(val));
		buffer->push_back(static_cast<char>((val >> 8) & 0xFF));
		buffer->push_back(static_cast<char>((val >> 16) & 0xFF));
		buffer->push_back(static_cast<char>((val >> 24) & 0xFF));
		}

		static void getSimpleLogMsgData(log_msg* msg) {
		vector<char> 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);
		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);

		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);

cmds/statsd/src/logd/LogEvent.cpp

+194 −9

Original line number	Diff line number	Diff line
		@@ -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<int32_t>();
		addToValues(pos, depth, value, last);
		}

		void LogEvent::parseInt64(int32_t* pos, int32_t depth, bool* last) {
		int64_t value = readNextValue<int64_t>();
		addToValues(pos, depth, value, last);
		}

		void LogEvent::parseString(int32_t* pos, int32_t depth, bool* last) {
		int32_t numBytes = readNextValue<int32_t>();
		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<float>();
		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<uint8_t>();
		addToValues(pos, depth, value, last);
		}

		void LogEvent::parseByteArray(int32_t* pos, int32_t depth, bool* last) {
		int32_t numBytes = readNextValue<int32_t>();
		if ((uint32_t)numBytes > mRemainingLen) {
		mValid = false;
		return;
		}

		vector<uint8_t> 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<uint8_t>();

		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<uint8_t>());
		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<uint8_t>();
		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<uint8_t>();
		if (getTypeId(typeInfo) != OBJECT_TYPE) mValid = false;

		uint8_t numElements = readNextValue<uint8_t>();
		if (numElements < 2 \|\| numElements > 127) mValid = false;

		typeInfo = readNextValue<uint8_t>();
		if (getTypeId(typeInfo) != INT64_TYPE) mValid = false;
		mElapsedTimestampNs = readNextValue<int64_t>();
		numElements--;

		typeInfo = readNextValue<uint8_t>();
		if (getTypeId(typeInfo) != INT32_TYPE) mValid = false;
		mTagId = readNextValue<int32_t>();
		numElements--;


		for (pos[0] = 1; pos[0] <= numElements && mValid; pos[0]++) {
		typeInfo = readNextValue<uint8_t>();
		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

cmds/statsd/src/logd/LogEvent.h

+70 −2

Original line number	Diff line number	Diff line
		@@ -24,6 +24,7 @@
		#include <log/log_read.h>
		#include <private/android_logger.h>
		#include <stats_event_list.h>
		#include "stats_event.h"
		#include <utils/Errors.h>

		#include <string>
		@@ -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 <class T>
		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 <class T>
		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.
		*/

cmds/statsd/src/socket/StatsSocketListener.cpp

+6 −13

Original line number	Diff line number	Diff line
		@@ -39,8 +39,6 @@ namespace android {
		namespace os {
		namespace statsd {

		static const int kLogMsgHeaderSize = 28;

		StatsSocketListener::StatsSocketListener(std::shared_ptr<LogEventQueue> 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<LogEvent>(msg), &oldestTimestamp)) {
		if (!mQueue->push(std::make_unique<LogEvent>(msg, len, uid), &oldestTimestamp)) {
		StatsdStats::getInstance().noteEventQueueOverflow(oldestTimestamp);
		}