TEST(logcat, regex) {
FILE *fp;
int count = 0;
char buffer[BIG_BUFFER];
snprintf(buffer, sizeof(buffer), "logcat --pid %d -d -e logcat_test_a+b", getpid());
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_ab"));
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_b"));
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_aaaab"));
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test_aaaa"));
// Let the logs settle
sleep(1);
ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
while (fgets(buffer, sizeof(buffer), fp)) {
if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
continue;
}
EXPECT_TRUE(strstr(buffer, "logcat_test_") != NULL);
count++;
}
pclose(fp);
ASSERT_EQ(2, count);
}
TEST(logcat, maxcount) {
FILE *fp;
int count = 0;
char buffer[BIG_BUFFER];
snprintf(buffer, sizeof(buffer), "logcat --pid %d -d --max-count 3", getpid());
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
LOG_FAILURE_RETRY(__android_log_print(ANDROID_LOG_WARN, "logcat_test", "logcat_test"));
// Let the logs settle
sleep(1);
ASSERT_TRUE(NULL != (fp = popen(buffer, "r")));
while (fgets(buffer, sizeof(buffer), fp)) {
if (!strncmp(begin, buffer, sizeof(begin) - 1)) {
continue;
}
count++;
}
pclose(fp);
ASSERT_EQ(3, 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(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 for the logd posting call to make it into
* the logs. Expect this to be less than double the process wakeup time (2ms).
*/
static void BM_log_delay(benchmark::State& state) {
pid_t pid = getpid();
struct logger_list* logger_list =
android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid);
if (!logger_list) {
fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
exit(EXIT_FAILURE);
}
signal(SIGALRM, caught_delay);
alarm(alarm_time);
while (state.KeepRunning()) {
log_time ts(CLOCK_REALTIME);
LOG_FAILURE_RETRY(android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
for (;;) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
alarm(alarm_time);
if (ret <= 0) {
state.SkipWithError("android_logger_list_read");
break;
}
if ((log_msg.entry.len != (4 + 1 + 8)) ||
(log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char* eventData = log_msg.msg();
if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) {
continue;
}
log_time tx(eventData + 4 + 1);
if (ts != tx) {
if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) {
state.SkipWithError("signal");
break;
}
continue;
}
break;
}
}
state.PauseTiming();
signal(SIGALRM, SIG_DFL);
alarm(0);
android_logger_list_free(logger_list);
}
TEST(liblog, too_big_payload) {
pid_t pid = getpid();
static const char big_payload_tag[] = "TEST_big_payload_XXXX";
char tag[sizeof(big_payload_tag)];
memcpy(tag, big_payload_tag, sizeof(tag));
snprintf(tag + sizeof(tag) - 5, 5, "%04X", pid & 0xFFFF);
std::string longString(3266519, 'x');
ssize_t ret = LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_SYSTEM,
ANDROID_LOG_INFO, tag, longString.c_str()));
struct logger_list *logger_list;
ASSERT_TRUE(NULL != (logger_list = android_logger_list_open(
LOG_ID_SYSTEM, O_RDONLY | O_NDELAY, 100, 0)));
ssize_t max_len = 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.id() != LOG_ID_SYSTEM)) {
continue;
}
char *data = log_msg.msg() + 1;
if (strcmp(data, tag)) {
continue;
}
data += strlen(data) + 1;
const char *left = data;
const char *right = longString.c_str();
while (*left && *right && (*left == *right)) {
++left;
++right;
}
if (max_len <= (left - data)) {
max_len = left - data + 1;
}
}
android_logger_list_close(logger_list);
EXPECT_LE(LOGGER_ENTRY_MAX_PAYLOAD - sizeof(big_payload_tag),
static_cast<size_t>(max_len));
EXPECT_EQ(ret, max_len + sizeof(big_payload_tag));
}
/*
* Measure the fastest rate we can reliabley stuff print messages into
* the log at high pressure. Expect this to be less than double the process
* wakeup time (2ms?)
*/
static void BM_log_maximum_retry(int iters) {
StartBenchmarkTiming();
for (int i = 0; i < iters; ++i) {
LOG_FAILURE_RETRY(
__android_log_print(ANDROID_LOG_INFO,
"BM_log_maximum_retry", "%d", i));
}
StopBenchmarkTiming();
}
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 for the logd posting call to make it into
* the logs. Expect this to be less than double the process wakeup time (2ms).
*/
static void BM_log_delay(int iters) {
pid_t pid = getpid();
struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS,
O_RDONLY, 0, pid);
if (!logger_list) {
fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
exit(EXIT_FAILURE);
}
signal(SIGALRM, caught_delay);
alarm(alarm_time);
StartBenchmarkTiming();
for (int i = 0; i < iters; ++i) {
log_time ts(CLOCK_REALTIME);
LOG_FAILURE_RETRY(
android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)));
for (;;) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
alarm(alarm_time);
if (ret <= 0) {
iters = i;
break;
}
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) {
if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) {
iters = i;
break;
}
continue;
}
break;
}
}
signal(SIGALRM, SIG_DFL);
alarm(0);
StopBenchmarkTiming();
android_logger_list_free(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)));
}
/*
* Measure the time it takes for the logd posting call to acquire the
* timestamp to place into the internal record. Expect this to be less than
* 4 syscalls (3us). This test uses manual injection of timing because it is
* comparing the timestamp at send, and then picking up the corresponding log
* end-to-end long path from logd to see what actual timestamp was submitted.
*/
static void BM_log_latency(benchmark::State& state) {
pid_t pid = getpid();
struct logger_list* logger_list =
android_logger_list_open(LOG_ID_EVENTS, ANDROID_LOG_RDONLY, 0, pid);
if (!logger_list) {
fprintf(stderr, "Unable to open events log: %s\n", strerror(errno));
exit(EXIT_FAILURE);
}
signal(SIGALRM, caught_latency);
alarm(alarm_time);
for (size_t j = 0; state.KeepRunning() && j < 10 * state.iterations(); ++j) {
retry: // We allow transitory errors (logd overloaded) to be retried.
log_time ts;
LOG_FAILURE_RETRY((ts = log_time(CLOCK_REALTIME),
android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))));
for (;;) {
log_msg log_msg;
int ret = android_logger_list_read(logger_list, &log_msg);
alarm(alarm_time);
if (ret <= 0) {
state.SkipWithError("android_logger_list_read");
break;
}
if ((log_msg.entry.len != (4 + 1 + 8)) ||
(log_msg.id() != LOG_ID_EVENTS)) {
continue;
}
char* eventData = log_msg.msg();
if (!eventData || (eventData[4] != EVENT_TYPE_LONG)) {
continue;
}
log_time tx(eventData + 4 + 1);
if (ts != tx) {
if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) {
state.SkipWithError("signal");
break;
}
continue;
}
uint64_t start = ts.nsec();
uint64_t end = log_msg.nsec();
if (end < start) goto retry;
state.SetIterationTime((end - start) / (double)NS_PER_SEC);
break;
}
}
signal(SIGALRM, SIG_DFL);
alarm(0);
android_logger_list_free(logger_list);
}
/*
* Measure the fastest rate we can reliabley stuff print messages into
* the log at high pressure. Expect this to be less than double the process
* wakeup time (2ms?)
*/
static void BM_log_maximum_retry(benchmark::State& state) {
while (state.KeepRunning()) {
LOG_FAILURE_RETRY(__android_log_print(
ANDROID_LOG_INFO, "BM_log_maximum_retry", "%zu", state.iterations()));
}
}
