tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity
platform_system_core/logd/LogBuffer.cpp
Mark Salyzyn 4ed16b4381 Revert "logd: Add minimum time bucket statistics" 
This forward port reverts
    commit e457b74ce6

No longer as necessary once we add
    liblog: Instrument logging of logd write drops
Although this provided an indication of how close statistically we
were to overloading logd it is simpler to understand fails thus to
hunt and peck a corrected value for /proc/sys/net/unix/max_dgram_qlen

Change-Id: I2b30e0fc30625a48fd11a12c2d2cc6a41f26226f
2015-03-04 13:21:41 -08:00

498 lines
14 KiB
C++
Raw Blame History

/*
* 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 <ctype.h>
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sys/user.h>
#include <time.h>
#include <unistd.h>
#include <cutils/properties.h>
#include <log/logger.h>
#include "LogBuffer.h"
#include "LogReader.h"
#include "LogStatistics.h"
#include "LogWhiteBlackList.h"
// Default
#define LOG_BUFFER_SIZE (256 * 1024) // Tuned on a per-platform basis here?
#define log_buffer_size(id) mMaxSize[id]
#define LOG_BUFFER_MIN_SIZE (64 * 1024UL)
#define LOG_BUFFER_MAX_SIZE (256 * 1024 * 1024UL)
static bool valid_size(unsigned long value) {
if ((value < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < value)) {
return false;
}
long pages = sysconf(_SC_PHYS_PAGES);
if (pages < 1) {
return true;
}
long pagesize = sysconf(_SC_PAGESIZE);
if (pagesize <= 1) {
pagesize = PAGE_SIZE;
}
// maximum memory impact a somewhat arbitrary ~3%
pages = (pages + 31) / 32;
unsigned long maximum = pages * pagesize;
if ((maximum < LOG_BUFFER_MIN_SIZE) || (LOG_BUFFER_MAX_SIZE < maximum)) {
return true;
}
return value <= maximum;
}
static unsigned long property_get_size(const char *key) {
char property[PROPERTY_VALUE_MAX];
property_get(key, property, "");
char *cp;
unsigned long value = strtoul(property, &cp, 10);
switch(*cp) {
case 'm':
case 'M':
value *= 1024;
/* FALLTHRU */
case 'k':
case 'K':
value *= 1024;
/* FALLTHRU */
case '\0':
break;
default:
value = 0;
}
if (!valid_size(value)) {
value = 0;
}
return value;
}
LogBuffer::LogBuffer(LastLogTimes *times)
: mTimes(*times) {
pthread_mutex_init(&mLogElementsLock, NULL);
static const char global_tuneable[] = "persist.logd.size"; // Settings App
static const char global_default[] = "ro.logd.size"; // BoardConfig.mk
unsigned long default_size = property_get_size(global_tuneable);
if (!default_size) {
default_size = property_get_size(global_default);
}
log_id_for_each(i) {
char key[PROP_NAME_MAX];
snprintf(key, sizeof(key), "%s.%s",
global_tuneable, android_log_id_to_name(i));
unsigned long property_size = property_get_size(key);
if (!property_size) {
snprintf(key, sizeof(key), "%s.%s",
global_default, android_log_id_to_name(i));
property_size = property_get_size(key);
}
if (!property_size) {
property_size = default_size;
}
if (!property_size) {
property_size = LOG_BUFFER_SIZE;
}
if (setSize(i, property_size)) {
setSize(i, LOG_BUFFER_MIN_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 (last != mLogElements.begin()) {
--it;
if ((*it)->getRealTime() <= realtime) {
break;
}
last = it;
}
if (last == mLogElements.end()) {
mLogElements.push_back(elem);
} else {
log_time end = log_time::EPOCH;
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, uid_t caller_uid) {
LogTimeEntry *oldest = NULL;
LogTimeEntry::lock();
// Region locked?
LastLogTimes::iterator t = mTimes.begin();
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
if (entry->owned_Locked() && entry->isWatching(id)
&& (!oldest || (oldest->mStart > entry->mStart))) {
oldest = entry;
}
t++;
}
LogBufferElementCollection::iterator it;
if (caller_uid != AID_ROOT) {
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 == caller_uid) {
it = mLogElements.erase(it);
stats.subtract(e->getMsgLen(), id, uid, e->getPid());
delete e;
pruneRows--;
if (pruneRows == 0) {
break;
}
} else {
++it;
}
}
LogTimeEntry::unlock();
return;
}
// 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);
l.sort();
UidStatisticsCollection::iterator iu = l.begin();
if (iu != l.end()) {
UidStatistics *u = *iu;
worst = u->getUid();
worst_sizes = u->sizes();
if (++iu != l.end()) {
second_worst_sizes = (*iu)->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) || mPrune.naughty(e)) { // Worst or BlackListed
it = mLogElements.erase(it);
unsigned short len = e->getMsgLen();
stats.subtract(len, id, uid, e->getPid());
delete e;
pruneRows--;
if (uid == worst) {
kick = true;
if ((pruneRows == 0) || (worst_sizes < second_worst_sizes)) {
break;
}
worst_sizes -= len;
} else 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(id, 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(id, 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, uid_t uid) {
pthread_mutex_lock(&mLogElementsLock);
prune(id, ULONG_MAX, uid);
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 (!valid_size(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);
if (start == LogTimeEntry::EPOCH) {
// client wants to start from the beginning
it = mLogElements.begin();
} else {
// 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->getMonotonicTime() <= start) {
it++;
break;
}
}
}
for (; 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);
}
Reference in a new issue View git blame Copy permalink