Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 1736ba46 authored by Ruchir Rastogi's avatar Ruchir Rastogi
Browse files

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
parent 8cca880b

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

    }