tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Merge changes If1a62a90,Ibce79cf1,Ia2bbf01a,I1763be56,I56762747, ...

Browse source 
* 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
This commit is contained in:
Tom Cherry 2020-04-09 17:24:12 +00:00 committed by Gerrit Code Review
commit 56cd920ff8
9 changed files with 115 additions and 207 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

14
logd/FlushCommand.cpp
View file

@ -49,18 +49,8 @@ void FlushCommand::runSocketCommand(SocketClient* client) {
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();

2
logd/FlushCommand.h
View file

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

125
logd/LogBuffer.cpp
View file

@ -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 @@ int LogBuffer::log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid,
// 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 @@ class LogBufferElementLast {
}
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 @@ class LogBufferElementLast {
}
};
// 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 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
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 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
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 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
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 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
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 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
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 @@ unsigned long LogBuffer::getSize(log_id_t id) {
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

7
logd/LogBuffer.h
View file

@ -118,11 +118,10 @@ class LogBuffer {
// 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 @@ class LogBuffer {
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);

17
logd/LogBufferElement.cpp
View file

@ -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 @@ LogBufferElement::LogBufferElement(const LogBufferElement& elem)
: 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 @@ size_t LogBufferElement::populateDroppedMessage(char*& buffer, LogBuffer* parent
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 @@ log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool
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 @@ log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent, bool
}
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);

7
logd/LogBufferElement.h
View file

@ -39,6 +39,7 @@ class __attribute__((packed)) LogBufferElement {
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 @@ class __attribute__((packed)) LogBufferElement {
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);
};

95
logd/LogReader.cpp
View file

@ -89,8 +89,7 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
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 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
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 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
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;

41
logd/LogTimes.cpp
View file

@ -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 @@ LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client,
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 @@ void* LogTimeEntry::threadStart(void* obj) {
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,
&timesLock, &me->mTimeout) == ETIMEDOUT) {
if (pthread_cond_clockwait(&me->threadTriggeredCondition, &timesLock, CLOCK_MONOTONIC,
&me->mTimeout) == ETIMEDOUT) {
me->mTimeout.tv_sec = 0;
me->mTimeout.tv_nsec = 0;
}
@ -105,13 +103,22 @@ void* LogTimeEntry::threadStart(void* obj) {
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 @@ int LogTimeEntry::FilterFirstPass(const LogBufferElement* element, void* obj) {
}
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 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement* element, void* obj) {
LogTimeEntry::wrlock();
me->mStart = element->getRealTime();
me->mStart = element->getSequence();
if (me->skipAhead[element->getLogId()]) {
me->skipAhead[element->getLogId()]--;
@ -204,6 +211,10 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement* element, void* obj) {
goto skip;
}
if (me->mStartTime != log_time::EPOCH && element->getRealTime() <= me->mStartTime) {
goto skip;
}
if (me->mRelease) {
goto stop;
}

14
logd/LogTimes.h
View file

@ -49,16 +49,16 @@ class LogTimeEntry {
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) {