TEST(logcat, End_to_End) {
pid_t pid = getpid();
log_time ts(CLOCK_MONOTONIC);
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
FILE *fp;
ASSERT_EQ(0, NULL == (fp = popen(
"logcat -b events -t 100 2>/dev/null",
"r")));
char buffer[5120];
int count = 0;
while (fgets(buffer, sizeof(buffer), fp)) {
int p;
unsigned long long t;
if ((2 != sscanf(buffer, "I/[0] ( %d): %llu", &p, &t))
|| (p != pid)) {
continue;
}
log_time tx((const char *) &t);
if (ts == tx) {
++count;
}
}
pclose(fp);
ASSERT_EQ(1, count);
}
static void caught_blocking_clear(int /*signum*/) {
unsigned long long v = 0xDEADBEEFA55C0000ULL;
v += getpid() & 0xFFFF;
LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
}
TEST(liblog, __android_log_btwrite) {
int intBuf = 0xDEADBEEF;
ASSERT_LT(0, __android_log_btwrite(0,
EVENT_TYPE_INT,
&intBuf, sizeof(intBuf)));
long long longBuf = 0xDEADBEEFA55A5AA5;
ASSERT_LT(0, __android_log_btwrite(0,
EVENT_TYPE_LONG,
&longBuf, sizeof(longBuf)));
usleep(1000);
char Buf[] = "\20\0\0\0DeAdBeEfA55a5aA5";
ASSERT_LT(0, __android_log_btwrite(0,
EVENT_TYPE_STRING,
Buf, sizeof(Buf) - 1));
usleep(1000);
}
TEST(logcat, blocking) {
FILE *fp;
unsigned long long v = 0xDEADBEEFA55F0000ULL;
pid_t pid = getpid();
v += pid & 0xFFFF;
LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
v &= 0xFFFFFFFFFFFAFFFFULL;
ASSERT_EQ(0, NULL == (fp = popen(
"( trap exit HUP QUIT INT PIPE KILL ; sleep 6; echo DONE )&"
" logcat -b events 2>&1",
"r")));
char buffer[5120];
int count = 0;
int signals = 0;
signal(SIGALRM, caught_blocking);
alarm(2);
while (fgets(buffer, sizeof(buffer), fp)) {
alarm(2);
if (!strncmp(buffer, "DONE", 4)) {
break;
}
++count;
int p;
unsigned long long l;
if ((2 != sscanf(buffer, "I/[0] ( %u): %lld", &p, &l))
|| (p != pid)) {
continue;
}
if (l == v) {
++signals;
break;
}
}
alarm(0);
signal(SIGALRM, SIG_DFL);
// Generate SIGPIPE
fclose(fp);
caught_blocking(0);
pclose(fp);
ASSERT_LE(2, count);
ASSERT_EQ(1, signals);
}
static void caught_blocking_tail(int signum)
{
unsigned long long v = 0xA55ADEADBEEF0000ULL;
v += getpid() & 0xFFFF;
LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
}
/*
* Measure the time it takes to submit the android event logging call
* using discrete acquisition under very-light load (<1% CPU utilization).
*/
static void BM_log_light_overhead(benchmark::State& state) {
for (int64_t i = 0; state.KeepRunning(); ++i) {
__android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i));
state.PauseTiming();
usleep(10000);
state.ResumeTiming();
}
}
/*
* Measure the time it takes to submit the android event logging call
* using discrete acquisition under light load. Expect this to be a long path
* to logger to convert the unknown tag (0) into a tagname (less than 200us).
*/
static void BM_log_event_overhead(benchmark::State& state) {
for (int64_t i = 0; state.KeepRunning(); ++i) {
// log tag number 0 is not known, nor shall it ever be known
__android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i));
state.PauseTiming();
logd_yield();
state.ResumeTiming();
}
}
static void caught_blocking(int signum)
{
unsigned long long v = 0xDEADBEEFA55A0000ULL;
v += getpid() & 0xFFFF;
++signaled;
if ((signal_time.tv_sec == 0) && (signal_time.tv_nsec == 0)) {
clock_gettime(CLOCK_MONOTONIC, &signal_time);
signal_time.tv_sec += 2;
}
LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
}
/*
* Measure the time it takes to submit the android event logging call
* using discrete acquisition under light load with a known logtag. Expect
* this to be a dozen or so syscall periods (less than 40us)
*/
static void BM_log_event_overhead_42(benchmark::State& state) {
for (int64_t i = 0; state.KeepRunning(); ++i) {
// In system/core/logcat/event.logtags:
// # These are used for testing, do not modify without updating
// # tests/framework-tests/src/android/util/EventLogFunctionalTest.java.
// # system/core/liblog/tests/liblog_benchmark.cpp
// # system/core/liblog/tests/liblog_test.cpp
// 42 answer (to life the universe etc|3)
__android_log_btwrite(42, EVENT_TYPE_LONG, &i, sizeof(i));
state.PauseTiming();
logd_yield();
state.ResumeTiming();
}
}
TEST(liblog, __android_log_btwrite__android_logger_list_read) {
struct logger_list *logger_list;
pid_t pid = getpid();
ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open(
LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid)));
log_time ts(CLOCK_MONOTONIC);
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
usleep(1000000);
int count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) {
break;
}
ASSERT_EQ(log_msg.entry.pid, pid);
if ((log_msg.entry.len != (4 + 1 + 8))
|| (log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char *eventData = log_msg.msg();
if (eventData[4] != EVENT_TYPE_LONG) {
continue;
}
log_time tx(eventData + 4 + 1);
if (ts == tx) {
++count;
}
}
ASSERT_EQ(1, count);
android_logger_list_close(logger_list);
}
static void caught_delay(int /*signum*/)
{
unsigned long long v = 0xDEADBEEFA55A5AA6ULL;
LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
}
void __android_log_btwrite_multiple__helper(int count) {
log_time ts(CLOCK_MONOTONIC);
struct logger_list *logger_list;
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_EVENTS, ANDROID_LOG_RDONLY | ANDROID_LOG_NONBLOCK, 1000, 0)));
log_time ts1(CLOCK_MONOTONIC);
pid_t pid = fork();
if (pid == 0) {
// child
for (int i = count; i; --i) {
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
usleep(100);
}
ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts1, sizeof(ts1)));
usleep(1000000);
_exit(0);
}
siginfo_t info{};
ASSERT_EQ(0, TEMP_FAILURE_RETRY(waitid(P_PID, pid, &info, WEXITED)));
int expected_count = (count < 2) ? count : 2;
int expected_chatty_count = (count <= 2) ? 0 : 1;
int expected_expire_count = (count < 2) ? 0 : (count - 2);
count = 0;
int second_count = 0;
int chatty_count = 0;
int expire_count = 0;
for (;;) {
log_msg log_msg;
if (android_logger_list_read(logger_list, &log_msg) <= 0) break;
if ((log_msg.entry.pid != pid) ||
(log_msg.entry.len < (4 + 1 + 8)) ||
(log_msg.id() != LOG_ID_EVENTS)) continue;
char *eventData = log_msg.msg();
if (!eventData) continue;
uint32_t tag = get4LE(eventData);
if ((eventData[4] == EVENT_TYPE_LONG) && (log_msg.entry.len == (4 + 1 + 8))) {
if (tag != 0) continue;
log_time tx(eventData + 4 + 1);
if (ts == tx) {
++count;
} else if (ts1 == tx) {
++second_count;
}
} else if (eventData[4] == EVENT_TYPE_STRING) {
// chatty
if (tag != 1004) continue;
++chatty_count;
// int len = get4LE(eventData + 4 + 1);
const char *cp = strstr(eventData + 4 + 1 + 4, " expire ");
if (!cp) continue;
unsigned val = 0;
sscanf(cp, " expire %u lines", &val);
expire_count += val;
}
}
EXPECT_EQ(expected_count, count);
EXPECT_EQ(1, second_count);
EXPECT_EQ(expected_chatty_count, chatty_count);
EXPECT_EQ(expected_expire_count, expire_count);
android_logger_list_close(logger_list);
}