logd: replace internal CLOCK_MONOTONIC use with sequence numbers
- switch to simpler and faster internal sequence number, drops
a syscall overhead on 32-bit platforms.
- add ability to break-out of flushTo loop with filter return -1
allowing in reduction in reader overhead.
Change-Id: Ic5cb2b9afa4d9470153971fc9197b07279e2b79d
diff --git a/logd/FlushCommand.cpp b/logd/FlushCommand.cpp
index 3be07c0..26a1861 100644
--- a/logd/FlushCommand.cpp
+++ b/logd/FlushCommand.cpp
@@ -27,7 +27,7 @@
unsigned long tail,
unsigned int logMask,
pid_t pid,
- log_time start)
+ uint64_t start)
: mReader(reader)
, mNonBlock(nonBlock)
, mTail(tail)
diff --git a/logd/FlushCommand.h b/logd/FlushCommand.h
index f34c06a..61c6858 100644
--- a/logd/FlushCommand.h
+++ b/logd/FlushCommand.h
@@ -31,7 +31,7 @@
unsigned long mTail;
unsigned int mLogMask;
pid_t mPid;
- log_time mStart;
+ uint64_t mStart;
public:
FlushCommand(LogReader &mReader,
@@ -39,7 +39,7 @@
unsigned long tail = -1,
unsigned int logMask = -1,
pid_t pid = 0,
- log_time start = LogTimeEntry::EPOCH);
+ uint64_t start = 1);
virtual void runSocketCommand(SocketClient *client);
static bool hasReadLogs(SocketClient *client);
diff --git a/logd/LogBuffer.cpp b/logd/LogBuffer.cpp
index 2b495ab..2693583 100644
--- a/logd/LogBuffer.cpp
+++ b/logd/LogBuffer.cpp
@@ -161,7 +161,7 @@
if (last == mLogElements.end()) {
mLogElements.push_back(elem);
} else {
- log_time end = log_time::EPOCH;
+ uint64_t end = 1;
bool end_set = false;
bool end_always = false;
@@ -184,7 +184,7 @@
}
if (end_always
- || (end_set && (end >= (*last)->getMonotonicTime()))) {
+ || (end_set && (end >= (*last)->getSequence()))) {
mLogElements.push_back(elem);
} else {
mLogElements.insert(last,elem);
@@ -241,7 +241,7 @@
for(it = mLogElements.begin(); it != mLogElements.end();) {
LogBufferElement *e = *it;
- if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+ if (oldest && (oldest->mStart <= e->getSequence())) {
break;
}
@@ -293,7 +293,7 @@
for(it = mLogElements.begin(); it != mLogElements.end();) {
LogBufferElement *e = *it;
- if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+ if (oldest && (oldest->mStart <= e->getSequence())) {
break;
}
@@ -334,7 +334,7 @@
while((pruneRows > 0) && (it != mLogElements.end())) {
LogBufferElement *e = *it;
if (e->getLogId() == id) {
- if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+ if (oldest && (oldest->mStart <= e->getSequence())) {
if (!whitelist) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
@@ -366,7 +366,7 @@
while((it != mLogElements.end()) && (pruneRows > 0)) {
LogBufferElement *e = *it;
if (e->getLogId() == id) {
- if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
+ if (oldest && (oldest->mStart <= e->getSequence())) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
@@ -423,16 +423,16 @@
return retval;
}
-log_time LogBuffer::flushTo(
- SocketClient *reader, const log_time start, bool privileged,
- bool (*filter)(const LogBufferElement *element, void *arg), void *arg) {
+uint64_t LogBuffer::flushTo(
+ SocketClient *reader, const uint64_t start, bool privileged,
+ int (*filter)(const LogBufferElement *element, void *arg), void *arg) {
LogBufferElementCollection::iterator it;
- log_time max = start;
+ uint64_t max = start;
uid_t uid = reader->getUid();
pthread_mutex_lock(&mLogElementsLock);
- if (start == LogTimeEntry::EPOCH) {
+ if (start <= 1) {
// client wants to start from the beginning
it = mLogElements.begin();
} else {
@@ -441,7 +441,7 @@
for (it = mLogElements.end(); it != mLogElements.begin(); /* do nothing */) {
--it;
LogBufferElement *element = *it;
- if (element->getMonotonicTime() <= start) {
+ if (element->getSequence() <= start) {
it++;
break;
}
@@ -455,13 +455,19 @@
continue;
}
- if (element->getMonotonicTime() <= start) {
+ if (element->getSequence() <= start) {
continue;
}
// NB: calling out to another object with mLogElementsLock held (safe)
- if (filter && !(*filter)(element, arg)) {
- continue;
+ if (filter) {
+ int ret = (*filter)(element, arg);
+ if (ret == false) {
+ continue;
+ }
+ if (ret != true) {
+ break;
+ }
}
pthread_mutex_unlock(&mLogElementsLock);
@@ -481,7 +487,7 @@
}
void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) {
- log_time oldest(CLOCK_MONOTONIC);
+ uint64_t oldest = UINT64_MAX;
pthread_mutex_lock(&mLogElementsLock);
@@ -491,7 +497,7 @@
LogBufferElement *element = *it;
if ((logMask & (1 << element->getLogId()))) {
- oldest = element->getMonotonicTime();
+ oldest = element->getSequence();
break;
}
}
diff --git a/logd/LogBuffer.h b/logd/LogBuffer.h
index 86a2a2a..13e6aa8 100644
--- a/logd/LogBuffer.h
+++ b/logd/LogBuffer.h
@@ -51,9 +51,9 @@
void log(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, pid_t tid,
const char *msg, unsigned short len);
- log_time flushTo(SocketClient *writer, const log_time start,
+ uint64_t flushTo(SocketClient *writer, const uint64_t start,
bool privileged,
- bool (*filter)(const LogBufferElement *element, void *arg) = NULL,
+ int (*filter)(const LogBufferElement *element, void *arg) = NULL,
void *arg = NULL);
void clear(log_id_t id, uid_t uid = AID_ROOT);
diff --git a/logd/LogBufferElement.cpp b/logd/LogBufferElement.cpp
index d959ceb..5e780b5 100644
--- a/logd/LogBufferElement.cpp
+++ b/logd/LogBufferElement.cpp
@@ -24,7 +24,8 @@
#include "LogBufferElement.h"
#include "LogReader.h"
-const log_time LogBufferElement::FLUSH_ERROR((uint32_t)0, (uint32_t)0);
+const uint64_t LogBufferElement::FLUSH_ERROR(0);
+atomic_int_fast64_t LogBufferElement::sequence;
LogBufferElement::LogBufferElement(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, pid_t tid,
@@ -34,7 +35,7 @@
, mPid(pid)
, mTid(tid)
, mMsgLen(len)
- , mMonotonicTime(CLOCK_MONOTONIC)
+ , mSequence(sequence.fetch_add(1, memory_order_relaxed))
, mRealTime(realtime) {
mMsg = new char[len];
memcpy(mMsg, msg, len);
@@ -44,7 +45,7 @@
delete [] mMsg;
}
-log_time LogBufferElement::flushTo(SocketClient *reader) {
+uint64_t LogBufferElement::flushTo(SocketClient *reader) {
struct logger_entry_v3 entry;
memset(&entry, 0, sizeof(struct logger_entry_v3));
entry.hdr_size = sizeof(struct logger_entry_v3);
@@ -64,5 +65,5 @@
return FLUSH_ERROR;
}
- return mMonotonicTime;
+ return mSequence;
}
diff --git a/logd/LogBufferElement.h b/logd/LogBufferElement.h
index fdca973..25f1450 100644
--- a/logd/LogBufferElement.h
+++ b/logd/LogBufferElement.h
@@ -18,6 +18,7 @@
#define _LOGD_LOG_BUFFER_ELEMENT_H__
#include <sys/types.h>
+#include <stdatomic.h>
#include <sysutils/SocketClient.h>
#include <log/log.h>
#include <log/log_read.h>
@@ -29,8 +30,9 @@
const pid_t mTid;
char *mMsg;
const unsigned short mMsgLen;
- const log_time mMonotonicTime;
+ const uint64_t mSequence;
const log_time mRealTime;
+ static atomic_int_fast64_t sequence;
public:
LogBufferElement(log_id_t log_id, log_time realtime,
@@ -43,11 +45,12 @@
pid_t getPid(void) const { return mPid; }
pid_t getTid(void) const { return mTid; }
unsigned short getMsgLen() const { return mMsgLen; }
- log_time getMonotonicTime(void) const { return mMonotonicTime; }
+ 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 log_time FLUSH_ERROR;
- log_time flushTo(SocketClient *writer);
+ static const uint64_t FLUSH_ERROR;
+ uint64_t flushTo(SocketClient *writer);
};
#endif
diff --git a/logd/LogReader.cpp b/logd/LogReader.cpp
index 26df087..f7df275 100644
--- a/logd/LogReader.cpp
+++ b/logd/LogReader.cpp
@@ -100,50 +100,51 @@
nonBlock = true;
}
- // Convert realtime to monotonic time
- if (start == log_time::EPOCH) {
- start = LogTimeEntry::EPOCH;
- } else {
+ uint64_t sequence = 1;
+ // Convert realtime to sequence number
+ if (start != log_time::EPOCH) {
class LogFindStart {
const pid_t mPid;
const unsigned mLogMask;
bool startTimeSet;
log_time &start;
- log_time last;
+ uint64_t &sequence;
+ uint64_t last;
public:
- LogFindStart(unsigned logMask, pid_t pid, log_time &start)
+ LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence)
: mPid(pid)
, mLogMask(logMask)
, startTimeSet(false)
, start(start)
- , last(LogTimeEntry::EPOCH)
+ , sequence(sequence)
+ , last(sequence)
{ }
- static bool callback(const LogBufferElement *element, void *obj) {
+ static int callback(const LogBufferElement *element, void *obj) {
LogFindStart *me = reinterpret_cast<LogFindStart *>(obj);
- if (!me->startTimeSet
- && (!me->mPid || (me->mPid == element->getPid()))
+ if ((!me->mPid || (me->mPid == element->getPid()))
&& (me->mLogMask & (1 << element->getLogId()))) {
if (me->start == element->getRealTime()) {
- me->start = element->getMonotonicTime();
+ me->sequence = element->getSequence();
me->startTimeSet = true;
+ return -1;
} else {
if (me->start < element->getRealTime()) {
- me->start = me->last;
+ me->sequence = me->last;
me->startTimeSet = true;
+ return -1;
}
- me->last = element->getMonotonicTime();
+ me->last = element->getSequence();
}
}
return false;
}
bool found() { return startTimeSet; }
- } logFindStart(logMask, pid, start);
+ } logFindStart(logMask, pid, start, sequence);
- logbuf().flushTo(cli, LogTimeEntry::EPOCH,
- FlushCommand::hasReadLogs(cli),
+ logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli),
logFindStart.callback, &logFindStart);
if (!logFindStart.found()) {
@@ -151,12 +152,11 @@
doSocketDelete(cli);
return false;
}
- log_time now(CLOCK_MONOTONIC);
- start = now;
+ sequence = LogBufferElement::getCurrentSequence();
}
}
- FlushCommand command(*this, nonBlock, tail, logMask, pid, start);
+ FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence);
command.runSocketCommand(cli);
return true;
}
diff --git a/logd/LogTimes.cpp b/logd/LogTimes.cpp
index 5f9db8d..1b60b7e 100644
--- a/logd/LogTimes.cpp
+++ b/logd/LogTimes.cpp
@@ -23,12 +23,10 @@
pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
-const struct timespec LogTimeEntry::EPOCH = { 0, 1 };
-
LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid,
- log_time start)
+ uint64_t start)
: mRefCount(1)
, mRelease(false)
, mError(false)
@@ -42,7 +40,7 @@
, mClient(client)
, mStart(start)
, mNonBlock(nonBlock)
- , mEnd(CLOCK_MONOTONIC)
+ , mEnd(LogBufferElement::getCurrentSequence())
{
pthread_cond_init(&threadTriggeredCondition, NULL);
cleanSkip_Locked();
@@ -129,7 +127,7 @@
lock();
while (me->threadRunning && !me->isError_Locked()) {
- log_time start = me->mStart;
+ uint64_t start = me->mStart;
unlock();
@@ -161,13 +159,13 @@
}
// A first pass to count the number of elements
-bool LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) {
+int LogTimeEntry::FilterFirstPass(const LogBufferElement *element, void *obj) {
LogTimeEntry *me = reinterpret_cast<LogTimeEntry *>(obj);
LogTimeEntry::lock();
if (me->mCount == 0) {
- me->mStart = element->getMonotonicTime();
+ me->mStart = element->getSequence();
}
if ((!me->mPid || (me->mPid == element->getPid()))
@@ -181,12 +179,12 @@
}
// A second pass to send the selected elements
-bool LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) {
+int LogTimeEntry::FilterSecondPass(const LogBufferElement *element, void *obj) {
LogTimeEntry *me = reinterpret_cast<LogTimeEntry *>(obj);
LogTimeEntry::lock();
- me->mStart = element->getMonotonicTime();
+ me->mStart = element->getSequence();
if (me->skipAhead[element->getLogId()]) {
me->skipAhead[element->getLogId()]--;
@@ -195,7 +193,7 @@
// Truncate to close race between first and second pass
if (me->mNonBlock && me->mTail && (me->mIndex >= me->mCount)) {
- goto skip;
+ goto stop;
}
if (!me->isWatching(element->getLogId())) {
@@ -207,7 +205,7 @@
}
if (me->isError_Locked()) {
- goto skip;
+ goto stop;
}
if (!me->mTail) {
@@ -234,6 +232,10 @@
skip:
LogTimeEntry::unlock();
return false;
+
+stop:
+ LogTimeEntry::unlock();
+ return -1;
}
void LogTimeEntry::cleanSkip_Locked(void) {
diff --git a/logd/LogTimes.h b/logd/LogTimes.h
index 81aedfb..ae2f92b 100644
--- a/logd/LogTimes.h
+++ b/logd/LogTimes.h
@@ -47,13 +47,12 @@
public:
LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock,
unsigned long tail, unsigned int logMask, pid_t pid,
- log_time start);
+ uint64_t start);
SocketClient *mClient;
- static const struct timespec EPOCH;
- log_time mStart;
+ uint64_t mStart;
const bool mNonBlock;
- const log_time mEnd; // only relevant if mNonBlock
+ const uint64_t mEnd; // only relevant if mNonBlock
// Protect List manipulations
static void lock(void) { pthread_mutex_lock(×Lock); }
@@ -103,8 +102,8 @@
}
bool isWatching(log_id_t id) { return (mLogMask & (1<<id)) != 0; }
// flushTo filter callbacks
- static bool FilterFirstPass(const LogBufferElement *element, void *me);
- static bool FilterSecondPass(const LogBufferElement *element, void *me);
+ static int FilterFirstPass(const LogBufferElement *element, void *me);
+ static int FilterSecondPass(const LogBufferElement *element, void *me);
};
typedef android::List<LogTimeEntry *> LastLogTimes;