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

3 files changed, 203 insertions, 112 deletions

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 <stdio.h>
+#include <stdlib.h>
+#include <string.h>
+
+#include <gtest/gtest.h>
+
+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 <ctype.h>
 #include <signal.h>
 #include <stdio.h>
+#include <stdlib.h>
 #include <string.h>
 
 #include <gtest/gtest.h>
@@ -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;