From 9879ac8e1290d744fc4363e6a976516053d5f64d Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 3 Jun 2014 11:24:34 -0700 Subject: [PATCH] logcat: test: modernize - split sequential sort output test out as a benchmark check - Allow up to two failures of sort results because of occasional reader locks. - logcat -g output was changed to handle wider set of values incorporating a multiplier for UX, and would not pass test if 'logcat -G 1M' was run. - If spam filter is turned off, prune checks would fail, allowed for an empty default. Change-Id: I06d6089e18279df7525d1c16a1f76b3125ddbf05 --- logcat/tests/Android.mk | 32 ++++-- logcat/tests/logcat_benchmark.cpp | 128 ++++++++++++++++++++++++ logcat/tests/logcat_test.cpp | 155 ++++++++++-------------------- 3 files changed, 203 insertions(+), 112 deletions(-) create mode 100644 logcat/tests/logcat_benchmark.cpp diff --git a/logcat/tests/Android.mk b/logcat/tests/Android.mk index 5d4d29ebc..015a23df1 100644 --- a/logcat/tests/Android.mk +++ b/logcat/tests/Android.mk @@ -16,11 +16,7 @@ LOCAL_PATH := $(call my-dir) -# ----------------------------------------------------------------------------- -# Unit tests. -# ----------------------------------------------------------------------------- - -test_module := logcat-unit-tests +test_module_prefix := logcat- test_tags := tests test_c_flags := \ @@ -28,7 +24,29 @@ test_c_flags := \ -g \ -Wall -Wextra \ -Werror \ - -fno-builtin + -fno-builtin \ + -std=gnu++11 + +# ----------------------------------------------------------------------------- +# Benchmarks (actually a gTest where the result code does not matter) +# ---------------------------------------------------------------------------- + +benchmark_src_files := \ + logcat_benchmark.cpp + +# Build benchmarks for the device. Run with: +# adb shell /data/nativetest/logcat-benchmarks/logcat-benchmarks +include $(CLEAR_VARS) +LOCAL_MODULE := $(test_module_prefix)benchmarks +LOCAL_MODULE_TAGS := $(test_tags) +LOCAL_ADDITIONAL_DEPENDENCIES := $(LOCAL_PATH)/Android.mk +LOCAL_CFLAGS += $(test_c_flags) +LOCAL_SRC_FILES := $(benchmark_src_files) +include $(BUILD_NATIVE_TEST) + +# ----------------------------------------------------------------------------- +# Unit tests. +# ----------------------------------------------------------------------------- test_src_files := \ logcat_test.cpp \ @@ -36,7 +54,7 @@ test_src_files := \ # Build tests for the device (with .so). Run with: # adb shell /data/nativetest/logcat-unit-tests/logcat-unit-tests include $(CLEAR_VARS) -LOCAL_MODULE := $(test_module) +LOCAL_MODULE := $(test_module_prefix)unit-tests LOCAL_MODULE_TAGS := $(test_tags) LOCAL_ADDITIONAL_DEPENDENCIES := $(LOCAL_PATH)/Android.mk LOCAL_CFLAGS += $(test_c_flags) diff --git a/logcat/tests/logcat_benchmark.cpp b/logcat/tests/logcat_benchmark.cpp new file mode 100644 index 000000000..be815be1b --- /dev/null +++ b/logcat/tests/logcat_benchmark.cpp @@ -0,0 +1,128 @@ +/* + * Copyright (C) 2013-2014 The Android Open Source Project + * + * Licensed under the Apache License, Version 2.0 (the "License"); + * you may not use this file except in compliance with the License. + * You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ + +#include +#include +#include + +#include + +static const char begin[] = "--------- beginning of "; + +TEST(logcat, sorted_order) { + FILE *fp; + + ASSERT_TRUE(NULL != (fp = popen( + "logcat -v time -b radio -b events -b system -b main -d 2>/dev/null", + "r"))); + + class timestamp { + private: + int month; + int day; + int hour; + int minute; + int second; + int millisecond; + bool ok; + + public: + void init(const char *buffer) + { + ok = false; + if (buffer != NULL) { + ok = sscanf(buffer, "%d-%d %d:%d:%d.%d ", + &month, &day, &hour, &minute, &second, &millisecond) == 6; + } + } + + timestamp(const char *buffer) + { + init(buffer); + } + + bool operator< (timestamp &T) + { + return !ok || !T.ok + || (month < T.month) + || ((month == T.month) + && ((day < T.day) + || ((day == T.day) + && ((hour < T.hour) + || ((hour == T.hour) + && ((minute < T.minute) + || ((minute == T.minute) + && ((second < T.second) + || ((second == T.second) + && (millisecond < T.millisecond)))))))))); + } + + bool valid(void) + { + return ok; + } + } last(NULL); + + char *last_buffer = NULL; + char buffer[5120]; + + int count = 0; + int next_lt_last = 0; + + while (fgets(buffer, sizeof(buffer), fp)) { + if (!strncmp(begin, buffer, sizeof(begin) - 1)) { + continue; + } + if (!last.valid()) { + free(last_buffer); + last_buffer = strdup(buffer); + last.init(buffer); + } + timestamp next(buffer); + if (next < last) { + if (last_buffer) { + fprintf(stderr, "<%s", last_buffer); + } + fprintf(stderr, ">%s", buffer); + ++next_lt_last; + } + if (next.valid()) { + free(last_buffer); + last_buffer = strdup(buffer); + last.init(buffer); + } + ++count; + } + free(last_buffer); + + pclose(fp); + + static const int max_ok = 2; + + // Allow few fails, happens with readers active + fprintf(stderr, "%s: %d/%d out of order entries\n", + (next_lt_last) + ? ((next_lt_last <= max_ok) + ? "WARNING" + : "ERROR") + : "INFO", + next_lt_last, count); + + EXPECT_GE(max_ok, next_lt_last); + + // sample statistically too small + EXPECT_LT(100, count); +} diff --git a/logcat/tests/logcat_test.cpp b/logcat/tests/logcat_test.cpp index 2e8ae8b6d..9b316d150 100644 --- a/logcat/tests/logcat_test.cpp +++ b/logcat/tests/logcat_test.cpp @@ -17,6 +17,7 @@ #include #include #include +#include #include #include @@ -41,99 +42,6 @@ static const char begin[] = "--------- beginning of "; -TEST(logcat, sorted_order) { - FILE *fp; - - ASSERT_TRUE(NULL != (fp = popen( - "logcat -v time -b radio -b events -b system -b main -d 2>/dev/null", - "r"))); - - class timestamp { - private: - int month; - int day; - int hour; - int minute; - int second; - int millisecond; - bool ok; - - public: - void init(const char *buffer) - { - ok = false; - if (buffer != NULL) { - ok = sscanf(buffer, "%d-%d %d:%d:%d.%d ", - &month, &day, &hour, &minute, &second, &millisecond) == 6; - } - } - - timestamp(const char *buffer) - { - init(buffer); - } - - bool operator< (timestamp &T) - { - return !ok || !T.ok - || (month < T.month) - || ((month == T.month) - && ((day < T.day) - || ((day == T.day) - && ((hour < T.hour) - || ((hour == T.hour) - && ((minute < T.minute) - || ((minute == T.minute) - && ((second < T.second) - || ((second == T.second) - && (millisecond < T.millisecond)))))))))); - } - - bool valid(void) - { - return ok; - } - } last(NULL); - - char *last_buffer = NULL; - char buffer[5120]; - - int count = 0; - int next_lt_last = 0; - - while (fgets(buffer, sizeof(buffer), fp)) { - if (!strncmp(begin, buffer, sizeof(begin) - 1)) { - continue; - } - if (!last.valid()) { - free(last_buffer); - last_buffer = strdup(buffer); - last.init(buffer); - } - timestamp next(buffer); - if (next < last) { - if (last_buffer) { - fprintf(stderr, "<%s", last_buffer); - } - fprintf(stderr, ">%s", buffer); - ++next_lt_last; - } - if (next.valid()) { - free(last_buffer); - last_buffer = strdup(buffer); - last.init(buffer); - } - ++count; - } - free(last_buffer); - - pclose(fp); - - EXPECT_EQ(0, next_lt_last); - - EXPECT_LT(100, count); -} - TEST(logcat, buckets) { FILE *fp; @@ -362,9 +270,10 @@ TEST(logcat, End_to_End) { ASSERT_EQ(1, count); } -TEST(logcat, get_) { +TEST(logcat, get_size) { FILE *fp; + // NB: crash log only available in user space ASSERT_TRUE(NULL != (fp = popen( "logcat -b radio -b events -b system -b main -g 2>/dev/null", "r"))); @@ -375,13 +284,49 @@ TEST(logcat, get_) { while (fgets(buffer, sizeof(buffer), fp)) { int size, consumed, max, payload; + char size_mult, consumed_mult; + long full_size, full_consumed; size = consumed = max = payload = 0; - if ((4 == sscanf(buffer, "%*s ring buffer is %dKb (%dKb consumed)," - " max entry is %db, max payload is %db", - &size, &consumed, &max, &payload)) - && ((size * 3) >= consumed) - && ((size * 1024) > max) + // NB: crash log can be very small, not hit a Kb of consumed space + // doubly lucky we are not including it. + if (6 != sscanf(buffer, "%*s ring buffer is %d%cb (%d%cb consumed)," + " max entry is %db, max payload is %db", + &size, &size_mult, &consumed, &consumed_mult, + &max, &payload)) { + fprintf(stderr, "WARNING: Parse error: %s", buffer); + continue; + } + full_size = size; + switch(size_mult) { + case 'G': + full_size *= 1024; + /* FALLTHRU */ + case 'M': + full_size *= 1024; + /* FALLTHRU */ + case 'K': + full_size *= 1024; + break; + } + full_consumed = consumed; + switch(consumed_mult) { + case 'G': + full_consumed *= 1024; + /* FALLTHRU */ + case 'M': + full_consumed *= 1024; + /* FALLTHRU */ + case 'K': + full_consumed *= 1024; + break; + } + EXPECT_GT((full_size * 9) / 4, full_consumed); + EXPECT_GT(full_size, max); + EXPECT_GT(max, payload); + + if ((((full_size * 9) / 4) >= full_consumed) + && (full_size > max) && (max > payload)) { ++count; } @@ -649,7 +594,7 @@ static bool set_white_black(const char *list) { char buffer[5120]; - snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list); + snprintf(buffer, sizeof(buffer), "logcat -P '%s' 2>&1", list ? list : ""); fp = popen(buffer, "r"); if (fp == NULL) { fprintf(stderr, "ERROR: %s\n", buffer); @@ -662,10 +607,10 @@ static bool set_white_black(const char *list) { ++buf; } char *end = buf + strlen(buf); - while (isspace(*--end) && (end >= buf)) { + while ((end > buf) && isspace(*--end)) { *end = '\0'; } - if (end < buf) { + if (end <= buf) { continue; } fprintf(stderr, "%s\n", buf); @@ -679,7 +624,7 @@ TEST(logcat, white_black_adjust) { char *list = NULL; char *adjust = NULL; - ASSERT_EQ(true, get_white_black(&list)); + get_white_black(&list); static const char adjustment[] = "~! 300/20 300/25 2000 ~1000/5 ~1000/30"; ASSERT_EQ(true, set_white_black(adjustment)); @@ -696,8 +641,8 @@ TEST(logcat, white_black_adjust) { adjust = NULL; ASSERT_EQ(true, set_white_black(list)); - ASSERT_EQ(true, get_white_black(&adjust)); - EXPECT_STREQ(list, adjust); + get_white_black(&adjust); + EXPECT_STREQ(list ? list : "", adjust ? adjust : ""); free(adjust); adjust = NULL;