tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

logd: Add worst pid of system filter

Browse source 
- Add a new statistic that reports per pid and log_id for AID_SYSTEM
- Add a new pruning filter ~1000/! boolean
- Use this new statistic to prune on worst pid within AID_SYSTEM

Bug: 26029733
Bug: 21615139
Bug: 22855208
Change-Id: Iab5dd28f807dcf03d276372853883f3b6afa8294
This commit is contained in:
Mark Salyzyn 2015-08-28 08:02:59 -07:00
parent 420b64160c
commit bec3c3def9
7 changed files with 224 additions and 81 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

213
logd/LogBuffer.cpp
View file

@ -248,9 +248,9 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
LogTimeEntry::lock();
LastLogTimes::iterator t = mTimes.begin();
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
LastLogTimes::iterator times = mTimes.begin();
while(times != mTimes.end()) {
LogTimeEntry *entry = (*times);
if (entry->owned_Locked()) {
if (!entry->mNonBlock) {
end_always = true;
@ -261,7 +261,7 @@ int LogBuffer::log(log_id_t log_id, log_time realtime,
end_set = true;
}
}
t++;
times++;
}
if (end_always
@ -307,20 +307,35 @@ void LogBuffer::maybePrune(log_id_t id) {
LogBufferElementCollection::iterator LogBuffer::erase(
LogBufferElementCollection::iterator it, bool coalesce) {
LogBufferElement *e = *it;
log_id_t id = e->getLogId();
LogBufferElement *element = *it;
log_id_t id = element->getLogId();
LogBufferIteratorMap::iterator f = mLastWorstUid[id].find(e->getUid());
if ((f != mLastWorstUid[id].end()) && (it == f->second)) {
mLastWorstUid[id].erase(f);
{ // start of scope for uid found iterator
LogBufferIteratorMap::iterator found =
mLastWorstUid[id].find(element->getUid());
if ((found != mLastWorstUid[id].end())
&& (it == found->second)) {
mLastWorstUid[id].erase(found);
}
}
if (element->getUid() == AID_SYSTEM) {
// start of scope for pid found iterator
LogBufferPidIteratorMap::iterator found =
mLastWorstPidOfSystem[id].find(element->getPid());
if ((found != mLastWorstPidOfSystem[id].end())
&& (it == found->second)) {
mLastWorstPidOfSystem[id].erase(found);
}
}
it = mLogElements.erase(it);
if (coalesce) {
stats.erase(e);
stats.erase(element);
} else {
stats.subtract(e);
stats.subtract(element);
}
delete e;
delete element;
return it;
}
@ -340,8 +355,13 @@ class LogBufferElementKey {
} __packed;
public:
LogBufferElementKey(uid_t u, pid_t p, pid_t t):uid(u),pid(p),tid(t),padding(0) { }
LogBufferElementKey(uint64_t k):value(k) { }
LogBufferElementKey(uid_t uid, pid_t pid, pid_t tid):
uid(uid),
pid(pid),
tid(tid),
padding(0) {
}
LogBufferElementKey(uint64_t key):value(key) { }
uint64_t getKey() { return value; }
};
@ -353,38 +373,42 @@ class LogBufferElementLast {
public:
bool coalesce(LogBufferElement *e, unsigned short dropped) {
LogBufferElementKey key(e->getUid(), e->getPid(), e->getTid());
bool coalesce(LogBufferElement *element, unsigned short dropped) {
LogBufferElementKey key(element->getUid(),
element->getPid(),
element->getTid());
LogBufferElementMap::iterator it = map.find(key.getKey());
if (it != map.end()) {
LogBufferElement *l = it->second;
unsigned short d = l->getDropped();
if ((dropped + d) > USHRT_MAX) {
LogBufferElement *found = it->second;
unsigned short moreDropped = found->getDropped();
if ((dropped + moreDropped) > USHRT_MAX) {
map.erase(it);
} else {
l->setDropped(dropped + d);
found->setDropped(dropped + moreDropped);
return true;
}
}
return false;
}
void add(LogBufferElement *e) {
LogBufferElementKey key(e->getUid(), e->getPid(), e->getTid());
map[key.getKey()] = e;
void add(LogBufferElement *element) {
LogBufferElementKey key(element->getUid(),
element->getPid(),
element->getTid());
map[key.getKey()] = element;
}
inline void clear() {
map.clear();
}
void clear(LogBufferElement *e) {
uint64_t current = e->getRealTime().nsec()
void clear(LogBufferElement *element) {
uint64_t current = element->getRealTime().nsec()
- (EXPIRE_RATELIMIT * NS_PER_SEC);
for(LogBufferElementMap::iterator it = map.begin(); it != map.end();) {
LogBufferElement *l = it->second;
if ((l->getDropped() >= EXPIRE_THRESHOLD)
&& (current > l->getRealTime().nsec())) {
LogBufferElement *mapElement = it->second;
if ((mapElement->getDropped() >= EXPIRE_THRESHOLD)
&& (current > mapElement->getRealTime().nsec())) {
it = map.erase(it);
} else {
++it;
@ -449,9 +473,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
LogTimeEntry::lock();
// Region locked?
LastLogTimes::iterator t = mTimes.begin();
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
LastLogTimes::iterator times = mTimes.begin();
while(times != mTimes.end()) {
LogTimeEntry *entry = (*times);
if (entry->owned_Locked() && entry->isWatching(id)
&& (!oldest ||
(oldest->mStart > entry->mStart) ||
@ -459,7 +483,7 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
(entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
oldest = entry;
}
t++;
times++;
}
LogBufferElementCollection::iterator it;
@ -467,14 +491,14 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (caller_uid != AID_ROOT) {
// Only here if clearAll condition (pruneRows == ULONG_MAX)
for(it = mLogElements.begin(); it != mLogElements.end();) {
LogBufferElement *e = *it;
LogBufferElement *element = *it;
if ((e->getLogId() != id) || (e->getUid() != caller_uid)) {
if ((element->getLogId() != id) || (element->getUid() != caller_uid)) {
++it;
continue;
}
if (oldest && (oldest->mStart <= e->getSequence())) {
if (oldest && (oldest->mStart <= element->getSequence())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
@ -491,20 +515,21 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
return busy;
}
// prune by worst offender by uid
// prune by worst offenders; by blacklist, UID, and by PID of system UID
bool hasBlacklist = (id != LOG_ID_SECURITY) && mPrune.naughty();
while (!clearAll && (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;
pid_t worstPid = 0; // POSIX guarantees PID != 0
if (worstUidEnabledForLogid(id) && mPrune.worstUidEnabled()) {
std::unique_ptr<const UidEntry *[]> sorted = stats.sort(
AID_ROOT, (pid_t)0, 2, id);
{ // begin scope for UID sorted list
std::unique_ptr<const UidEntry *[]> sorted = stats.sort(
AID_ROOT, (pid_t)0, 2, id);
if (sorted.get()) {
if (sorted[0] && sorted[1]) {
if (sorted.get() && sorted[0] && sorted[1]) {
worst_sizes = sorted[0]->getSizes();
// Calculate threshold as 12.5% of available storage
size_t threshold = log_buffer_size(id) / 8;
@ -520,6 +545,18 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
}
}
if ((worst == AID_SYSTEM) && mPrune.worstPidOfSystemEnabled()) {
// begin scope of PID sorted list
std::unique_ptr<const PidEntry *[]> sorted = stats.sort(
worst, (pid_t)0, 2, id, worst);
if (sorted.get() && sorted[0] && sorted[1]) {
worstPid = sorted[0]->getKey();
second_worst_sizes = worst_sizes
- sorted[0]->getSizes()
+ sorted[1]->getSizes();
}
}
}
// skip if we have neither worst nor naughty filters
@ -536,11 +573,23 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
// - check age-out of preserved logs
bool gc = pruneRows <= 1;
if (!gc && (worst != (uid_t) -1)) {
LogBufferIteratorMap::iterator f = mLastWorstUid[id].find(worst);
if ((f != mLastWorstUid[id].end())
&& (f->second != mLogElements.end())) {
leading = false;
it = f->second;
{ // begin scope for uid worst found iterator
LogBufferIteratorMap::iterator found = mLastWorstUid[id].find(worst);
if ((found != mLastWorstUid[id].end())
&& (found->second != mLogElements.end())) {
leading = false;
it = found->second;
}
}
if (worstPid) {
// begin scope for pid worst found iterator
LogBufferPidIteratorMap::iterator found
= mLastWorstPidOfSystem[id].find(worstPid);
if ((found != mLastWorstPidOfSystem[id].end())
&& (found->second != mLogElements.end())) {
leading = false;
it = found->second;
}
}
}
static const timespec too_old = {
@ -551,9 +600,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
--lastt;
LogBufferElementLast last;
while (it != mLogElements.end()) {
LogBufferElement *e = *it;
LogBufferElement *element = *it;
if (oldest && (oldest->mStart <= e->getSequence())) {
if (oldest && (oldest->mStart <= element->getSequence())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
@ -561,12 +610,12 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
break;
}
if (e->getLogId() != id) {
if (element->getLogId() != id) {
++it;
continue;
}
unsigned short dropped = e->getDropped();
unsigned short dropped = element->getDropped();
// remove any leading drops
if (leading && dropped) {
@ -574,13 +623,13 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
continue;
}
if (dropped && last.coalesce(e, dropped)) {
if (dropped && last.coalesce(element, dropped)) {
it = erase(it, true);
continue;
}
if (hasBlacklist && mPrune.naughty(e)) {
last.clear(e);
if (hasBlacklist && mPrune.naughty(element)) {
last.clear(element);
it = erase(it);
if (dropped) {
continue;
@ -591,35 +640,42 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
break;
}
if (e->getUid() == worst) {
if (element->getUid() == worst) {
kick = true;
if (worst_sizes < second_worst_sizes) {
break;
}
worst_sizes -= e->getMsgLen();
worst_sizes -= element->getMsgLen();
}
continue;
}
if ((e->getRealTime() < ((*lastt)->getRealTime() - too_old))
|| (e->getRealTime() > (*lastt)->getRealTime())) {
if ((element->getRealTime() < ((*lastt)->getRealTime() - too_old))
|| (element->getRealTime() > (*lastt)->getRealTime())) {
break;
}
if (dropped) {
last.add(e);
if ((!gc && (e->getUid() == worst))
|| (mLastWorstUid[id].find(e->getUid())
last.add(element);
if (worstPid
&& ((!gc && (element->getPid() == worstPid))
|| (mLastWorstPidOfSystem[id].find(element->getPid())
== mLastWorstPidOfSystem[id].end()))) {
mLastWorstPidOfSystem[id][element->getUid()] = it;
}
if ((!gc && !worstPid && (element->getUid() == worst))
|| (mLastWorstUid[id].find(element->getUid())
== mLastWorstUid[id].end())) {
mLastWorstUid[id][e->getUid()] = it;
mLastWorstUid[id][element->getUid()] = it;
}
++it;
continue;
}
if (e->getUid() != worst) {
if ((element->getUid() != worst)
|| (worstPid && (element->getPid() != worstPid))) {
leading = false;
last.clear(e);
last.clear(element);
++it;
continue;
}
@ -631,19 +687,24 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
kick = true;
unsigned short len = e->getMsgLen();
unsigned short len = element->getMsgLen();
// do not create any leading drops
if (leading) {
it = erase(it);
} else {
stats.drop(e);
e->setDropped(1);
if (last.coalesce(e, 1)) {
stats.drop(element);
element->setDropped(1);
if (last.coalesce(element, 1)) {
it = erase(it, true);
} else {
last.add(e);
if (!gc || (mLastWorstUid[id].find(worst)
last.add(element);
if (worstPid && (!gc
|| (mLastWorstPidOfSystem[id].find(worstPid)
== mLastWorstPidOfSystem[id].end()))) {
mLastWorstPidOfSystem[id][worstPid] = it;
}
if ((!gc && !worstPid) || (mLastWorstUid[id].find(worst)
== mLastWorstUid[id].end())) {
mLastWorstUid[id][worst] = it;
}
@ -666,16 +727,15 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
bool hasWhitelist = (id != LOG_ID_SECURITY) && mPrune.nice() && !clearAll;
it = mLogElements.begin();
while((pruneRows > 0) && (it != mLogElements.end())) {
LogBufferElement *e = *it;
LogBufferElement *element = *it;
if (e->getLogId() != id) {
if (element->getLogId() != id) {
it++;
continue;
}
if (oldest && (oldest->mStart <= e->getSequence())) {
if (oldest && (oldest->mStart <= element->getSequence())) {
busy = true;
if (whitelist) {
break;
}
@ -691,7 +751,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
break;
}
if (hasWhitelist && !e->getDropped() && mPrune.nice(e)) { // WhiteListed
if (hasWhitelist && !element->getDropped() && mPrune.nice(element)) {
// WhiteListed
whitelist = true;
it++;
continue;
@ -705,14 +766,14 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (whitelist && (pruneRows > 0)) {
it = mLogElements.begin();
while((it != mLogElements.end()) && (pruneRows > 0)) {
LogBufferElement *e = *it;
LogBufferElement *element = *it;
if (e->getLogId() != id) {
if (element->getLogId() != id) {
++it;
continue;
}
if (oldest && (oldest->mStart <= e->getSequence())) {
if (oldest && (oldest->mStart <= element->getSequence())) {
busy = true;
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island

5
logd/LogBuffer.h
View file

@ -61,6 +61,11 @@ class LogBuffer {
LogBufferElementCollection::iterator>
LogBufferIteratorMap;
LogBufferIteratorMap mLastWorstUid[LOG_ID_MAX];
// watermark of any worst/chatty pid of system processing
typedef std::unordered_map<pid_t,
LogBufferElementCollection::iterator>
LogBufferPidIteratorMap;
LogBufferPidIteratorMap mLastWorstPidOfSystem[LOG_ID_MAX];
unsigned long mMaxSize[LOG_ID_MAX];

47
logd/LogStatistics.cpp
View file

@ -75,6 +75,9 @@ void LogStatistics::add(LogBufferElement *element) {
}
uidTable[log_id].add(element->getUid(), element);
if (element->getUid() == AID_SYSTEM) {
pidSystemTable[log_id].add(element->getPid(), element);
}
if (!enable) {
return;
@ -107,6 +110,9 @@ void LogStatistics::subtract(LogBufferElement *element) {
}
uidTable[log_id].subtract(element->getUid(), element);
if (element->getUid() == AID_SYSTEM) {
pidSystemTable[log_id].subtract(element->getPid(), element);
}
if (!enable) {
return;
@ -134,6 +140,9 @@ void LogStatistics::drop(LogBufferElement *element) {
++mDroppedElements[log_id];
uidTable[log_id].drop(element->getUid(), element);
if (element->getUid() == AID_SYSTEM) {
pidSystemTable[log_id].drop(element->getPid(), element);
}
if (!enable) {
return;
@ -273,7 +282,43 @@ std::string UidEntry::format(const LogStatistics &stat, log_id_t id) const {
}
}
return formatLine(name, size, pruned);
std::string output = formatLine(name, size, pruned);
if (uid != AID_SYSTEM) {
return output;
}
static const size_t maximum_sorted_entries = 32;
std::unique_ptr<const PidEntry *[]> sorted
= stat.pidSystemTable[id].sort(uid, (pid_t)0, maximum_sorted_entries);
if (!sorted.get()) {
return output;
}
std::string byPid;
size_t index;
bool hasDropped = false;
for (index = 0; index < maximum_sorted_entries; ++index) {
const PidEntry *entry = sorted[index];
if (!entry) {
break;
}
if (entry->getSizes() <= (getSizes() / 100)) {
break;
}
if (entry->getDropped()) {
hasDropped = true;
}
byPid += entry->format(stat, id);
}
if (index > 1) { // print this only if interesting
std::string ditto("\" ");
output += formatLine(std::string(" PID/UID COMMAND LINE"),
ditto, hasDropped ? ditto : std::string(""));
output += byPid;
}
return output;
}
std::string PidEntry::formatHeader(const std::string &name, log_id_t /* id */) const {

8
logd/LogStatistics.h
View file

@ -416,6 +416,10 @@ class LogStatistics {
typedef LogHashtable<uid_t, UidEntry> uidTable_t;
uidTable_t uidTable[LOG_ID_MAX];
// pid of system to size list
typedef LogHashtable<pid_t, PidEntry> pidSystemTable_t;
pidSystemTable_t pidSystemTable[LOG_ID_MAX];
// pid to uid list
typedef LogHashtable<pid_t, PidEntry> pidTable_t;
pidTable_t pidTable;
@ -451,6 +455,10 @@ public:
size_t len, log_id id) {
return uidTable[id].sort(uid, pid, len);
}
std::unique_ptr<const PidEntry *[]> sort(uid_t uid, pid_t pid,
size_t len, log_id id, uid_t) {
return pidSystemTable[id].sort(uid, pid, len);
}
// fast track current value by id only
size_t sizes(log_id_t id) const { return mSizes[id]; }

20
logd/LogWhiteBlackList.cpp
View file

@ -66,6 +66,7 @@ PruneList::~PruneList() {
int PruneList::init(const char *str) {
mWorstUidEnabled = true;
mWorstPidOfSystemEnabled = true;
PruneCollection::iterator it;
for (it = mNice.begin(); it != mNice.end();) {
it = mNice.erase(it);
@ -103,13 +104,14 @@ int PruneList::init(const char *str) {
// default here means take internal default.
if (filter == _default) {
// See README.property for description of filter format
filter = "~!";
filter = "~! ~1000/!";
}
if (filter == _disable) {
filter = "";
}
mWorstUidEnabled = false;
mWorstPidOfSystemEnabled = false;
for(str = filter.c_str(); *str; ++str) {
if (isspace(*str)) {
@ -131,6 +133,19 @@ int PruneList::init(const char *str) {
}
continue;
}
// special case, translated to worst PID of System at priority
static const char worstPid[] = "1000/!";
if (!strncmp(str, worstPid, sizeof(worstPid) - 1)) {
mWorstPidOfSystemEnabled = true;
str += sizeof(worstPid) - 1;
if (!*str) {
break;
}
if (!isspace(*str)) {
return 1;
}
continue;
}
if (!*str) {
return 1;
}
@ -209,6 +224,9 @@ std::string PruneList::format() {
if (mWorstUidEnabled) {
string = "~!";
fmt = nice_format;
if (mWorstPidOfSystemEnabled) {
string += " ~1000/!";
}
}
PruneCollection::iterator it;

2
logd/LogWhiteBlackList.h
View file

@ -53,6 +53,7 @@ class PruneList {
PruneCollection mNaughty;
PruneCollection mNice;
bool mWorstUidEnabled;
bool mWorstPidOfSystemEnabled;
public:
PruneList();
@ -65,6 +66,7 @@ public:
bool nice(LogBufferElement *element);
bool nice(void) { return !mNice.empty(); }
bool worstUidEnabled() const { return mWorstUidEnabled; }
bool worstPidOfSystemEnabled() const { return mWorstPidOfSystemEnabled; }
std::string format();
};

10
logd/README.property
View file

@ -23,9 +23,11 @@ ro.config.low_ram bool false if true, logd.statistics, logd.kernel
of 256K.
persist.logd.filter string Pruning filter to optimize content.
At runtime use: logcat -P "<string>"
ro.logd.filter string "~!" default for persist.logd.filter.
ro.logd.filter string "~! ~1000/!" default for persist.logd.filter.
This default means to prune the
oldest entries of chattiest UID.
oldest entries of chattiest UID, and
the chattiest PID of system
(1000, or AID_SYSTEM).
persist.logd.timestamp string ro The recording timestamp source.
"m[onotonic]" is the only supported
key character, otherwise realtime.
@ -52,4 +54,6 @@ NB:
such as main, system, ... override global default.
- Pruning filter is of form of a space-separated list of [~][UID][/PID]
references, where '~' prefix means to blacklist otherwise whitelist. For
blacklisting, UID may be a '!' to instead reference the chattiest client.
blacklisting, UID or PID may be a '!' to instead reference the chattiest
client, with the restriction that the PID must be in the UID group 1000
(system or AID_SYSTEM).