Merge changes If1a62a90,Ibce79cf1,Ia2bbf01a,I1763be56,I56762747, ...
* changes:
logd: don't send logs before the start time on the first flushTo()
Revert "logd: drop mSequence from LogBufferElement"
Revert "logd: regression in handling watermark boundary."
Revert "logd: logcat --clear respect pruneMargin"
logd: wait for timeout via CLOCK_MONOTONIC
Revert "logd: wakeup wrap timeout if realtime changes drastically"
logd: do not attempt to sort log messages by time
diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp
index bd17555..0845504 100644
--- a/logd/FlushCommand.cpp
+++ b/logd/FlushCommand.cpp
@@ -49,18 +49,8 @@
return;
}
if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) {
- if (mReader.logbuf().isMonotonic()) {
- LogTimeEntry::unlock();
- return;
- }
- // If the user changes the time in a gross manner that
- // invalidates the timeout, fall through and trigger.
- log_time now(CLOCK_REALTIME);
- if (((entry->mEnd + entry->mTimeout) > now) &&
- (now > entry->mEnd)) {
- LogTimeEntry::unlock();
- return;
- }
+ LogTimeEntry::unlock();
+ return;
}
entry->triggerReader_Locked();
LogTimeEntry::unlock();
diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h
index ceaf393..a69d439 100644
--- a/logd/FlushCommand.h
+++ b/logd/FlushCommand.h
@@ -16,7 +16,7 @@
#ifndef _FLUSH_COMMAND_H
#define _FLUSH_COMMAND_H
-#include <private/android_logger.h>
+#include <android/log.h>
#include <sysutils/SocketClientCommand.h>
class LogBufferElement;
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 1cf2061..5bec076 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -27,6 +27,7 @@
#include <unistd.h>
#include <unordered_map>
+#include <utility>
#include <cutils/properties.h>
#include <private/android_logger.h>
@@ -43,8 +44,6 @@
// Default
#define log_buffer_size(id) mMaxSize[id]
-const log_time LogBuffer::pruneMargin(3, 0);
-
void LogBuffer::init() {
log_id_for_each(i) {
mLastSet[i] = false;
@@ -390,59 +389,7 @@
// assumes LogBuffer::wrlock() held, owns elem, look after garbage collection
void LogBuffer::log(LogBufferElement* elem) {
- // cap on how far back we will sort in-place, otherwise append
- static uint32_t too_far_back = 5; // five seconds
- // Insert elements in time sorted order if possible
- // NB: if end is region locked, place element at end of list
- LogBufferElementCollection::iterator it = mLogElements.end();
- LogBufferElementCollection::iterator last = it;
- if (__predict_true(it != mLogElements.begin())) --it;
- if (__predict_false(it == mLogElements.begin()) ||
- __predict_true((*it)->getRealTime() <= elem->getRealTime()) ||
- __predict_false((((*it)->getRealTime().tv_sec - too_far_back) >
- elem->getRealTime().tv_sec) &&
- (elem->getLogId() != LOG_ID_KERNEL) &&
- ((*it)->getLogId() != LOG_ID_KERNEL))) {
- mLogElements.push_back(elem);
- } else {
- log_time end(log_time::EPOCH);
- bool end_set = false;
- bool end_always = false;
-
- LogTimeEntry::rdlock();
-
- LastLogTimes::iterator times = mTimes.begin();
- while (times != mTimes.end()) {
- LogTimeEntry* entry = times->get();
- if (!entry->mNonBlock) {
- end_always = true;
- break;
- }
- // it passing mEnd is blocked by the following checks.
- if (!end_set || (end <= entry->mEnd)) {
- end = entry->mEnd;
- end_set = true;
- }
- times++;
- }
-
- if (end_always || (end_set && (end > (*it)->getRealTime()))) {
- mLogElements.push_back(elem);
- } else {
- // should be short as timestamps are localized near end()
- do {
- last = it;
- if (__predict_false(it == mLogElements.begin())) {
- break;
- }
- --it;
- } while (((*it)->getRealTime() > elem->getRealTime()) &&
- (!end_set || (end <= (*it)->getRealTime())));
- mLogElements.insert(last, elem);
- }
- LogTimeEntry::unlock();
- }
-
+ mLogElements.push_back(elem);
stats.add(elem);
maybePrune(elem->getLogId());
}
@@ -614,12 +561,11 @@
}
void clear(LogBufferElement* element) {
- log_time current =
- element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0);
+ uint64_t current = element->getRealTime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC);
for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
LogBufferElement* mapElement = it->second;
- if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) &&
- (current > mapElement->getRealTime())) {
+ if (mapElement->getDropped() >= EXPIRE_THRESHOLD &&
+ current > mapElement->getRealTime().nsec()) {
it = map.erase(it);
} else {
++it;
@@ -628,16 +574,6 @@
}
};
-// Determine if watermark is within pruneMargin + 1s from the end of the list,
-// the caller will use this result to set an internal busy flag indicating
-// the prune operation could not be completed because a reader is blocking
-// the request.
-bool LogBuffer::isBusy(log_time watermark) {
- LogBufferElementCollection::iterator ei = mLogElements.end();
- --ei;
- return watermark < ((*ei)->getRealTime() - pruneMargin - log_time(1, 0));
-}
-
// If the selected reader is blocking our pruning progress, decide on
// what kind of mitigation is necessary to unblock the situation.
void LogBuffer::kickMe(LogTimeEntry* me, log_id_t id, unsigned long pruneRows) {
@@ -726,8 +662,6 @@
}
times++;
}
- log_time watermark(log_time::tv_sec_max, log_time::tv_nsec_max);
- if (oldest) watermark = oldest->mStart - pruneMargin;
LogBufferElementCollection::iterator it;
@@ -749,9 +683,9 @@
mLastSet[id] = true;
}
- if (oldest && (watermark <= element->getRealTime())) {
- busy = isBusy(watermark);
- if (busy) kickMe(oldest, id, pruneRows);
+ if (oldest && oldest->mStart <= element->getSequence()) {
+ busy = true;
+ kickMe(oldest, id, pruneRows);
break;
}
@@ -837,8 +771,8 @@
while (it != mLogElements.end()) {
LogBufferElement* element = *it;
- if (oldest && (watermark <= element->getRealTime())) {
- busy = isBusy(watermark);
+ if (oldest && oldest->mStart <= element->getSequence()) {
+ busy = true;
// Do not let chatty eliding trigger any reader mitigation
break;
}
@@ -989,9 +923,9 @@
mLastSet[id] = true;
}
- if (oldest && (watermark <= element->getRealTime())) {
- busy = isBusy(watermark);
- if (!whitelist && busy) kickMe(oldest, id, pruneRows);
+ if (oldest && oldest->mStart <= element->getSequence()) {
+ busy = true;
+ if (!whitelist) kickMe(oldest, id, pruneRows);
break;
}
@@ -1022,9 +956,9 @@
mLastSet[id] = true;
}
- if (oldest && (watermark <= element->getRealTime())) {
- busy = isBusy(watermark);
- if (busy) kickMe(oldest, id, pruneRows);
+ if (oldest && oldest->mStart <= element->getSequence()) {
+ busy = true;
+ kickMe(oldest, id, pruneRows);
break;
}
@@ -1111,43 +1045,32 @@
return retval;
}
-log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
- pid_t* lastTid, bool privileged, bool security,
- int (*filter)(const LogBufferElement* element,
- void* arg),
- void* arg) {
+uint64_t LogBuffer::flushTo(SocketClient* reader, uint64_t start, pid_t* lastTid, bool privileged,
+ bool security,
+ int (*filter)(const LogBufferElement* element, void* arg), void* arg) {
LogBufferElementCollection::iterator it;
uid_t uid = reader->getUid();
rdlock();
- if (start == log_time::EPOCH) {
+ if (start <= 1) {
// client wants to start from the beginning
it = mLogElements.begin();
} else {
- // Cap to 300 iterations we look back for out-of-order entries.
- size_t count = 300;
-
// Client wants to start from some specified time. Chances are
// we are better off starting from the end of the time sorted list.
- LogBufferElementCollection::iterator last;
- for (last = it = mLogElements.end(); it != mLogElements.begin();
+ for (it = mLogElements.end(); it != mLogElements.begin();
/* do nothing */) {
--it;
LogBufferElement* element = *it;
- if (element->getRealTime() > start) {
- last = it;
- } else if (element->getRealTime() == start) {
- last = ++it;
- break;
- } else if (!--count) {
+ if (element->getSequence() <= start) {
+ it++;
break;
}
}
- it = last;
}
- log_time curr = start;
+ uint64_t curr = start;
LogBufferElement* lastElement = nullptr; // iterator corruption paranoia
static const size_t maxSkip = 4194304; // maximum entries to skip
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index c2d5b97..16225a5 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -118,11 +118,10 @@
// lastTid is an optional context to help detect if the last previous
// valid message was from the same source so we can differentiate chatty
// filter types (identical or expired)
- log_time flushTo(SocketClient* writer, const log_time& start,
+ uint64_t flushTo(SocketClient* writer, uint64_t start,
pid_t* lastTid, // &lastTid[LOG_ID_MAX] or nullptr
bool privileged, bool security,
- int (*filter)(const LogBufferElement* element,
- void* arg) = nullptr,
+ int (*filter)(const LogBufferElement* element, void* arg) = nullptr,
void* arg = nullptr);
bool clear(log_id_t id, uid_t uid = AID_ROOT);
@@ -175,10 +174,8 @@
private:
static constexpr size_t minPrune = 4;
static constexpr size_t maxPrune = 256;
- static const log_time pruneMargin;
void maybePrune(log_id_t id);
- bool isBusy(log_time watermark);
void kickMe(LogTimeEntry* me, log_id_t id, unsigned long pruneRows);
bool prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT);
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index ec81933..3714800 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -30,15 +30,15 @@
#include "LogReader.h"
#include "LogUtils.h"
-const log_time LogBufferElement::FLUSH_ERROR((uint32_t)-1, (uint32_t)-1);
+const uint64_t LogBufferElement::FLUSH_ERROR(0);
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, uint16_t len)
+LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
+ pid_t tid, const char* msg, uint16_t len)
: mUid(uid),
mPid(pid),
mTid(tid),
+ mSequence(sequence.fetch_add(1, memory_order_relaxed)),
mRealTime(realtime),
mMsgLen(len),
mLogId(log_id),
@@ -51,6 +51,7 @@
: mUid(elem.mUid),
mPid(elem.mPid),
mTid(elem.mTid),
+ mSequence(elem.mSequence),
mRealTime(elem.mRealTime),
mMsgLen(elem.mMsgLen),
mLogId(elem.mLogId),
@@ -244,7 +245,7 @@
return retval;
}
-log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool lastSame) {
+uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool lastSame) {
struct logger_entry entry = {};
entry.hdr_size = sizeof(struct logger_entry);
@@ -263,7 +264,7 @@
if (mDropped) {
entry.len = populateDroppedMessage(buffer, parent, lastSame);
- if (!entry.len) return mRealTime;
+ if (!entry.len) return mSequence;
iovec[1].iov_base = buffer;
} else {
entry.len = mMsgLen;
@@ -271,9 +272,7 @@
}
iovec[1].iov_len = entry.len;
- log_time retval = reader->sendDatav(iovec, 1 + (entry.len != 0))
- ? FLUSH_ERROR
- : mRealTime;
+ uint64_t retval = reader->sendDatav(iovec, 1 + (entry.len != 0)) ? FLUSH_ERROR : mSequence;
if (buffer) free(buffer);
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index fd790e4..434b7db 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -39,6 +39,7 @@
const uint32_t mUid;
const uint32_t mPid;
const uint32_t mTid;
+ uint64_t mSequence;
log_time mRealTime;
union {
char* mMsg; // mDropped == false
@@ -90,10 +91,12 @@
const char* getMsg() const {
return mDropped ? nullptr : mMsg;
}
+ uint64_t getSequence() const { return mSequence; }
+ static uint64_t getCurrentSequence() { return sequence.load(memory_order_relaxed); }
log_time getRealTime(void) const {
return mRealTime;
}
- static const log_time FLUSH_ERROR;
- log_time flushTo(SocketClient* writer, LogBuffer* parent, bool lastSame);
+ static const uint64_t FLUSH_ERROR;
+ uint64_t flushTo(SocketClient* writer, LogBuffer* parent, bool lastSame);
};
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index 9db8c00..f79d39c 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -89,8 +89,7 @@
static const char _timeout[] = " timeout=";
cp = strstr(buffer, _timeout);
if (cp) {
- timeout = atol(cp + sizeof(_timeout) - 1) * NS_PER_SEC +
- log_time(CLOCK_REALTIME).nsec();
+ timeout = atol(cp + sizeof(_timeout) - 1) * NS_PER_SEC + log_time(CLOCK_MONOTONIC).nsec();
}
unsigned int logMask = -1;
@@ -130,70 +129,53 @@
nonBlock = true;
}
- log_time sequence = start;
- //
- // This somewhat expensive data validation operation is required
- // for non-blocking, with timeout. The incoming timestamp must be
- // in range of the list, if not, return immediately. This is
- // used to prevent us from from getting stuck in timeout processing
- // with an invalid time.
- //
- // Find if time is really present in the logs, monotonic or real, implicit
- // conversion from monotonic or real as necessary to perform the check.
- // Exit in the check loop ASAP as you find a transition from older to
- // newer, but use the last entry found to ensure overlap.
- //
- if (nonBlock && (sequence != log_time::EPOCH) && timeout) {
- class LogFindStart { // A lambda by another name
- private:
+ uint64_t sequence = 1;
+ // Convert realtime to sequence number
+ if (start != log_time::EPOCH) {
+ class LogFindStart {
const pid_t mPid;
const unsigned mLogMask;
- bool mStartTimeSet;
- log_time mStart;
- log_time& mSequence;
- log_time mLast;
- bool mIsMonotonic;
+ bool startTimeSet;
+ const log_time start;
+ uint64_t& sequence;
+ uint64_t last;
+ bool isMonotonic;
- public:
- LogFindStart(pid_t pid, unsigned logMask, log_time& sequence,
+ public:
+ LogFindStart(unsigned logMask, pid_t pid, log_time start, uint64_t& sequence,
bool isMonotonic)
: mPid(pid),
mLogMask(logMask),
- mStartTimeSet(false),
- mStart(sequence),
- mSequence(sequence),
- mLast(sequence),
- mIsMonotonic(isMonotonic) {
- }
+ startTimeSet(false),
+ start(start),
+ sequence(sequence),
+ last(sequence),
+ isMonotonic(isMonotonic) {}
static int callback(const LogBufferElement* element, void* obj) {
LogFindStart* me = reinterpret_cast<LogFindStart*>(obj);
if ((!me->mPid || (me->mPid == element->getPid())) &&
(me->mLogMask & (1 << element->getLogId()))) {
- log_time real = element->getRealTime();
- if (me->mStart == real) {
- me->mSequence = real;
- me->mStartTimeSet = true;
+ if (me->start == element->getRealTime()) {
+ me->sequence = element->getSequence();
+ me->startTimeSet = true;
return -1;
- } else if (!me->mIsMonotonic || android::isMonotonic(real)) {
- if (me->mStart < real) {
- me->mSequence = me->mLast;
- me->mStartTimeSet = true;
+ } else if (!me->isMonotonic || android::isMonotonic(element->getRealTime())) {
+ if (me->start < element->getRealTime()) {
+ me->sequence = me->last;
+ me->startTimeSet = true;
return -1;
}
- me->mLast = real;
+ me->last = element->getSequence();
} else {
- me->mLast = real;
+ me->last = element->getSequence();
}
}
return false;
}
- bool found() {
- return mStartTimeSet;
- }
-
- } logFindStart(pid, logMask, sequence,
+ bool found() { return startTimeSet; }
+ } logFindStart(logMask, pid, start, sequence,
logbuf().isMonotonic() && android::isMonotonic(start));
logbuf().flushTo(cli, sequence, nullptr, FlushCommand::hasReadLogs(cli),
@@ -201,24 +183,27 @@
logFindStart.callback, &logFindStart);
if (!logFindStart.found()) {
- doSocketDelete(cli);
- return false;
+ if (nonBlock) {
+ doSocketDelete(cli);
+ return false;
+ }
+ sequence = LogBufferElement::getCurrentSequence();
}
}
android::prdebug(
- "logdr: UID=%d GID=%d PID=%d %c tail=%lu logMask=%x pid=%d "
- "start=%" PRIu64 "ns timeout=%" PRIu64 "ns\n",
- cli->getUid(), cli->getGid(), cli->getPid(), nonBlock ? 'n' : 'b', tail,
- logMask, (int)pid, sequence.nsec(), timeout);
+ "logdr: UID=%d GID=%d PID=%d %c tail=%lu logMask=%x pid=%d "
+ "start=%" PRIu64 "ns timeout=%" PRIu64 "ns\n",
+ cli->getUid(), cli->getGid(), cli->getPid(), nonBlock ? 'n' : 'b', tail, logMask,
+ (int)pid, start.nsec(), timeout);
- if (sequence == log_time::EPOCH) {
+ if (start == log_time::EPOCH) {
timeout = 0;
}
LogTimeEntry::wrlock();
- auto entry = std::make_unique<LogTimeEntry>(
- *this, cli, nonBlock, tail, logMask, pid, sequence, timeout);
+ auto entry = std::make_unique<LogTimeEntry>(*this, cli, nonBlock, tail, logMask, pid, start,
+ sequence, timeout);
if (!entry->startReader_Locked()) {
LogTimeEntry::unlock();
return false;
diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp
index 208d67f..ed8d2f5 100644
--- a/logd/LogTimes.cpp
+++ b/logd/LogTimes.cpp
@@ -18,8 +18,6 @@
#include <string.h>
#include <sys/prctl.h>
-#include <private/android_logger.h>
-
#include "FlushCommand.h"
#include "LogBuffer.h"
#include "LogReader.h"
@@ -27,9 +25,9 @@
pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
-LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client,
- bool nonBlock, unsigned long tail, log_mask_t logMask,
- pid_t pid, log_time start, uint64_t timeout)
+LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock,
+ unsigned long tail, log_mask_t logMask, pid_t pid, log_time start_time,
+ uint64_t start, uint64_t timeout)
: leadingDropped(false),
mReader(reader),
mLogMask(logMask),
@@ -38,9 +36,9 @@
mTail(tail),
mIndex(0),
mClient(client),
+ mStartTime(start_time),
mStart(start),
- mNonBlock(nonBlock),
- mEnd(log_time(android_log_clockid())) {
+ mNonBlock(nonBlock) {
mTimeout.tv_sec = timeout / NS_PER_SEC;
mTimeout.tv_nsec = timeout % NS_PER_SEC;
memset(mLastTid, 0, sizeof(mLastTid));
@@ -81,12 +79,12 @@
wrlock();
- log_time start = me->mStart;
+ uint64_t start = me->mStart;
while (!me->mRelease) {
if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
- if (pthread_cond_timedwait(&me->threadTriggeredCondition,
- ×Lock, &me->mTimeout) == ETIMEDOUT) {
+ if (pthread_cond_clockwait(&me->threadTriggeredCondition, ×Lock, CLOCK_MONOTONIC,
+ &me->mTimeout) == ETIMEDOUT) {
me->mTimeout.tv_sec = 0;
me->mTimeout.tv_nsec = 0;
}
@@ -105,13 +103,22 @@
start = logbuf.flushTo(client, start, me->mLastTid, privileged,
security, FilterSecondPass, me);
+ // We only ignore entries before the original start time for the first flushTo(), if we
+ // get entries after this first flush before the original start time, then the client
+ // wouldn't have seen them.
+ // Note: this is still racy and may skip out of order events that came in since the last
+ // time the client disconnected and then reconnected with the new start time. The long term
+ // solution here is that clients must request events since a specific sequence number.
+ me->mStartTime.tv_sec = 0;
+ me->mStartTime.tv_nsec = 0;
+
wrlock();
if (start == LogBufferElement::FLUSH_ERROR) {
break;
}
- me->mStart = start + log_time(0, 1);
+ me->mStart = start + 1;
if (me->mNonBlock || me->mRelease) {
break;
@@ -158,11 +165,11 @@
}
if (me->mCount == 0) {
- me->mStart = element->getRealTime();
+ me->mStart = element->getSequence();
}
- if ((!me->mPid || (me->mPid == element->getPid())) &&
- (me->isWatching(element->getLogId()))) {
+ if ((!me->mPid || me->mPid == element->getPid()) && me->isWatching(element->getLogId()) &&
+ (me->mStartTime == log_time::EPOCH || me->mStartTime <= element->getRealTime())) {
++me->mCount;
}
@@ -177,7 +184,7 @@
LogTimeEntry::wrlock();
- me->mStart = element->getRealTime();
+ me->mStart = element->getSequence();
if (me->skipAhead[element->getLogId()]) {
me->skipAhead[element->getLogId()]--;
@@ -204,6 +211,10 @@
goto skip;
}
+ if (me->mStartTime != log_time::EPOCH && element->getRealTime() <= me->mStartTime) {
+ goto skip;
+ }
+
if (me->mRelease) {
goto stop;
}
diff --git a/logd/LogTimes.h b/logd/LogTimes.h
index 9f6f203..a99c73b 100644
--- a/logd/LogTimes.h
+++ b/logd/LogTimes.h
@@ -49,16 +49,16 @@
unsigned long mTail;
unsigned long mIndex;
- public:
- LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock,
- unsigned long tail, log_mask_t logMask, pid_t pid,
- log_time start, uint64_t timeout);
+ public:
+ LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock, unsigned long tail,
+ log_mask_t logMask, pid_t pid, log_time start_time, uint64_t sequence,
+ uint64_t timeout);
SocketClient* mClient;
- log_time mStart;
- struct timespec mTimeout;
+ log_time mStartTime;
+ uint64_t mStart;
+ struct timespec mTimeout; // CLOCK_MONOTONIC based timeout used for log wrapping.
const bool mNonBlock;
- const log_time mEnd; // only relevant if mNonBlock
// Protect List manipulations
static void wrlock(void) {