openkylin
/
platform_system_core
mirror of https://gitee.com/openkylin/platform_system_core.git
9
0
Fork 0
Code Issues Projects Releases Wiki Activity

Merge changes Ib441cecf,Ieb1bbe3d,I3e63e430,I531b4317,I8dd60545, ... 

* changes:
  logcat: Add --wrap timeout
  logcat: Add low hanging fruit long arguments
  logcat: Add long arguments to logcat, support for pid filter
  liblog: Support for ANDROID_LOG_WRAP mode flag on reader
  logd: test wakeup on wrap timeout
  logd: wakeup on wrap or timeout
This commit is contained in:
Mark Salyzyn 2015-12-07 22:27:13 +00:00 committed by Gerrit Code Review
parent 3ea02e8eca 41ba25f864
commit d1379a8aed
11 changed files with 291 additions and 59 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

2
include/log/logger.h
View File

@ -163,6 +163,8 @@ int android_logger_set_prune_list(struct logger_list *logger_list,
#define ANDROID_LOG_RDWR O_RDWR
#define ANDROID_LOG_ACCMODE O_ACCMODE
#define ANDROID_LOG_NONBLOCK O_NONBLOCK
#define ANDROID_LOG_WRAP 0x40000000 /* Block until buffer about to wrap */
#define ANDROID_LOG_WRAP_DEFAULT_TIMEOUT 7200 /* 2 hour default */
#define ANDROID_LOG_PSTORE 0x80000000
struct logger_list *android_logger_list_alloc(int mode,

4
liblog/README
View File

@ -116,6 +116,10 @@ DESCRIPTION
code, otherwise the android_logger_list_read call will block for new
entries.
The ANDROID_LOG_WRAP mode flag to the android_logger_list_alloc_time
signals logd to quiesce the reader until the buffer is about to prune
at the start time then proceed to dumping content.
The ANDROID_LOG_PSTORE mode flag to the android_logger_open is used to
switch from the active logs to the persistent logs from before the last
reboot.

8
liblog/log_read.c
View File

@ -797,6 +797,14 @@ int android_logger_list_read(struct logger_list *logger_list,
}
if (logger_list->start.tv_sec || logger_list->start.tv_nsec) {
if (logger_list->mode & ANDROID_LOG_WRAP) {
// ToDo: alternate API to allow timeout to be adjusted.
ret = snprintf(cp, remaining, " timeout=%u",
ANDROID_LOG_WRAP_DEFAULT_TIMEOUT);
ret = min(ret, remaining);
remaining -= ret;
cp += ret;
}
ret = snprintf(cp, remaining, " start=%" PRIu32 ".%09" PRIu32,
logger_list->start.tv_sec,
logger_list->start.tv_nsec);

119
logcat/logcat.cpp
View File

@ -6,6 +6,7 @@
#include <dirent.h>
#include <errno.h>
#include <fcntl.h>
#include <getopt.h>
#include <math.h>
#include <sched.h>
#include <signal.h>
@ -256,13 +257,19 @@ static void show_help(const char *cmd)
" -s Set default filter to silent.\n"
" Like specifying filterspec '*:S'\n"
" -f <filename> Log to file. Default is stdout\n"
" --file=<filename>\n"
" -r <kbytes> Rotate log every kbytes. Requires -f\n"
" --rotate_kbytes=<kbytes>\n"
" -n <count> Sets max number of rotated logs to <count>, default 4\n"
" -v <format> Sets the log print format, where <format> is:\n\n"
" --rotate_count=<count>\n"
" -v <format> Sets the log print format, where <format> is:\n"
" --format=<format>\n"
" brief color epoch long monotonic printable process raw\n"
" tag thread threadtime time usec UTC year zone\n\n"
" -D print dividers between each log buffer\n"
" --dividers\n"
" -c clear (flush) the entire log and exit\n"
" --clear\n"
" -d dump the log and then exit (don't block)\n"
" -t <count> print only the most recent <count> lines (implies -d)\n"
" -t '<time>' print most recent lines since specified time (implies -d)\n"
@ -271,22 +278,32 @@ static void show_help(const char *cmd)
" count is pure numerical, time is 'MM-DD hh:mm:ss.mmm...'\n"
" 'YYYY-MM-DD hh:mm:ss.mmm...' or 'sssss.mmm...' format\n"
" -g get the size of the log's ring buffer and exit\n"
" --buffer_size\n"
" -G <size> set size of log ring buffer, may suffix with K or M.\n"
" --buffer_size=<size>\n"
" -L dump logs from prior to last reboot\n"
" --last\n"
" -b <buffer> Request alternate ring buffer, 'main', 'system', 'radio',\n"
" 'events', 'crash' or 'all'. Multiple -b parameters are\n"
" --buffer=<buffer> 'events', 'crash' or 'all'. Multiple -b parameters are\n"
" allowed and results are interleaved. The default is\n"
" -b main -b system -b crash.\n"
" -B output the log in binary.\n"
" --binary\n"
" -S output statistics.\n"
" -G <size> set size of log ring buffer, may suffix with K or M.\n"
" --statistics\n"
" -p print prune white and ~black list. Service is specified as\n"
" UID, UID/PID or /PID. Weighed for quicker pruning if prefix\n"
" --prune UID, UID/PID or /PID. Weighed for quicker pruning if prefix\n"
" with ~, otherwise weighed for longevity if unadorned. All\n"
" other pruning activity is oldest first. Special case ~!\n"
" represents an automatic quicker pruning for the noisiest\n"
" UID as determined by the current statistics.\n"
" -P '<list> ...' set prune white and ~black list, using same format as\n"
" printed above. Must be quoted.\n");
" --prune='<list> ...' printed above. Must be quoted.\n"
" --pid=<pid> Only prints logs from the given pid.\n"
// Check ANDROID_LOG_WRAP_DEFAULT_TIMEOUT value
" --wrap Sleep for 2 hours or when buffer about to wrap whichever\n"
" comes first. Improves efficiency of polling by providing\n"
" an about-to-wrap wakeup.\n");
fprintf(stderr,"\nfilterspecs are a series of \n"
" <tag>[:priority]\n\n"
@ -348,15 +365,19 @@ static const char *multiplier_of_size(unsigned long value)
static bool getSizeTArg(char *ptr, size_t *val, size_t min = 0,
size_t max = SIZE_MAX)
{
char *endp;
errno = 0;
size_t ret = (size_t) strtoll(ptr, &endp, 0);
if (endp[0] != '\0' || errno != 0 ) {
if (!ptr) {
return false;
}
if (ret > max || ret < min) {
char *endp;
errno = 0;
size_t ret = (size_t)strtoll(ptr, &endp, 0);
if (endp[0] || errno) {
return false;
}
if ((ret > max) || (ret < min)) {
return false;
}
@ -497,6 +518,7 @@ int main(int argc, char **argv)
struct logger_list *logger_list;
size_t tail_lines = 0;
log_time tail_time(log_time::EPOCH);
size_t pid = 0;
signal(SIGPIPE, exit);
@ -510,13 +532,66 @@ int main(int argc, char **argv)
for (;;) {
int ret;
ret = getopt(argc, argv, ":cdDLt:T:gG:sQf:r:n:v:b:BSpP:");
int option_index = 0;
static const char pid_str[] = "pid";
static const char wrap_str[] = "wrap";
static const struct option long_options[] = {
{ "binary", no_argument, NULL, 'B' },
{ "buffer", required_argument, NULL, 'b' },
{ "buffer_size", optional_argument, NULL, 'g' },
{ "clear", no_argument, NULL, 'c' },
{ "dividers", no_argument, NULL, 'D' },
{ "file", required_argument, NULL, 'f' },
{ "format", required_argument, NULL, 'v' },
{ "last", no_argument, NULL, 'L' },
{ pid_str, required_argument, NULL, 0 },
{ "prune", optional_argument, NULL, 'p' },
{ "rotate_count", required_argument, NULL, 'n' },
{ "rotate_kbytes", required_argument, NULL, 'r' },
{ "statistics", no_argument, NULL, 'S' },
// support, but ignore and do not document, the optional argument
{ wrap_str, optional_argument, NULL, 0 },
{ NULL, 0, NULL, 0 }
};
ret = getopt_long(argc, argv, ":cdDLt:T:gG:sQf:r:n:v:b:BSpP:",
long_options, &option_index);
if (ret < 0) {
break;
}
switch(ret) {
switch (ret) {
case 0:
// One of the long options
if (long_options[option_index].name == pid_str) {
// ToDo: determine runtime PID_MAX?
if (!getSizeTArg(optarg, &pid, 1)) {
logcat_panic(true, "%s %s out of range\n",
long_options[option_index].name, optarg);
}
break;
}
if (long_options[option_index].name == wrap_str) {
mode |= ANDROID_LOG_WRAP |
ANDROID_LOG_RDONLY |
ANDROID_LOG_NONBLOCK;
// ToDo: implement API that supports setting a wrap timeout
size_t dummy = ANDROID_LOG_WRAP_DEFAULT_TIMEOUT;
if (optarg && !getSizeTArg(optarg, &dummy, 1)) {
logcat_panic(true, "%s %s out of range\n",
long_options[option_index].name, optarg);
}
if (dummy != ANDROID_LOG_WRAP_DEFAULT_TIMEOUT) {
fprintf(stderr,
"WARNING: %s %u seconds, ignoring %zu\n",
long_options[option_index].name,
ANDROID_LOG_WRAP_DEFAULT_TIMEOUT, dummy);
}
break;
}
break;
case 's':
// default to all silent
android_log_addFilterRule(g_logformat, "*:s");
@ -568,8 +643,11 @@ int main(int argc, char **argv)
break;
case 'g':
getLogSize = 1;
break;
if (!optarg) {
getLogSize = 1;
break;
}
// FALLTHRU
case 'G': {
char *cp;
@ -607,8 +685,11 @@ int main(int argc, char **argv)
break;
case 'p':
getPruneList = 1;
break;
if (!optarg) {
getPruneList = 1;
break;
}
// FALLTHRU
case 'P':
setPruneList = optarg;
@ -838,9 +919,9 @@ int main(int argc, char **argv)
dev = devices;
if (tail_time != log_time::EPOCH) {
logger_list = android_logger_list_alloc_time(mode, tail_time, 0);
logger_list = android_logger_list_alloc_time(mode, tail_time, pid);
} else {
logger_list = android_logger_list_alloc(mode, tail_lines, 0);
logger_list = android_logger_list_alloc(mode, tail_lines, pid);
}
const char *openDeviceFail = NULL;
const char *clearFail = NULL;

13
logd/FlushCommand.cpp
View File

@ -27,13 +27,15 @@ FlushCommand::FlushCommand(LogReader &reader,
unsigned long tail,
unsigned int logMask,
pid_t pid,
uint64_t start) :
uint64_t start,
uint64_t timeout) :
mReader(reader),
mNonBlock(nonBlock),
mTail(tail),
mLogMask(logMask),
mPid(pid),
mStart(start) {
mStart(start),
mTimeout(timeout) {
}
// runSocketCommand is called once for every open client on the
@ -54,6 +56,10 @@ void FlushCommand::runSocketCommand(SocketClient *client) {
while(it != times.end()) {
entry = (*it);
if (entry->mClient == client) {
if (entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec) {
LogTimeEntry::unlock();
return;
}
entry->triggerReader_Locked();
if (entry->runningReader_Locked()) {
LogTimeEntry::unlock();
@ -71,7 +77,8 @@ void FlushCommand::runSocketCommand(SocketClient *client) {
LogTimeEntry::unlock();
return;
}
entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask, mPid, mStart);
entry = new LogTimeEntry(mReader, client, mNonBlock, mTail, mLogMask,
mPid, mStart, mTimeout);
times.push_front(entry);
}

4
logd/FlushCommand.h
View File

@ -32,6 +32,7 @@ class FlushCommand : public SocketClientCommand {
unsigned int mLogMask;
pid_t mPid;
uint64_t mStart;
uint64_t mTimeout;
public:
FlushCommand(LogReader &mReader,
@ -39,7 +40,8 @@ public:
unsigned long tail = -1,
unsigned int logMask = -1,
pid_t pid = 0,
uint64_t start = 1);
uint64_t start = 1,
uint64_t timeout = 0);
virtual void runSocketCommand(SocketClient *client);
static bool hasReadLogs(SocketClient *client);

94
logd/LogBuffer.cpp
View File

@ -129,41 +129,57 @@ void LogBuffer::init() {
}
bool lastMonotonic = monotonic;
monotonic = android_log_clockid() == CLOCK_MONOTONIC;
if (lastMonotonic == monotonic) {
return;
if (lastMonotonic != monotonic) {
//
// Fixup all timestamps, may not be 100% accurate, but better than
// throwing what we have away when we get 'surprised' by a change.
// In-place element fixup so no need to check reader-lock. Entries
// should already be in timestamp order, but we could end up with a
// few out-of-order entries if new monotonics come in before we
// are notified of the reinit change in status. A Typical example would
// be:
// --------- beginning of system
// 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
// --------- beginning of kernel
// 0.000000 0 0 I : Initializing cgroup subsys
// as the act of mounting /data would trigger persist.logd.timestamp to
// be corrected. 1/30 corner case YMMV.
//
pthread_mutex_lock(&mLogElementsLock);
LogBufferElementCollection::iterator it = mLogElements.begin();
while((it != mLogElements.end())) {
LogBufferElement *e = *it;
if (monotonic) {
if (!android::isMonotonic(e->mRealTime)) {
LogKlog::convertRealToMonotonic(e->mRealTime);
}
} else {
if (android::isMonotonic(e->mRealTime)) {
LogKlog::convertMonotonicToReal(e->mRealTime);
}
}
++it;
}
pthread_mutex_unlock(&mLogElementsLock);
}
// We may have been triggered by a SIGHUP. Release any sleeping reader
// threads to dump their current content.
//
// Fixup all timestamps, may not be 100% accurate, but better than
// throwing what we have away when we get 'surprised' by a change.
// In-place element fixup so no need to check reader-lock. Entries
// should already be in timestamp order, but we could end up with a
// few out-of-order entries if new monotonics come in before we
// are notified of the reinit change in status. A Typical example would
// be:
// --------- beginning of system
// 10.494082 184 201 D Cryptfs : Just triggered post_fs_data
// --------- beginning of kernel
// 0.000000 0 0 I : Initializing cgroup subsys cpuacct
// as the act of mounting /data would trigger persist.logd.timestamp to
// be corrected. 1/30 corner case YMMV.
//
pthread_mutex_lock(&mLogElementsLock);
LogBufferElementCollection::iterator it = mLogElements.begin();
while((it != mLogElements.end())) {
LogBufferElement *e = *it;
if (monotonic) {
if (!android::isMonotonic(e->mRealTime)) {
LogKlog::convertRealToMonotonic(e->mRealTime);
}
} else {
if (android::isMonotonic(e->mRealTime)) {
LogKlog::convertMonotonicToReal(e->mRealTime);
}
// NB: this is _not_ performed in the context of a SIGHUP, it is
// performed during startup, and in context of reinit administrative thread
LogTimeEntry::lock();
LastLogTimes::iterator times = mTimes.begin();
while(times != mTimes.end()) {
LogTimeEntry *entry = (*times);
if (entry->owned_Locked()) {
entry->triggerReader_Locked();
}
++it;
times++;
}
pthread_mutex_unlock(&mLogElementsLock);
LogTimeEntry::unlock();
}
LogBuffer::LogBuffer(LastLogTimes *times):
@ -429,7 +445,10 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
while(t != mTimes.end()) {
LogTimeEntry *entry = (*t);
if (entry->owned_Locked() && entry->isWatching(id)
&& (!oldest || (oldest->mStart > entry->mStart))) {
&& (!oldest ||
(oldest->mStart > entry->mStart) ||
((oldest->mStart == entry->mStart) &&
(entry->mTimeout.tv_sec || entry->mTimeout.tv_nsec)))) {
oldest = entry;
}
t++;
@ -448,8 +467,12 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
}
if (oldest && (oldest->mStart <= e->getSequence())) {
oldest->triggerSkip_Locked(id, pruneRows);
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}
break;
}
@ -523,6 +546,9 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (oldest && (oldest->mStart <= e->getSequence())) {
busy = true;
if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
}
break;
}
@ -648,6 +674,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}
@ -680,6 +708,8 @@ bool LogBuffer::prune(log_id_t id, unsigned long pruneRows, uid_t caller_uid) {
if (stats.sizes(id) > (2 * log_buffer_size(id))) {
// kick a misbehaving log reader client off the island
oldest->release_Locked();
} else if (oldest->mTimeout.tv_sec || oldest->mTimeout.tv_nsec) {
oldest->triggerReader_Locked();
} else {
oldest->triggerSkip_Locked(id, pruneRows);
}

10
logd/LogReader.cpp
View File

@ -67,6 +67,14 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
start.strptime(cp + sizeof(_start) - 1, "%s.%q");
}
uint64_t timeout = 0;
static const char _timeout[] = " timeout=";
cp = strstr(buffer, _timeout);
if (cp) {
timeout = atol(cp + sizeof(_timeout) - 1) * NS_PER_SEC +
log_time(CLOCK_REALTIME).nsec();
}
unsigned int logMask = -1;
static const char _logIds[] = " lids=";
cp = strstr(buffer, _logIds);
@ -166,7 +174,7 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
}
}
FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence);
FlushCommand command(*this, nonBlock, tail, logMask, pid, sequence, timeout);
command.runSocketCommand(cli);
return true;
}

22
logd/LogTimes.cpp
View File

@ -14,6 +14,7 @@
* limitations under the License.
*/
#include <errno.h>
#include <sys/prctl.h>
#include "FlushCommand.h"
@ -26,7 +27,7 @@ pthread_mutex_t LogTimeEntry::timesLock = PTHREAD_MUTEX_INITIALIZER;
LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
bool nonBlock, unsigned long tail,
unsigned int logMask, pid_t pid,
uint64_t start) :
uint64_t start, uint64_t timeout) :
mRefCount(1),
mRelease(false),
mError(false),
@ -42,6 +43,8 @@ LogTimeEntry::LogTimeEntry(LogReader &reader, SocketClient *client,
mStart(start),
mNonBlock(nonBlock),
mEnd(LogBufferElement::getCurrentSequence()) {
mTimeout.tv_sec = timeout / NS_PER_SEC;
mTimeout.tv_nsec = timeout % NS_PER_SEC;
pthread_cond_init(&threadTriggeredCondition, NULL);
cleanSkip_Locked();
}
@ -131,6 +134,19 @@ void *LogTimeEntry::threadStart(void *obj) {
uint64_t start = me->mStart;
while (me->threadRunning && !me->isError_Locked()) {
if (me->mTimeout.tv_sec || me->mTimeout.tv_nsec) {
if (pthread_cond_timedwait(&me->threadTriggeredCondition,
&timesLock,
&me->mTimeout) == ETIMEDOUT) {
me->mTimeout.tv_sec = 0;
me->mTimeout.tv_nsec = 0;
}
if (!me->threadRunning || me->isError_Locked()) {
break;
}
}
unlock();
if (me->mTail) {
@ -154,7 +170,9 @@ void *LogTimeEntry::threadStart(void *obj) {
me->cleanSkip_Locked();
pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);
if (!me->mTimeout.tv_sec && !me->mTimeout.tv_nsec) {
pthread_cond_wait(&me->threadTriggeredCondition, &timesLock);
}
}
unlock();

3
logd/LogTimes.h
View File

@ -50,10 +50,11 @@ class LogTimeEntry {
public:
LogTimeEntry(LogReader &reader, SocketClient *client, bool nonBlock,
unsigned long tail, unsigned int logMask, pid_t pid,
uint64_t start);
uint64_t start, uint64_t timeout);
SocketClient *mClient;
uint64_t mStart;
struct timespec mTimeout;
const bool mNonBlock;
const uint64_t mEnd; // only relevant if mNonBlock

71
logd/tests/logd_test.cpp
View File

@ -243,6 +243,12 @@ static void dump_log_msg(const char *prefix,
case 3:
fprintf(stderr, "lid=system ");
break;
case 4:
fprintf(stderr, "lid=crash ");
break;
case 5:
fprintf(stderr, "lid=kernel ");
break;
default:
if (lid >= 0) {
fprintf(stderr, "lid=%d ", lid);
@ -519,3 +525,68 @@ TEST(logd, benchmark) {
// 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
ASSERT_GT(totalSize, nowSpamSize * 2);
}
TEST(logd, timeout) {
log_msg msg_wrap, msg_timeout;
bool content_wrap = false, content_timeout = false, written = false;
unsigned int alarm_wrap = 0, alarm_timeout = 0;
// A few tries to get it right just in case wrap kicks in due to
// content providers being active during the test.
int i = 3;
while (--i) {
int fd = socket_local_client("logdr",
ANDROID_SOCKET_NAMESPACE_RESERVED,
SOCK_SEQPACKET);
ASSERT_LT(0, fd);
struct sigaction ignore, old_sigaction;
memset(&ignore, 0, sizeof(ignore));
ignore.sa_handler = caught_signal;
sigemptyset(&ignore.sa_mask);
sigaction(SIGALRM, &ignore, &old_sigaction);
unsigned int old_alarm = alarm(3);
static const char ask[] = "dumpAndClose lids=0,1,2,3,4,5 timeout=6";
written = write(fd, ask, sizeof(ask)) == sizeof(ask);
if (!written) {
alarm(old_alarm);
sigaction(SIGALRM, &old_sigaction, NULL);
close(fd);
continue;
}
content_wrap = recv(fd, msg_wrap.buf, sizeof(msg_wrap), 0) > 0;
alarm_wrap = alarm(5);
content_timeout = recv(fd, msg_timeout.buf, sizeof(msg_timeout), 0) > 0;
alarm_timeout = alarm((old_alarm <= 0)
? old_alarm
: (old_alarm > (1 + 3 - alarm_wrap))
? old_alarm - 3 + alarm_wrap
: 2);
sigaction(SIGALRM, &old_sigaction, NULL);
close(fd);
if (!content_wrap && !alarm_wrap && content_timeout && !alarm_timeout) {
break;
}
}
if (content_wrap) {
dump_log_msg("wrap", &msg_wrap, 3, -1);
}
if (content_timeout) {
dump_log_msg("timeout", &msg_timeout, 3, -1);
}
EXPECT_TRUE(written);
EXPECT_FALSE(content_wrap);
EXPECT_EQ(0U, alarm_wrap);
EXPECT_TRUE(content_timeout);
EXPECT_NE(0U, alarm_timeout);
}