blob: 8dcab87fd3e30834d82f8536a25ee594e02e9fb3 [file] [log] [blame]
/*
* Copyright (C) 2012-2014 The Android Open Source Project
*
* Licensed under the Apache License, Version 2.0 (the "License");
* you may not use this file except in compliance with the License.
* You may obtain a copy of the License at
*
* http://www.apache.org/licenses/LICENSE-2.0
*
* Unless required by applicable law or agreed to in writing, software
* distributed under the License is distributed on an "AS IS" BASIS,
* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
* See the License for the specific language governing permissions and
* limitations under the License.
*/
#include <stdio.h>
#include <string.h>
#include <time.h>
#include <unistd.h>
#include <log/logger.h>
#include "LogBuffer.h"
#include "LogStatistics.h"
#include "LogWhiteBlackList.h"
#include "LogReader.h"
// Default
#define LOG_BUFFER_SIZE (256 * 1024) // Tuned on a per-platform basis here?
#define log_buffer_size(id) mMaxSize[id]
LogBuffer::LogBuffer(LastLogTimes *times)
: mTimes(*times) {
pthread_mutex_init(&mLogElementsLock, NULL);
dgram_qlen_statistics = false;
log_id_for_each(i) {
mMaxSize[i] = LOG_BUFFER_SIZE;
}
}
void LogBuffer::log(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, pid_t tid,
const char *msg, unsigned short len) {
if ((log_id >= LOG_ID_MAX) || (log_id < 0)) {
return;
}
LogBufferElement *elem = new LogBufferElement(log_id, realtime,
uid, pid, tid, msg, len);
pthread_mutex_lock(&mLogElementsLock);
// 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;
while (--it != mLogElements.begin()) {
if ((*it)->getRealTime() <= realtime) {
// halves the peak performance, use with caution
if (dgram_qlen_statistics) {
LogBufferElementCollection::iterator ib = it;
unsigned short buckets, num = 1;
for (unsigned short i = 0; (buckets = stats.dgram_qlen(i)); ++i) {
buckets -= num;
num += buckets;
while (buckets && (--ib != mLogElements.begin())) {
--buckets;
}
if (buckets) {
break;
}
stats.recordDiff(
elem->getRealTime() - (*ib)->getRealTime(), i);
}
}
break;
}
last = it;
}
if (last == mLogElements.end()) {
mLogElements.push_back(elem);
} else {
log_time end;
bool end_set = false;
bool end_always = false;
LogTimeEntry::lock();
LastLogTimes::iterator t = mTimes.begin();
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
if (entry->owned_Locked()) {
if (!entry->mNonBlock) {
end_always = true;
break;
}
if (!end_set || (end <= entry->mEnd)) {
end = entry->mEnd;
end_set = true;
}
}
t++;
}
if (end_always
|| (end_set && (end >= (*last)->getMonotonicTime()))) {
mLogElements.push_back(elem);
} else {
mLogElements.insert(last,elem);
}
LogTimeEntry::unlock();
}
stats.add(len, log_id, uid, pid);
maybePrune(log_id);
pthread_mutex_unlock(&mLogElementsLock);
}
// If we're using more than 256K of memory for log entries, prune
// at least 10% of the log entries.
//
// mLogElementsLock must be held when this function is called.
void LogBuffer::maybePrune(log_id_t id) {
size_t sizes = stats.sizes(id);
if (sizes > log_buffer_size(id)) {
size_t sizeOver90Percent = sizes - ((log_buffer_size(id) * 9) / 10);
size_t elements = stats.elements(id);
unsigned long pruneRows = elements * sizeOver90Percent / sizes;
elements /= 10;
if (pruneRows <= elements) {
pruneRows = elements;
}
prune(id, pruneRows);
}
}
// prune "pruneRows" of type "id" from the buffer.
//
// mLogElementsLock must be held when this function is called.
void LogBuffer::prune(log_id_t id, unsigned long pruneRows) {
LogTimeEntry *oldest = NULL;
LogTimeEntry::lock();
// Region locked?
LastLogTimes::iterator t = mTimes.begin();
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
if (entry->owned_Locked()
&& (!oldest || (oldest->mStart > entry->mStart))) {
oldest = entry;
}
t++;
}
LogBufferElementCollection::iterator it;
// prune by worst offender by uid
while (pruneRows > 0) {
// recalculate the worst offender on every batched pass
uid_t worst = (uid_t) -1;
size_t worst_sizes = 0;
size_t second_worst_sizes = 0;
if ((id != LOG_ID_CRASH) && mPrune.worstUidEnabled()) {
LidStatistics &l = stats.id(id);
UidStatisticsCollection::iterator iu;
for (iu = l.begin(); iu != l.end(); ++iu) {
UidStatistics *u = (*iu);
size_t sizes = u->sizes();
if (worst_sizes < sizes) {
second_worst_sizes = worst_sizes;
worst_sizes = sizes;
worst = u->getUid();
}
if ((second_worst_sizes < sizes) && (sizes < worst_sizes)) {
second_worst_sizes = sizes;
}
}
}
bool kick = false;
for(it = mLogElements.begin(); it != mLogElements.end();) {
LogBufferElement *e = *it;
if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
break;
}
if (e->getLogId() != id) {
++it;
continue;
}
uid_t uid = e->getUid();
if (uid == worst) {
it = mLogElements.erase(it);
unsigned short len = e->getMsgLen();
stats.subtract(len, id, worst, e->getPid());
delete e;
kick = true;
pruneRows--;
if ((pruneRows == 0) || (worst_sizes < second_worst_sizes)) {
break;
}
worst_sizes -= len;
} else if (mPrune.naughty(e)) { // BlackListed
it = mLogElements.erase(it);
stats.subtract(e->getMsgLen(), id, uid, e->getPid());
delete e;
pruneRows--;
if (pruneRows == 0) {
break;
}
} else {
++it;
}
}
if (!kick || !mPrune.worstUidEnabled()) {
break; // the following loop will ask bad clients to skip/drop
}
}
bool whitelist = false;
it = mLogElements.begin();
while((pruneRows > 0) && (it != mLogElements.end())) {
LogBufferElement *e = *it;
if (e->getLogId() == id) {
if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
if (!whitelist) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else {
oldest->triggerSkip_Locked(pruneRows);
}
}
break;
}
if (mPrune.nice(e)) { // WhiteListed
whitelist = true;
it++;
continue;
}
it = mLogElements.erase(it);
stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
delete e;
pruneRows--;
} else {
it++;
}
}
if (whitelist && (pruneRows > 0)) {
it = mLogElements.begin();
while((it != mLogElements.end()) && (pruneRows > 0)) {
LogBufferElement *e = *it;
if (e->getLogId() == id) {
if (oldest && (oldest->mStart <= e->getMonotonicTime())) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else {
oldest->triggerSkip_Locked(pruneRows);
}
break;
}
it = mLogElements.erase(it);
stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid());
delete e;
pruneRows--;
} else {
it++;
}
}
}
LogTimeEntry::unlock();
}
// clear all rows of type "id" from the buffer.
void LogBuffer::clear(log_id_t id) {
pthread_mutex_lock(&mLogElementsLock);
prune(id, ULONG_MAX);
pthread_mutex_unlock(&mLogElementsLock);
}
// get the used space associated with "id".
unsigned long LogBuffer::getSizeUsed(log_id_t id) {
pthread_mutex_lock(&mLogElementsLock);
size_t retval = stats.sizes(id);
pthread_mutex_unlock(&mLogElementsLock);
return retval;
}
// set the total space allocated to "id"
int LogBuffer::setSize(log_id_t id, unsigned long size) {
// Reasonable limits ...
if ((size < (64 * 1024)) || ((256 * 1024 * 1024) < size)) {
return -1;
}
pthread_mutex_lock(&mLogElementsLock);
log_buffer_size(id) = size;
pthread_mutex_unlock(&mLogElementsLock);
return 0;
}
// get the total space allocated to "id"
unsigned long LogBuffer::getSize(log_id_t id) {
pthread_mutex_lock(&mLogElementsLock);
size_t retval = log_buffer_size(id);
pthread_mutex_unlock(&mLogElementsLock);
return retval;
}
log_time LogBuffer::flushTo(
SocketClient *reader, const log_time start, bool privileged,
bool (*filter)(const LogBufferElement *element, void *arg), void *arg) {
LogBufferElementCollection::iterator it;
log_time max = start;
uid_t uid = reader->getUid();
pthread_mutex_lock(&mLogElementsLock);
for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
LogBufferElement *element = *it;
if (!privileged && (element->getUid() != uid)) {
continue;
}
if (element->getMonotonicTime() <= start) {
continue;
}
// NB: calling out to another object with mLogElementsLock held (safe)
if (filter && !(*filter)(element, arg)) {
continue;
}
pthread_mutex_unlock(&mLogElementsLock);
// range locking in LastLogTimes looks after us
max = element->flushTo(reader);
if (max == element->FLUSH_ERROR) {
return max;
}
pthread_mutex_lock(&mLogElementsLock);
}
pthread_mutex_unlock(&mLogElementsLock);
return max;
}
void LogBuffer::formatStatistics(char **strp, uid_t uid, unsigned int logMask) {
log_time oldest(CLOCK_MONOTONIC);
pthread_mutex_lock(&mLogElementsLock);
// Find oldest element in the log(s)
LogBufferElementCollection::iterator it;
for (it = mLogElements.begin(); it != mLogElements.end(); ++it) {
LogBufferElement *element = *it;
if ((logMask & (1 << element->getLogId()))) {
oldest = element->getMonotonicTime();
break;
}
}
stats.format(strp, uid, logMask, oldest);
pthread_mutex_unlock(&mLogElementsLock);
}