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

Merge "liblog: logd: support logd.timestamp = monotonic"

Browse source 
am: 8897a3fffd

* commit '8897a3fffd28c779dcfd8e5988ae90f5da7b5a88':
  liblog: logd: support logd.timestamp = monotonic
This commit is contained in:
Mark Salyzyn 2015-11-04 00:43:13 +00:00 committed by android-build-merger
commit 55316200b8
14 changed files with 200 additions and 87 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
liblog/logd_write.c
View file

@ -191,7 +191,11 @@ static int __write_to_log_daemon(log_id_t log_id, struct iovec *vec, size_t nr)
* };
*/
clock_gettime(CLOCK_REALTIME, &ts);
if (android_log_timestamp() == 'm') {
clock_gettime(CLOCK_MONOTONIC, &ts);
} else {
clock_gettime(CLOCK_REALTIME, &ts);
}
pmsg_header.magic = LOGGER_MAGIC;
pmsg_header.len = sizeof(pmsg_header) + sizeof(header);

13
liblog/logprint.c
View file

@ -203,7 +203,7 @@ AndroidLogFormat *android_log_format_new()
p_ret->year_output = false;
p_ret->zone_output = false;
p_ret->epoch_output = false;
p_ret->monotonic_output = false;
p_ret->monotonic_output = android_log_timestamp() == 'm';
return p_ret;
}
@ -1261,10 +1261,13 @@ char *android_log_formatLogLine (
now = entry->tv_sec;
nsec = entry->tv_nsec;
if (p_format->monotonic_output) {
struct timespec time;
convertMonotonic(&time, entry);
now = time.tv_sec;
nsec = time.tv_nsec;
// prevent convertMonotonic from being called if logd is monotonic
if (android_log_timestamp() != 'm') {
struct timespec time;
convertMonotonic(&time, entry);
now = time.tv_sec;
nsec = time.tv_nsec;
}
}
if (now < 0) {
nsec = NS_PER_SEC - nsec;

10
logcat/logcat.cpp
View file

@ -399,6 +399,10 @@ static log_time lastLogTime(char *outputFileName) {
}
log_time now(CLOCK_REALTIME);
bool monotonic = android_log_timestamp() == 'm';
if (monotonic) {
now = log_time(CLOCK_MONOTONIC);
}
std::string directory;
char *file = strrchr(outputFileName, '/');
@ -417,7 +421,11 @@ static log_time lastLogTime(char *outputFileName) {
struct dirent *dp;
while ((dp = readdir(dir.get())) != NULL) {
if ((dp->d_type != DT_REG)
|| strncmp(dp->d_name, file, len)
// If we are using realtime, check all files that match the
// basename for latest time. If we are using monotonic time
// then only check the main file because time cycles on
// every reboot.
|| strncmp(dp->d_name, file, len + monotonic)
|| (dp->d_name[len]
&& ((dp->d_name[len] != '.')
|| !isdigit(dp->d_name[len+1])))) {

140
logcat/tests/logcat_test.cpp
View file

@ -75,6 +75,12 @@ TEST(logcat, buckets) {
}
TEST(logcat, year) {
if (android_log_timestamp() == 'm') {
fprintf(stderr, "Skipping test, logd is monotonic time\n");
return;
}
FILE *fp;
char needle[32];
@ -108,7 +114,44 @@ TEST(logcat, year) {
ASSERT_EQ(3, count);
}
// Return a pointer to each null terminated -v long time field.
char *fgetLongTime(char *buffer, size_t buflen, FILE *fp) {
while (fgets(buffer, buflen, fp)) {
char *cp = buffer;
if (*cp != '[') {
continue;
}
while (*++cp == ' ') {
;
}
char *ep = cp;
while (isdigit(*ep)) {
++ep;
}
if ((*ep != '-') && (*ep != '.')) {
continue;
}
// Find PID field
while (((ep = strchr(ep, ':'))) && (*++ep != ' ')) {
;
}
if (!ep) {
continue;
}
ep -= 7;
*ep = '\0';
return cp;
}
return NULL;
}
TEST(logcat, tz) {
if (android_log_timestamp() == 'm') {
fprintf(stderr, "Skipping test, logd is monotonic time\n");
return;
}
FILE *fp;
ASSERT_TRUE(NULL != (fp = popen(
@ -119,11 +162,8 @@ TEST(logcat, tz) {
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[2]) && isdigit(buffer[3])
&& (buffer[4] == '-')
&& (strstr(buffer, " -0700 ") || strstr(buffer, " -0800 "))) {
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
++count;
}
}
@ -144,11 +184,8 @@ TEST(logcat, ntz) {
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[2]) && isdigit(buffer[3])
&& (buffer[4] == '-')
&& (strstr(buffer, " -0700 ") || strstr(buffer, " -0800 "))) {
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
if (strstr(buffer, " -0700") || strstr(buffer, " -0800")) {
++count;
}
}
@ -169,12 +206,8 @@ TEST(logcat, tail_3) {
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[2]) && isdigit(buffer[3])
&& (buffer[4] == '-')) {
++count;
}
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
++count;
}
pclose(fp);
@ -193,12 +226,8 @@ TEST(logcat, tail_10) {
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[2]) && isdigit(buffer[3])
&& (buffer[4] == '-')) {
++count;
}
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
++count;
}
pclose(fp);
@ -217,12 +246,8 @@ TEST(logcat, tail_100) {
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[2]) && isdigit(buffer[3])
&& (buffer[4] == '-')) {
++count;
}
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
++count;
}
pclose(fp);
@ -241,12 +266,8 @@ TEST(logcat, tail_1000) {
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[2]) && isdigit(buffer[3])
&& (buffer[4] == '-')) {
++count;
}
while (fgetLongTime(buffer, sizeof(buffer), fp)) {
++count;
}
pclose(fp);
@ -263,21 +284,15 @@ TEST(logcat, tail_time) {
char *last_timestamp = NULL;
char *first_timestamp = NULL;
int count = 0;
const unsigned int time_length = 18;
const unsigned int time_offset = 2;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1])
&& (buffer[time_offset + 2] == '-')) {
++count;
buffer[time_length + time_offset] = '\0';
if (!first_timestamp) {
first_timestamp = strdup(buffer + time_offset);
}
free(last_timestamp);
last_timestamp = strdup(buffer + time_offset);
char *cp;
while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
++count;
if (!first_timestamp) {
first_timestamp = strdup(cp);
}
free(last_timestamp);
last_timestamp = strdup(cp);
}
pclose(fp);
@ -292,28 +307,24 @@ TEST(logcat, tail_time) {
int second_count = 0;
int last_timestamp_count = -1;
while (fgets(buffer, sizeof(buffer), fp)) {
if ((buffer[0] == '[') && (buffer[1] == ' ')
&& isdigit(buffer[time_offset]) && isdigit(buffer[time_offset + 1])
&& (buffer[time_offset + 2] == '-')) {
++second_count;
buffer[time_length + time_offset] = '\0';
if (first_timestamp) {
// we can get a transitory *extremely* rare failure if hidden
// underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000
EXPECT_STREQ(buffer + time_offset, first_timestamp);
free(first_timestamp);
first_timestamp = NULL;
}
if (!strcmp(buffer + time_offset, last_timestamp)) {
last_timestamp_count = second_count;
}
while ((cp = fgetLongTime(buffer, sizeof(buffer), fp))) {
++second_count;
if (first_timestamp) {
// we can get a transitory *extremely* rare failure if hidden
// underneath the time is *exactly* XX-XX XX:XX:XX.XXX000000
EXPECT_STREQ(cp, first_timestamp);
free(first_timestamp);
first_timestamp = NULL;
}
if (!strcmp(cp, last_timestamp)) {
last_timestamp_count = second_count;
}
}
pclose(fp);
free(last_timestamp);
last_timestamp = NULL;
free(first_timestamp);
EXPECT_TRUE(first_timestamp == NULL);
EXPECT_LE(count, second_count);
@ -601,6 +612,9 @@ TEST(logcat, logrotate) {
}
}
pclose(fp);
if ((count != 7) && (count != 8)) {
fprintf(stderr, "count=%d\n", count);
}
EXPECT_TRUE(count == 7 || count == 8);
}
}

