From 60636fa872382a8cde0440b72cdfc9032b5fa7d0 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Mon, 24 Oct 2016 16:22:17 -0700 Subject: [PATCH] logd: getTag() functional for chatty entries getTag() becomes invalid when entry is dropped because mMsg disappears to save space; but the per-tag spam filter depends on it still being valid. Conserve space in LogBufferElement by optimizing the size of the fields, then add a new mTag field that is set in the object constructor. Add an isBinary() method. SideEffects: save 12 bytes/log message overhead on 64-bit. Test: define DEBUG_CHECK_FOR_STALE_ENTRIES and look for stale entries Bug: 32247044 Change-Id: Iaa5f416718a92c9e0e6ffd56bd5260d8b908d5c0 --- logd/LogBuffer.cpp | 28 ++++++++++++++++++++++++++++ logd/LogBufferElement.cpp | 21 ++++++++------------- logd/LogBufferElement.h | 31 ++++++++++++++++++------------- 3 files changed, 54 insertions(+), 26 deletions(-) diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp index 5cab7a8c4..a00943309 100644 --- a/logd/LogBuffer.cpp +++ b/logd/LogBuffer.cpp @@ -13,6 +13,8 @@ * See the License for the specific language governing permissions and * limitations under the License. */ +// for manual checking of stale entries during LogBuffer::erase() +//#define DEBUG_CHECK_FOR_STALE_ENTRIES #include #include @@ -256,6 +258,11 @@ LogBufferElementCollection::iterator LogBuffer::erase( log_id_for_each(i) { doSetLast |= setLast[i] = mLastSet[i] && (it == mLast[i]); } +#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES + LogBufferElementCollection::iterator bad = it; + int key = ((id == LOG_ID_EVENTS) || (id == LOG_ID_SECURITY)) ? + element->getTag() : element->getUid(); +#endif it = mLogElements.erase(it); if (doSetLast) { log_id_for_each(i) { @@ -269,6 +276,27 @@ LogBufferElementCollection::iterator LogBuffer::erase( } } } +#ifdef DEBUG_CHECK_FOR_STALE_ENTRIES + log_id_for_each(i) { + for(auto b : mLastWorst[i]) { + if (bad == b.second) { + android::prdebug("stale mLastWorst[%d] key=%d mykey=%d\n", + i, b.first, key); + } + } + for(auto b : mLastWorstPidOfSystem[i]) { + if (bad == b.second) { + android::prdebug("stale mLastWorstPidOfSystem[%d] pid=%d\n", + i, b.first); + } + } + if (mLastSet[i] && (bad == mLast[i])) { + android::prdebug("stale mLast[%d]\n", i); + mLastSet[i] = false; + mLast[i] = mLogElements.begin(); + } + } +#endif if (coalesce) { stats.erase(element); } else { diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp index a9390022d..f5c60c72b 100644 --- a/logd/LogBufferElement.cpp +++ b/logd/LogBufferElement.cpp @@ -36,29 +36,24 @@ atomic_int_fast64_t LogBufferElement::sequence(1); LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid, const char *msg, unsigned short len) : - mLogId(log_id), mUid(uid), mPid(pid), mTid(tid), - mMsgLen(len), mSequence(sequence.fetch_add(1, memory_order_relaxed)), - mRealTime(realtime) { + mRealTime(realtime), + mMsgLen(len), + mLogId(log_id) { mMsg = new char[len]; memcpy(mMsg, msg, len); + mTag = (isBinary() && (mMsgLen >= sizeof(uint32_t))) ? + le32toh(reinterpret_cast(mMsg)->tag) : + 0; } LogBufferElement::~LogBufferElement() { delete [] mMsg; } -uint32_t LogBufferElement::getTag() const { - if (((mLogId != LOG_ID_EVENTS) && (mLogId != LOG_ID_SECURITY)) || - !mMsg || (mMsgLen < sizeof(uint32_t))) { - return 0; - } - return le32toh(reinterpret_cast(mMsg)->tag); -} - // caller must own and free character string char *android::tidToName(pid_t tid) { char *retval = NULL; @@ -164,7 +159,7 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, size_t hdrLen; // LOG_ID_SECURITY not strictly needed since spam filter not activated, // but required for accuracy. - if ((mLogId == LOG_ID_EVENTS) || (mLogId == LOG_ID_SECURITY)) { + if (isBinary()) { hdrLen = sizeof(android_log_event_string_t); } else { hdrLen = 1 + sizeof(tag); @@ -178,7 +173,7 @@ size_t LogBufferElement::populateDroppedMessage(char *&buffer, } size_t retval = hdrLen + len; - if ((mLogId == LOG_ID_EVENTS) || (mLogId == LOG_ID_SECURITY)) { + if (isBinary()) { android_log_event_string_t *event = reinterpret_cast(buffer); diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h index 2c7fd448d..fb7fbed5c 100644 --- a/logd/LogBufferElement.h +++ b/logd/LogBufferElement.h @@ -36,33 +36,40 @@ class LogBufferElement { friend LogBuffer; - const log_id_t mLogId; - const uid_t mUid; - const pid_t mPid; - const pid_t mTid; - char *mMsg; - union { - const unsigned short mMsgLen; // mMSg != NULL - unsigned short mDropped; // mMsg == NULL - }; + // sized to match reality of incoming log packets + uint32_t mTag; // only valid for isBinary() + const uint32_t mUid; + const uint32_t mPid; + const uint32_t mTid; const uint64_t mSequence; log_time mRealTime; + char *mMsg; + union { + const uint16_t mMsgLen; // mMSg != NULL + uint16_t mDropped; // mMsg == NULL + }; + const uint8_t mLogId; + static atomic_int_fast64_t sequence; // assumption: mMsg == NULL size_t populateDroppedMessage(char *&buffer, LogBuffer *parent); - 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); virtual ~LogBufferElement(); - log_id_t getLogId() const { return mLogId; } + bool isBinary(void) const { + return (mLogId == LOG_ID_EVENTS) || (mLogId == LOG_ID_SECURITY); + } + + log_id_t getLogId() const { return static_cast(mLogId); } uid_t getUid(void) const { return mUid; } pid_t getPid(void) const { return mPid; } pid_t getTid(void) const { return mTid; } + uint32_t getTag() const { return mTag; } unsigned short getDropped(void) const { return mMsg ? 0 : mDropped; } unsigned short setDropped(unsigned short value) { if (mMsg) { @@ -76,8 +83,6 @@ public: static uint64_t getCurrentSequence(void) { return sequence.load(memory_order_relaxed); } log_time getRealTime(void) const { return mRealTime; } - uint32_t getTag(void) const; - static const uint64_t FLUSH_ERROR; uint64_t flushTo(SocketClient *writer, LogBuffer *parent, bool privileged); };