logd: regression in handling watermark boundary.

Deal with a regression introduced in commit
5a34d6ea43 (logd: drop mSequence from
LogBufferElement) where log_time was compared against nsec() time
miscalculating the watermark boundary.  When dealing with logcat
-t/-T, or any tail reading, add a margin to prune to back off by a
period of 3 seconds (pruneMargin).

Test: gTest liblog-unit-tests logcat-unit-tests and logd-unit-tests
Bug: 37378309
Change-Id: I72ea858e4e7b5fa91741ea84c40d2e7c3c4aa031
This commit is contained in:
Mark Salyzyn 2017-04-17 12:46:12 -07:00
parent ffa38cfc1e
commit 5836379b21
2 changed files with 13 additions and 6 deletions

View file

@ -43,6 +43,8 @@
// 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;
@ -672,6 +674,8 @@ 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;
@ -693,7 +697,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
if (oldest && (watermark <= element->getRealTime())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
@ -785,7 +789,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->getRealTime().nsec())) {
if (oldest && (watermark <= element->getRealTime())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
@ -939,7 +943,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
if (oldest && (watermark <= element->getRealTime())) {
busy = true;
if (whitelist) {
break;
@ -983,7 +987,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
mLastSet[id] = true;
}
if (oldest && (oldest->mStart <= element->getRealTime().nsec())) {
if (oldest && (watermark <= element->getRealTime())) {
busy = true;
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
@ -1090,13 +1094,15 @@ log_time LogBuffer::flushTo(SocketClient* reader, const log_time& start,
// client wants to start from the beginning
it = mLogElements.begin();
} else {
LogBufferElementCollection::iterator last;
// 3 second limit to continue search for out-of-order entries.
log_time min = start - log_time(3, 0);
log_time min = start - pruneMargin;
// 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();
/* do nothing */) {
--it;

View file

@ -174,6 +174,7 @@ 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 prune(log_id_t id, unsigned long pruneRows, uid_t uid = AID_ROOT);