20
logd/LogAudit.cpp
View file

@ -123,17 +123,19 @@ int LogAudit::logPrint(const char *fmt, ...) {
&& (*cp == ':')) {
memcpy(timeptr + sizeof(audit_str) - 1, "0.0", 3);
memmove(timeptr + sizeof(audit_str) - 1 + 3, cp, strlen(cp) + 1);
//
// We are either in 1970ish (MONOTONIC) or 2015+ish (REALTIME) so to
// differentiate without prejudice, we use 1980 to delineate, earlier
// is monotonic, later is real.
//
# define EPOCH_PLUS_10_YEARS (10 * 1461 / 4 * 24 * 60 * 60)
if (now.tv_sec < EPOCH_PLUS_10_YEARS) {
LogKlog::convertMonotonicToReal(now);
if (!isMonotonic()) {
if (android::isMonotonic(now)) {
LogKlog::convertMonotonicToReal(now);
}
} else {
if (!android::isMonotonic(now)) {
LogKlog::convertRealToMonotonic(now);
}
}
} else if (isMonotonic()) {
now = log_time(CLOCK_MONOTONIC);
} else {
now.strptime("", ""); // side effect of setting CLOCK_REALTIME
now = log_time(CLOCK_REALTIME);
}
static const char pid_str[] = " pid=";

1
logd/LogAudit.h
View file

@ -29,6 +29,7 @@ class LogAudit : public SocketListener {
public:
LogAudit(LogBuffer *buf, LogReader *reader, int fdDmesg);
int log(char *buf, size_t len);
bool isMonotonic() { return logbuf->isMonotonic(); }
protected:
virtual bool onDataAvailable(SocketClient *cli);

42
logd/LogBuffer.cpp
View file

@ -28,6 +28,7 @@
#include <log/logger.h>
#include "LogBuffer.h"
#include "LogKlog.h"
#include "LogReader.h"
// Default
@ -126,9 +127,48 @@ void LogBuffer::init() {
setSize(i, LOG_BUFFER_MIN_SIZE);
}
}
bool lastMonotonic = monotonic;
monotonic = android_log_timestamp() == 'm';
if (lastMonotonic == monotonic) {
return;
}
//
// 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);
}
}
++it;
}
pthread_mutex_unlock(&mLogElementsLock);
}
LogBuffer::LogBuffer(LastLogTimes *times) : mTimes(*times) {
LogBuffer::LogBuffer(LastLogTimes *times):
monotonic(android_log_timestamp() == 'm'),
mTimes(*times) {
pthread_mutex_init(&mLogElementsLock, NULL);
init();

18
logd/LogBuffer.h
View file

@ -32,6 +32,21 @@
#include "LogStatistics.h"
#include "LogWhiteBlackList.h"
//
// We are either in 1970ish (MONOTONIC) or 2015+ish (REALTIME) so to
// differentiate without prejudice, we use 1980 to delineate, earlier
// is monotonic, later is real.
//
namespace android {
static bool isMonotonic(const log_time &mono) {
static const uint32_t EPOCH_PLUS_10_YEARS = 10 * 1461 / 4 * 24 * 60 * 60;
return mono.tv_sec < EPOCH_PLUS_10_YEARS;
}
}
typedef std::list<LogBufferElement *> LogBufferElementCollection;
class LogBuffer {
@ -49,11 +64,14 @@ class LogBuffer {
unsigned long mMaxSize[LOG_ID_MAX];
bool monotonic;
public:
LastLogTimes &mTimes;
LogBuffer(LastLogTimes *times);
void init();
bool isMonotonic() { return monotonic; }
int log(log_id_t log_id, log_time realtime,
uid_t uid, pid_t pid, pid_t tid,

5
logd/LogBufferElement.h
View file

@ -34,6 +34,9 @@ class LogBuffer;
#define EXPIRE_RATELIMIT 10 // maximum rate in seconds to report expiration
class LogBufferElement {
friend LogBuffer;
const log_id_t mLogId;
const uid_t mUid;
const pid_t mPid;
@ -44,7 +47,7 @@ class LogBufferElement {
unsigned short mDropped; // mMsg == NULL
};
const uint64_t mSequence;
const log_time mRealTime;
log_time mRealTime;
static atomic_int_fast64_t sequence;
// assumption: mMsg == NULL

10
logd/LogKlog.cpp
View file

@ -330,6 +330,10 @@ void LogKlog::sniffTime(log_time &now,
}
*buf = cp;
if (isMonotonic()) {
return;
}
const char *b;
if (((b = strnstr(cp, len, suspendStr)))
&& ((size_t)((b += sizeof(suspendStr) - 1) - cp) < len)) {
@ -376,7 +380,11 @@ void LogKlog::sniffTime(log_time &now,
convertMonotonicToReal(now);
} else {
now = log_time(CLOCK_REALTIME);
if (isMonotonic()) {
now = log_time(CLOCK_MONOTONIC);
} else {
now = log_time(CLOCK_REALTIME);
}
}
}

2
logd/LogKlog.h
View file

@ -43,7 +43,9 @@ public:
int log(const char *buf, size_t len);
void synchronize(const char *buf, size_t len);
bool isMonotonic() { return logbuf->isMonotonic(); }
static void convertMonotonicToReal(log_time &real) { real += correction; }
static void convertRealToMonotonic(log_time &real) { real -= correction; }
protected:
void sniffTime(log_time &now, const char **buf, size_t len, bool reverse);

14
logd/LogReader.cpp
View file

@ -114,15 +114,17 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
log_time &start;
uint64_t &sequence;
uint64_t last;
bool isMonotonic;
public:
LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence) :
LogFindStart(unsigned logMask, pid_t pid, log_time &start, uint64_t &sequence, bool isMonotonic) :
mPid(pid),
mLogMask(logMask),
startTimeSet(false),
start(start),
sequence(sequence),
last(sequence) {
last(sequence),
isMonotonic(isMonotonic) {
}
static int callback(const LogBufferElement *element, void *obj) {
@ -133,20 +135,24 @@ bool LogReader::onDataAvailable(SocketClient *cli) {
me->sequence = element->getSequence();
me->startTimeSet = true;
return -1;
} else {
} else if (!me->isMonotonic ||
android::isMonotonic(element->getRealTime())) {
if (me->start < element->getRealTime()) {
me->sequence = me->last;
me->startTimeSet = true;
return -1;
}
me->last = element->getSequence();
} else {
me->last = element->getSequence();
}
}
return false;
}
bool found() { return startTimeSet; }
} logFindStart(logMask, pid, start, sequence);
} logFindStart(logMask, pid, start, sequence,
logbuf().isMonotonic() && android::isMonotonic(start));
logbuf().flushTo(cli, sequence, FlushCommand::hasReadLogs(cli),
logFindStart.callback, &logFindStart);

4
logd/README.property
View file

@ -25,6 +25,10 @@ persist.logd.filter string Pruning filter to optimize content,
"~!" which means to prune the oldest
entries of chattiest UID. At runtime
use: logcat -P "<string>"
persist.logd.timestamp string The recording timestamp source. Default
is ro.logd.timestamp. "m[onotonic]" is
the only supported key character,
otherwise assumes realtime.
NB:
- Number support multipliers (K or M) for convenience. Range is limited

2
logd/main.cpp
View file

@ -298,7 +298,7 @@ static void readDmesg(LogAudit *al, LogKlog *kl) {
}
buf[--len] = '\0';
if (kl) {
if (kl && kl->isMonotonic()) {
kl->synchronize(buf.get(), len);
}