TEST(logd, statistics) {
size_t len;
char *buf;
alloc_statistics(&buf, &len);
ASSERT_TRUE(NULL != buf);
// remove trailing FF
char *cp = buf + len - 1;
*cp = '\0';
bool truncated = *--cp != '\f';
if (!truncated) {
*cp = '\0';
}
// squash out the byte count
cp = buf;
if (!truncated) {
while (isdigit(*cp) || (*cp == '\n')) {
++cp;
}
}
fprintf(stderr, "%s", cp);
EXPECT_LT((size_t)64, strlen(cp));
EXPECT_EQ(0, truncated);
char *main_logs = strstr(cp, "\nChattiest UIDs in main ");
EXPECT_TRUE(NULL != main_logs);
char *radio_logs = strstr(cp, "\nChattiest UIDs in radio ");
EXPECT_TRUE(NULL != radio_logs);
char *system_logs = strstr(cp, "\nChattiest UIDs in system ");
EXPECT_TRUE(NULL != system_logs);
char *events_logs = strstr(cp, "\nChattiest UIDs in events ");
EXPECT_TRUE(NULL != events_logs);
delete [] buf;
}
// BAD ROBOT
// Benchmark threshold are generally considered bad form unless there is
// is some human love applied to the continued maintenance and whether the
// thresholds are tuned on a per-target basis. Here we check if the values
// are more than double what is expected. Doubling will not prevent failure
// on busy or low-end systems that could have a tendency to stretch values.
//
// The primary goal of this test is to simulate a spammy app (benchmark
// being the worst) and check to make sure the logger can deal with it
// appropriately by checking all the statistics are in an expected range.
//
TEST(logd, benchmark) {
size_t len;
char *buf;
alloc_statistics(&buf, &len);
bool benchmark_already_run = buf && find_benchmark_spam(buf);
delete [] buf;
if (benchmark_already_run) {
fprintf(stderr, "WARNING: spam already present and too much history\n"
" false OK for prune by worst UID check\n");
}
FILE *fp;
// Introduce some extreme spam for the worst UID filter
ASSERT_TRUE(NULL != (fp = popen(
"/data/nativetest/liblog-benchmarks/liblog-benchmarks",
"r")));
char buffer[5120];
static const char *benchmarks[] = {
"BM_log_maximum_retry ",
"BM_log_maximum ",
"BM_clock_overhead ",
"BM_log_overhead ",
"BM_log_latency ",
"BM_log_delay "
};
static const unsigned int log_maximum_retry = 0;
static const unsigned int log_maximum = 1;
static const unsigned int clock_overhead = 2;
static const unsigned int log_overhead = 3;
static const unsigned int log_latency = 4;
static const unsigned int log_delay = 5;
unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])];
memset(ns, 0, sizeof(ns));
while (fgets(buffer, sizeof(buffer), fp)) {
for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
char *cp = strstr(buffer, benchmarks[i]);
if (!cp) {
continue;
}
sscanf(cp, "%*s %lu %lu", &ns[i], &ns[i]);
fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
}
}
int ret = pclose(fp);
if (!WIFEXITED(ret) || (WEXITSTATUS(ret) == 127)) {
fprintf(stderr,
"WARNING: "
"/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
" can not perform test\n");
return;
}
#ifdef TARGET_USES_LOGD
EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user
#else
EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel
#endif
#ifdef TARGET_USES_LOGD
EXPECT_GE(30000UL, ns[log_maximum]); // 27305 user
#else
EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel
#endif
EXPECT_GE(4096UL, ns[clock_overhead]); // 4095
#ifdef TARGET_USES_LOGD
EXPECT_GE(250000UL, ns[log_overhead]); // 121876 user
#else
EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel
#endif
#ifdef TARGET_USES_LOGD
EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space
#else
EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel
#endif
#ifdef TARGET_USES_LOGD
EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user
#else
EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel
#endif
for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
EXPECT_NE(0UL, ns[i]);
}
alloc_statistics(&buf, &len);
#ifdef TARGET_USES_LOGD
bool collected_statistics = !!buf;
EXPECT_EQ(true, collected_statistics);
#else
if (!buf) {
return;
}
#endif
ASSERT_TRUE(NULL != buf);
char *benchmark_statistics_found = find_benchmark_spam(buf);
ASSERT_TRUE(benchmark_statistics_found != NULL);
// Check how effective the SPAM filter is, parse out Now size.
// Total Now
// 0/4225? 7454388/303656 31488/755
// ^-- benchmark_statistics_found
unsigned long nowSpamSize = atol(benchmark_statistics_found);
delete [] buf;
ASSERT_NE(0UL, nowSpamSize);
// Determine if we have the spam filter enabled
int sock = socket_local_client("logd",
ANDROID_SOCKET_NAMESPACE_RESERVED,
SOCK_STREAM);
ASSERT_TRUE(sock >= 0);
static const char getPruneList[] = "getPruneList";
if (write(sock, getPruneList, sizeof(getPruneList)) > 0) {
char buffer[80];
memset(buffer, 0, sizeof(buffer));
read(sock, buffer, sizeof(buffer));
char *cp = strchr(buffer, '\n');
if (!cp || (cp[1] != '~') || (cp[2] != '!')) {
close(sock);
fprintf(stderr,
"WARNING: "
"Logger has SPAM filtration turned off \"%s\"\n", buffer);
return;
}
} else {
int save_errno = errno;
close(sock);
FAIL() << "Can not send " << getPruneList << " to logger -- " << strerror(save_errno);
}
static const unsigned long expected_absolute_minimum_log_size = 65536UL;
unsigned long totalSize = expected_absolute_minimum_log_size;
static const char getSize[] = {
'g', 'e', 't', 'L', 'o', 'g', 'S', 'i', 'z', 'e', ' ',
LOG_ID_MAIN + '0', '\0'
};
if (write(sock, getSize, sizeof(getSize)) > 0) {
char buffer[80];
memset(buffer, 0, sizeof(buffer));
read(sock, buffer, sizeof(buffer));
totalSize = atol(buffer);
if (totalSize < expected_absolute_minimum_log_size) {
fprintf(stderr,
"WARNING: "
"Logger had unexpected referenced size \"%s\"\n", buffer);
totalSize = expected_absolute_minimum_log_size;
}
}
close(sock);
// logd allows excursions to 110% of total size
totalSize = (totalSize * 11 ) / 10;
// 50% threshold for SPAM filter (<20% typical, lots of engineering margin)
ASSERT_GT(totalSize, nowSpamSize * 2);
}
TEST(logd, statistics) {
size_t len;
char *buf;
alloc_statistics(&buf, &len);
#ifdef TARGET_USES_LOGD
ASSERT_TRUE(NULL != buf);
#else
if (!buf) {
return;
}
#endif
// remove trailing FF
char *cp = buf + len - 1;
*cp = '\0';
bool truncated = *--cp != '\f';
if (!truncated) {
*cp = '\0';
}
// squash out the byte count
cp = buf;
if (!truncated) {
while (isdigit(*cp) || (*cp == '\n')) {
++cp;
}
}
fprintf(stderr, "%s", cp);
EXPECT_LT((size_t)64, strlen(cp));
EXPECT_EQ(0, truncated);
#ifdef TARGET_USES_LOGD
char *main_logs = strstr(cp, "\nmain:");
EXPECT_TRUE(NULL != main_logs);
char *radio_logs = strstr(cp, "\nradio:");
EXPECT_TRUE(NULL != radio_logs);
char *system_logs = strstr(cp, "\nsystem:");
EXPECT_TRUE(NULL != system_logs);
char *events_logs = strstr(cp, "\nevents:");
EXPECT_TRUE(NULL != events_logs);
#endif
// Parse timing stats
cp = strstr(cp, "Minimum time between log events per dgram_qlen:");
if (cp) {
while (*cp && (*cp != '\n')) {
++cp;
}
if (*cp == '\n') {
++cp;
}
char *list_of_spans = cp;
EXPECT_NE('\0', *list_of_spans);
unsigned short number_of_buckets = 0;
unsigned short *dgram_qlen = NULL;
unsigned short bucket = 0;
while (*cp && (*cp != '\n')) {
bucket = 0;
while (isdigit(*cp)) {
bucket = bucket * 10 + *cp - '0';
++cp;
}
while (*cp == ' ') {
++cp;
}
if (!bucket) {
break;
}
unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1];
EXPECT_TRUE(new_dgram_qlen != NULL);
if (dgram_qlen) {
memcpy(new_dgram_qlen, dgram_qlen, sizeof(*dgram_qlen) * number_of_buckets);
delete [] dgram_qlen;
}
dgram_qlen = new_dgram_qlen;
dgram_qlen[number_of_buckets++] = bucket;
}
char *end_of_spans = cp;
EXPECT_NE('\0', *end_of_spans);
EXPECT_LT(5, number_of_buckets);
unsigned long long *times = new unsigned long long [number_of_buckets];
ASSERT_TRUE(times != NULL);
memset(times, 0, sizeof(*times) * number_of_buckets);
while (*cp == '\n') {
++cp;
}
unsigned short number_of_values = 0;
unsigned long long value;
while (*cp && (*cp != '\n')) {
EXPECT_GE(number_of_buckets, number_of_values);
value = 0;
while (isdigit(*cp)) {
value = value * 10ULL + *cp - '0';
++cp;
}
switch(*cp) {
case ' ':
case '\n':
value *= 1000ULL;
/* FALLTHRU */
case 'm':
value *= 1000ULL;
/* FALLTHRU */
case 'u':
value *= 1000ULL;
/* FALLTHRU */
case 'n':
default:
break;
}
while (*++cp == ' ');
if (!value) {
break;
}
times[number_of_values] = value;
++number_of_values;
}
#ifdef TARGET_USES_LOGD
EXPECT_EQ(number_of_values, number_of_buckets);
#endif
FILE *fp;
ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r")));
unsigned max_dgram_qlen = 0;
fscanf(fp, "%u", &max_dgram_qlen);
fclose(fp);
// Find launch point
unsigned short launch = 0;
unsigned long long total = 0;
do {
total += times[launch];
} while (((++launch < number_of_buckets)
&& ((total / launch) >= (times[launch] / 8ULL)))
|| (launch == 1)); // too soon
bool failure = number_of_buckets <= launch;
if (!failure) {
unsigned short l = launch;
if (l >= number_of_buckets) {
l = number_of_buckets - 1;
}
failure = max_dgram_qlen < dgram_qlen[l];
}
// We can get failure if at any time liblog_benchmarks has been run
// because designed to overload /proc/sys/net/unix/max_dgram_qlen even
// at excessive values like 20000. It does so to measure the raw processing
// performance of logd.
if (failure) {
cp = find_benchmark_spam(cp);
}
if (cp) {
// Fake a failure, but without the failure code
if (number_of_buckets <= launch) {
printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n",
number_of_buckets, launch);
}
if (launch >= number_of_buckets) {
launch = number_of_buckets - 1;
}
if (max_dgram_qlen < dgram_qlen[launch]) {
printf ("Expected: max_dgram_qlen >= dgram_qlen[%d],"
" actual: %u vs %u\n",
launch, max_dgram_qlen, dgram_qlen[launch]);
}
} else
#ifndef TARGET_USES_LOGD
if (total)
#endif
{
EXPECT_GT(number_of_buckets, launch);
if (launch >= number_of_buckets) {
launch = number_of_buckets - 1;
}
EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]);
}
delete [] dgram_qlen;
delete [] times;
}
delete [] buf;
}
