From fe8c96d1526bd66d0c1adb757c87deefbbd29490 Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Tue, 28 Mar 2017 11:40:55 -0700 Subject: [PATCH 1/2] liblog: benchmark add BM_log_event_overhead_42 for a well known tag Measure the cost of using a known test event log tag from system/core/logcat/event.logtags: 42 answer (to life the universe etc|3) Test: liblog_benchmarks BM_log_event_overhead_42 Bug: 36683634 Change-Id: Ibd4be82bebfcedd381c84e8078cf6d05a636aa98 --- liblog/tests/liblog_benchmark.cpp | 26 +++++++++++++++++++++++++- logcat/event.logtags | 2 ++ 2 files changed, 27 insertions(+), 1 deletion(-) diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp index 3f795526c..c4bf95962 100644 --- a/liblog/tests/liblog_benchmark.cpp +++ b/liblog/tests/liblog_benchmark.cpp @@ -527,11 +527,13 @@ BENCHMARK(BM_log_print_overhead); /* * Measure the time it takes to submit the android event logging call * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) - * under light load. Expect this to be a dozen or so syscall periods (40us) + * 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(int iters) { for (unsigned long long i = 0; i < (unsigned)iters; ++i) { StartBenchmarkTiming(); + // log tag number 0 is not known, nor shall it ever be known __android_log_btwrite(0, EVENT_TYPE_LONG, &i, sizeof(i)); StopBenchmarkTiming(); logd_yield(); @@ -539,6 +541,28 @@ static void BM_log_event_overhead(int iters) { } BENCHMARK(BM_log_event_overhead); +/* + * Measure the time it takes to submit the android event logging call + * using discrete acquisition (StartBenchmarkTiming() -> StopBenchmarkTiming()) + * 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(int iters) { + for (unsigned long long i = 0; i < (unsigned)iters; ++i) { + StartBenchmarkTiming(); + // 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)); + StopBenchmarkTiming(); + logd_yield(); + } +} +BENCHMARK(BM_log_event_overhead_42); + static void BM_log_event_overhead_null(int iters) { set_log_null(); BM_log_event_overhead(iters); diff --git a/logcat/event.logtags b/logcat/event.logtags index 909f8e200..9f053511b 100644 --- a/logcat/event.logtags +++ b/logcat/event.logtags @@ -36,6 +36,8 @@ # 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) 314 pi 2718 e From 81ab11af67e8258bf70a98b8798ea027a414002b Mon Sep 17 00:00:00 2001 From: Mark Salyzyn Date: Wed, 29 Mar 2017 09:11:19 -0700 Subject: [PATCH 2/2] logd: liblog benchmark check BM_log_overhead regression Failed to acquire BM_log_print_overhead as it was renamed from BM_log_overhead in commit 8f2492f5821f7163a13c58286de8d0d419fefddc (liblog: benchmark: Use local LOGGER_NULL frontend') The test report would not clearly identify which entry was missing, or unparsed, so unrolled the loop and incorporating the indexes by name so that gTest failure report offers a much better clue to the problem. Test: gTest logd-unit-tests --gtest=logd.benchmark Bug: 36683634 Bug: 27405083 Change-Id: Ic590c230569871651fb716054ecf635385d0f8a2 --- logd/tests/logd_test.cpp | 20 +++++++++++--------- 1 file changed, 11 insertions(+), 9 deletions(-) diff --git a/logd/tests/logd_test.cpp b/logd/tests/logd_test.cpp index ddff39350..d0101edf6 100644 --- a/logd/tests/logd_test.cpp +++ b/logd/tests/logd_test.cpp @@ -426,7 +426,7 @@ TEST(logd, benchmark) { " BM_log_maximum_retry" " BM_log_maximum" " BM_clock_overhead" - " BM_log_overhead" + " BM_log_print_overhead" " BM_log_latency" " BM_log_delay", "r"))); @@ -434,13 +434,13 @@ TEST(logd, benchmark) { 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 " + "BM_log_maximum_retry ", "BM_log_maximum ", "BM_clock_overhead ", + "BM_log_print_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_print_overhead = 3; static const unsigned int log_latency = 4; static const unsigned int log_delay = 5; @@ -469,21 +469,23 @@ TEST(logd, benchmark) { } EXPECT_GE(200000UL, ns[log_maximum_retry]); // 104734 user + EXPECT_NE(0UL, ns[log_maximum_retry]); // failure to parse EXPECT_GE(90000UL, ns[log_maximum]); // 46913 user + EXPECT_NE(0UL, ns[log_maximum]); // failure to parse EXPECT_GE(4096UL, ns[clock_overhead]); // 4095 + EXPECT_NE(0UL, ns[clock_overhead]); // failure to parse - EXPECT_GE(250000UL, ns[log_overhead]); // 126886 user + EXPECT_GE(250000UL, ns[log_print_overhead]); // 126886 user + EXPECT_NE(0UL, ns[log_print_overhead]); // failure to parse EXPECT_GE(10000000UL, ns[log_latency]); // 1453559 user space (background cgroup) + EXPECT_NE(0UL, ns[log_latency]); // failure to parse EXPECT_GE(20000000UL, ns[log_delay]); // 10500289 user - - for (unsigned i = 0; i < arraysize(ns); ++i) { - EXPECT_NE(0UL, ns[i]); - } + EXPECT_NE(0UL, ns[log_delay]); // failure to parse alloc_statistics(&buf, &len);