Merge changes I2a073293,Ia55ef8b9,I79a385fc am: 82b5c619b8

am: 5a0afe7d27

Change-Id: I7dca568166725342be1f8a2fcf7db7fa250ab394
This commit is contained in:
Mark Salyzyn 2017-03-16 17:16:47 +00:00 committed by android-build-merger
commit 9f8a97ed0b
9 changed files with 101 additions and 90 deletions

View File

@ -27,7 +27,7 @@
#include "LogUtils.h"
FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid, uint64_t start,
unsigned int logMask, pid_t pid, log_time start,
uint64_t timeout)
: mReader(reader),
mNonBlock(nonBlock),
@ -35,7 +35,7 @@ FlushCommand::FlushCommand(LogReader& reader, bool nonBlock, unsigned long tail,
mLogMask(logMask),
mPid(pid),
mStart(start),
mTimeout((start > 1) ? timeout : 0) {
mTimeout((start != log_time::EPOCH) ? timeout : 0) {
}
// runSocketCommand is called once for every open client on the

View File

@ -16,7 +16,7 @@
#ifndef _FLUSH_COMMAND_H
#define _FLUSH_COMMAND_H
#include <android/log.h>
#include <private/android_logger.h>
#include <sysutils/SocketClientCommand.h>
class LogBufferElement;
@ -31,13 +31,13 @@ class FlushCommand : public SocketClientCommand {
unsigned long mTail;
unsigned int mLogMask;
pid_t mPid;
uint64_t mStart;
log_time mStart;
uint64_t mTimeout;
public:
explicit FlushCommand(LogReader& mReader, bool nonBlock = false,
unsigned long tail = -1, unsigned int logMask = -1,
pid_t pid = 0, uint64_t start = 1,
pid_t pid = 0, log_time start = log_time::EPOCH,
uint64_t timeout = 0);
virtual void runSocketCommand(SocketClient* client);

View File

@ -181,7 +181,7 @@ static enum match_type identical(LogBufferElement* elem,
lenr -= avcr - msgr;
if (lenl != lenr) return DIFFERENT;
// TODO: After b/35468874 is addressed, revisit "lenl > strlen(avc)"
// condition, it might become superflous.
// condition, it might become superfluous.
if (lenl > strlen(avc) &&
fastcmp<memcmp>(avcl + strlen(avc), avcr + strlen(avc),
lenl - strlen(avc))) {
@ -374,18 +374,12 @@ void LogBuffer::log(LogBufferElement* elem) {
// NB: if end is region locked, place element at end of list
LogBufferElementCollection::iterator it = mLogElements.end();
LogBufferElementCollection::iterator last = it;
while (last != mLogElements.begin()) {
--it;
if ((*it)->getRealTime() <= elem->getRealTime()) {
break;
}
last = it;
}
if (last == mLogElements.end()) {
if (__predict_true(it != mLogElements.begin())) --it;
if (__predict_false(it == mLogElements.begin()) ||
__predict_true((*it)->getRealTime() <= elem->getRealTime())) {
mLogElements.push_back(elem);
} else {
uint64_t end = 1;
log_time end = log_time::EPOCH;
bool end_set = false;
bool end_always = false;
@ -399,6 +393,7 @@ void LogBuffer::log(LogBufferElement* elem) {
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;
@ -407,12 +402,20 @@ void LogBuffer::log(LogBufferElement* elem) {
times++;
}
if (end_always || (end_set && (end >= (*last)->getSequence()))) {
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();
}
@ -587,12 +590,12 @@ class LogBufferElementLast {
}
void clear(LogBufferElement* element) {
uint64_t current =
element->getRealTime().nsec() - (EXPIRE_RATELIMIT * NS_PER_SEC);
log_time current =
element->getRealTime() - log_time(EXPIRE_RATELIMIT, 0);
for (LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
LogBufferElement* mapElement = it->second;
if ((mapElement->getDropped() >= EXPIRE_THRESHOLD) &&
(current > mapElement->getRealTime().nsec())) {
(current > mapElement->getRealTime())) {
it = map.erase(it);
} else {
++it;
@ -688,7 +691,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getSequence())) {
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
@ -780,7 +783,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
while (it != mLogElements.end()) {
LogBufferElement* element = *it;
if (oldest && (oldest->mStart <= element->getSequence())) {
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
@ -934,7 +937,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getSequence())) {
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true;
if (whitelist) {
break;
@ -978,7 +981,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getSequence())) {
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
busy = true;
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
@ -1071,32 +1074,37 @@ unsigned long LogBuffer::getSize(log_id_t id) {
return retval;
}
uint64_t LogBuffer::flushTo(
SocketClient* reader, const uint64_t start, bool privileged, bool security,
log_time LogBuffer::flushTo(
SocketClient* reader, const log_time& start, bool privileged, bool security,
int (*filter)(const LogBufferElement* element, void* arg), void* arg) {
LogBufferElementCollection::iterator it;
uint64_t max = start;
uid_t uid = reader->getUid();
pthread_mutex_lock(&mLogElementsLock);
if (start <= 1) {
if (start == log_time::EPOCH) {
// client wants to start from the beginning
it = mLogElements.begin();
} else {
LogBufferElementCollection::iterator last = mLogElements.begin();
// 30 second limit to continue search for out-of-order entries.
log_time min = start - log_time(30, 0);
// Client wants to start from some specified time. Chances are
// we are better off starting from the end of the time sorted list.
for (it = mLogElements.end(); it != mLogElements.begin();
/* do nothing */) {
--it;
LogBufferElement* element = *it;
if (element->getSequence() <= start) {
it++;
if (element->getRealTime() > start) {
last = it;
} else if (element->getRealTime() < min) {
break;
}
}
it = last;
}
log_time max = start;
// Help detect if the valid message before is from the same source so
// we can differentiate chatty filter types.
pid_t lastTid[LOG_ID_MAX] = { 0 };
@ -1112,7 +1120,7 @@ uint64_t LogBuffer::flushTo(
continue;
}
if (element->getSequence() <= start) {
if (element->getRealTime() <= start) {
continue;
}

View File

@ -115,7 +115,7 @@ class LogBuffer {
int log(log_id_t log_id, log_time realtime, uid_t uid, pid_t pid, pid_t tid,
const char* msg, unsigned short len);
uint64_t flushTo(SocketClient* writer, const uint64_t start,
log_time flushTo(SocketClient* writer, const log_time& start,
bool privileged, bool security,
int (*filter)(const LogBufferElement* element,
void* arg) = NULL,

View File

@ -30,7 +30,7 @@
#include "LogReader.h"
#include "LogUtils.h"
const uint64_t LogBufferElement::FLUSH_ERROR(0);
const log_time LogBufferElement::FLUSH_ERROR((uint32_t)-1, (uint32_t)-1);
atomic_int_fast64_t LogBufferElement::sequence(1);
LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
@ -39,7 +39,6 @@ LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
: mUid(uid),
mPid(pid),
mTid(tid),
mSequence(sequence.fetch_add(1, memory_order_relaxed)),
mRealTime(realtime),
mMsgLen(len),
mLogId(log_id) {
@ -55,7 +54,6 @@ 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) {
@ -206,7 +204,7 @@ size_t LogBufferElement::populateDroppedMessage(char*& buffer, LogBuffer* parent
return retval;
}
uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
log_time LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
bool privileged, bool lastSame) {
struct logger_entry_v4 entry;
@ -229,7 +227,7 @@ uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
if (!mMsg) {
entry.len = populateDroppedMessage(buffer, parent, lastSame);
if (!entry.len) return mSequence;
if (!entry.len) return mRealTime;
iovec[1].iov_base = buffer;
} else {
entry.len = mMsgLen;
@ -237,7 +235,7 @@ uint64_t LogBufferElement::flushTo(SocketClient* reader, LogBuffer* parent,
}
iovec[1].iov_len = entry.len;
uint64_t retval = reader->sendDatav(iovec, 2) ? FLUSH_ERROR : mSequence;
log_time retval = reader->sendDatav(iovec, 2) ? FLUSH_ERROR : mRealTime;
if (buffer) free(buffer);

View File

@ -40,7 +40,6 @@ class LogBufferElement {
const uint32_t mUid;
const uint32_t mPid;
const uint32_t mTid;
const uint64_t mSequence;
log_time mRealTime;
char* mMsg;
union {
@ -96,18 +95,12 @@ class LogBufferElement {
const char* getMsg() const {
return mMsg;
}
uint64_t getSequence(void) const {
return mSequence;
}
static uint64_t getCurrentSequence(void) {
return sequence.load(memory_order_relaxed);
}
log_time getRealTime(void) const {
return mRealTime;
}
static const uint64_t FLUSH_ERROR;
uint64_t flushTo(SocketClient* writer, LogBuffer* parent, bool privileged,
static const log_time FLUSH_ERROR;
log_time flushTo(SocketClient* writer, LogBuffer* parent, bool privileged,
bool lastSame);
};

View File

@ -116,57 +116,70 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
nonBlock = true;
}
uint64_t sequence = 1;
// Convert realtime to sequence number
if (start != log_time::EPOCH) {
class LogFindStart {
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:
const pid_t mPid;
const unsigned mLogMask;
bool startTimeSet;
log_time& start;
uint64_t& sequence;
uint64_t last;
bool isMonotonic;
bool mStartTimeSet;
log_time mStart;
log_time& mSequence;
log_time mLast;
bool mIsMonotonic;
public:
LogFindStart(unsigned logMask, pid_t pid, log_time& start,
uint64_t& sequence, bool isMonotonic)
LogFindStart(pid_t pid, unsigned logMask, log_time& sequence,
bool isMonotonic)
: mPid(pid),
mLogMask(logMask),
startTimeSet(false),
start(start),
sequence(sequence),
last(sequence),
isMonotonic(isMonotonic) {
mStartTimeSet(false),
mStart(sequence),
mSequence(sequence),
mLast(sequence),
mIsMonotonic(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()))) {
if (me->start == element->getRealTime()) {
me->sequence = element->getSequence();
me->startTimeSet = true;
log_time real = element->getRealTime();
if (me->mStart == real) {
me->mSequence = real;
me->mStartTimeSet = true;
return -1;
} else if (!me->isMonotonic ||
android::isMonotonic(element->getRealTime())) {
if (me->start < element->getRealTime()) {
me->sequence = me->last;
me->startTimeSet = true;
} else if (!me->mIsMonotonic || android::isMonotonic(real)) {
if (me->mStart < real) {
me->mSequence = me->mLast;
me->mStartTimeSet = true;
return -1;
}
me->last = element->getSequence();
me->mLast = real;
} else {
me->last = element->getSequence();
me->mLast = real;
}
}
return false;
}
bool found() {
return startTimeSet;
return mStartTimeSet;
}
} logFindStart(logMask, pid, start, sequence,
} logFindStart(pid, logMask, sequence,
logbuf().isMonotonic() && android::isMonotonic(start));
logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli),
@ -174,11 +187,8 @@ bool LogReader::onDataAvailable(SocketClient* cli) {
logFindStart.callback, &logFindStart);
if (!logFindStart.found()) {
if (nonBlock) {
doSocketDelete(cli);
return false;
}
sequence = LogBufferElement::getCurrentSequence();
doSocketDelete(cli);
return false;
}
}

View File

@ -17,6 +17,8 @@
#include <errno.h>
#include <sys/prctl.h>
#include <private/android_logger.h>
#include "FlushCommand.h"
#include "LogBuffer.h"
#include "LogReader.h"
@ -26,7 +28,7 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client,
bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid, uint64_t start,
unsigned int logMask, pid_t pid, log_time start,
uint64_t timeout)
: mRefCount(1),
mRelease(false),
@ -42,7 +44,7 @@ LogTimeEntry::LogTimeEntry(LogReader& reader, SocketClient* client,
mClient(client),
mStart(start),
mNonBlock(nonBlock),
mEnd(LogBufferElement::getCurrentSequence()) {
mEnd(log_time(android_log_clockid())) {
mTimeout.tv_sec = timeout / NS_PER_SEC;
mTimeout.tv_nsec = timeout % NS_PER_SEC;
pthread_cond_init(&threadTriggeredCondition, NULL);
@ -132,7 +134,7 @@ void* LogTimeEntry::threadStart(void* obj) {
lock();
uint64_t start = me->mStart;
log_time start = me->mStart;
while (me->threadRunning && !me->isError_Locked()) {
if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
@ -163,7 +165,7 @@ void* LogTimeEntry::threadStart(void* obj) {
break;
}
me->mStart = start + 1;
me->mStart = start + log_time(0, 1);
if (me->mNonBlock || !me->threadRunning || me->isError_Locked()) {
break;
@ -198,7 +200,7 @@ int LogTimeEntry::FilterFirstPass(const LogBufferElement* element, void* obj) {
}
if (me->mCount == 0) {
me->mStart = element->getSequence();
me->mStart = element->getRealTime();
}
if ((!me->mPid || (me->mPid == element->getPid())) &&
@ -217,7 +219,7 @@ int LogTimeEntry::FilterSecondPass(const LogBufferElement* element, void* obj) {
LogTimeEntry::lock();
me->mStart = element->getSequence();
me->mStart = element->getRealTime();
if (me->skipAhead[element->getLogId()]) {
me->skipAhead[element->getLogId()]--;

View File

@ -51,13 +51,13 @@ class LogTimeEntry {
public:
LogTimeEntry(LogReader& reader, SocketClient* client, bool nonBlock,
unsigned long tail, unsigned int logMask, pid_t pid,
uint64_t start, uint64_t timeout);
log_time start, uint64_t timeout);
SocketClient* mClient;
uint64_t mStart;
log_time mStart;
struct timespec mTimeout;
const bool mNonBlock;
const uint64_t mEnd; // only relevant if mNonBlock
const log_time mEnd; // only relevant if mNonBlock
// Protect List manipulations
static void lock(void) {