/* * 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 #include #include #include #include #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? #ifdef USERDEBUG_BUILD #define log_buffer_size(id) mMaxSize[id] #else #define log_buffer_size(id) LOG_BUFFER_SIZE #endif 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; #ifdef USERDEBUG_BUILD if (mPrune.worstUidEnabled()) #endif { 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; } #ifdef USERDEBUG_BUILD 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; } } #endif else { ++it; } } if (!kick #ifdef USERDEBUG_BUILD || !mPrune.worstUidEnabled() #endif ) { break; // the following loop will ask bad clients to skip/drop } } #ifdef USERDEBUG_BUILD bool whitelist = false; #endif it = mLogElements.begin(); while((pruneRows > 0) && (it != mLogElements.end())) { LogBufferElement *e = *it; if (e->getLogId() == id) { if (oldest && (oldest->mStart <= e->getMonotonicTime())) { #ifdef USERDEBUG_BUILD if (!whitelist) #endif { 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; } #ifdef USERDEBUG_BUILD if (mPrune.nice(e)) { // WhiteListed whitelist = true; it++; continue; } #endif it = mLogElements.erase(it); stats.subtract(e->getMsgLen(), id, e->getUid(), e->getPid()); delete e; pruneRows--; } else { it++; } } #ifdef USERDEBUG_BUILD 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++; } } } #endif 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; } #ifdef USERDEBUG_BUILD // 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; } #else // ! USERDEBUG_BUILD // get the total space allocated to "id" unsigned long LogBuffer::getSize(log_id_t /*id*/) { return log_buffer_size(id); } #endif 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); }