Merge lp:~vanvugt/mir/fastlog into lp:mir

[Daniel van Vugt]

Stop Android logging from consuming significant CPU (on every input event).
(LP: #1343074)

Two things needed fixing:
  1. Verbose logging (ALOGV) is meant to be disabled (optimized out) unless
     debugging, but it wasn't ever being removed. This means expensive calls
     to ALOGV remained, for example in EventHub.cpp on every input event.
  2. Our own Mir version of __android_log_print was extremely inefficient,
     formatting log messages unconditionally even when they did not meet the
     reporting threshold and were never used.

[PS Jenkins bot (ps-jenkins)]

PASSED: Continuous integration, rev:1778
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-ci/2177/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-utopic-i386-build/976
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-utopic-amd64-build/982
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-utopic-touch/971
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-utopic-amd64-ci/698
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-utopic-amd64-ci/698/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-utopic-armhf-ci/696
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-utopic-armhf-ci/696/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3262
        deb: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3262/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/2101
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/9987

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-team-mir-development-branch-ci/2177/rebuild

review: Approve (continuous-integration)

[Alan Griffiths (alan-griffiths)]

OK

review: Approve

[Kevin DuBois (kdub)]

lgtm

review: Approve

[Daniel d'Andrada (dandrader)]

lgtm

review: Approve

[PS Jenkins bot (ps-jenkins)]

FAILED: Autolanding.
More details in the following jenkins job:
http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-autolanding/890/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-utopic-i386-build/996
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-utopic-amd64-build/1002
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-utopic-touch/991
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-utopic-amd64-autolanding/274/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-utopic-armhf-autolanding/274
        deb: http://jenkins.qa.ubuntu.com/job/mir-team-mir-development-branch-utopic-armhf-autolanding/274/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3354
        deb: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3354/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/2120
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/10075

review: Needs Fixing (continuous-integration)

[PS Jenkins bot (ps-jenkins)]

review: Approve (continuous-integration)

=== modified file '3rd_party/android-deps/std/Log.h'
--- 3rd_party/android-deps/std/Log.h	2013-05-03 22:53:02 +0000
+++ 3rd_party/android-deps/std/Log.h	2014-07-17 07:43:34 +0000
@@ -61,8 +61,12 @@
  * Simplified macro to send a verbose log message using the current LOG_TAG.
  */
 #ifndef ALOGV
+#if LOG_NDEBUG // Per Android, optimize out verbose messages when LOG_NDEBUG=1
+#define ALOGV(...) ((void)0)
+#else
 #define ALOGV(...) ((void)ALOG(LOG_VERBOSE, LOG_TAG, __VA_ARGS__))
 #endif
+#endif
 
 /*
  * Simplified macro to send a debug log message using the current LOG_TAG.

=== modified file '3rd_party/android-input/android/frameworks/base/services/input/MirLog.cpp'
--- 3rd_party/android-input/android/frameworks/base/services/input/MirLog.cpp	2013-09-24 18:04:03 +0000
+++ 3rd_party/android-input/android/frameworks/base/services/input/MirLog.cpp	2014-07-17 07:43:34 +0000
@@ -154,11 +154,7 @@
 
 extern "C" int __android_log_print(int prio, const char *tag, const char *fmt, ...)
 {
-    char buffer[1024] = {'0'};
-    va_list ap;
-    va_start(ap, fmt);
-    int result = vsnprintf(buffer, sizeof buffer - 1, fmt, ap);
-    va_end(ap);
+    int result = 0;
 
     if (gLogState.globalMinPriority == ANDROID_LOG_UNKNOWN) {
         configureInitialState(&gLogState);
@@ -177,9 +173,16 @@
     }
 
     if (prio >= minPrio) {
-        char taggedBuffer[1024];
-        sprintf(taggedBuffer, "[%s]%s", tag, buffer);
-        mir::write_to_log(prio, taggedBuffer);
+        char buffer[1024];
+        int max = sizeof buffer - 1;
+        int tagend = snprintf(buffer, max, "[%s]", tag);
+
+        va_list ap;
+        va_start(ap, fmt);
+        result = vsnprintf(buffer+tagend, max - tagend, fmt, ap);
+        va_end(ap);
+
+        mir::write_to_log(prio, buffer);
     } else {
         // filter out log message
     }

=== modified file 'CMakeLists.txt'
--- CMakeLists.txt	2014-07-09 10:48:47 +0000
+++ CMakeLists.txt	2014-07-17 07:43:34 +0000
@@ -88,6 +88,10 @@
   set(CMAKE_EXE_LINKER_FLAGS "${CMAKE_EXE_LINKER_FLAGS} -Wl,--no-undefined")
 endif()
 
+# Define LOG_NDEBUG=1 to ensure Android ALOGV calls are not compiled in to
+# consume CPU time...
+add_definitions(-DLOG_NDEBUG=1)
+
 enable_testing()
 
 include_directories(include/shared)

=== modified file 'tests/acceptance-tests/CMakeLists.txt'
--- tests/acceptance-tests/CMakeLists.txt	2014-07-11 14:04:15 +0000
+++ tests/acceptance-tests/CMakeLists.txt	2014-07-17 07:43:34 +0000
@@ -39,6 +39,7 @@
   test_large_messages.cpp
   test_client_surface_visibility.cpp
   test_client_with_custom_display_config_deadlock.cpp
+  test_macros.cpp
   ${GENERATED_PROTOBUF_SRCS}
   ${GENERATED_PROTOBUF_HDRS}
 )

=== added file 'tests/acceptance-tests/test_macros.cpp'
--- tests/acceptance-tests/test_macros.cpp	1970-01-01 00:00:00 +0000
+++ tests/acceptance-tests/test_macros.cpp	2014-07-17 07:43:34 +0000
@@ -0,0 +1,28 @@
+/*
+ * Copyright © 2014 Canonical Ltd.
+ *
+ * This program is free software: you can redistribute it and/or modify
+ * it under the terms of the GNU General Public License version 3 as
+ * published by the Free Software Foundation.
+ *
+ * This program is distributed in the hope that it will be useful,
+ * but WITHOUT ANY WARRANTY; without even the implied warranty of
+ * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+ * GNU General Public License for more details.
+ *
+ * You should have received a copy of the GNU General Public License
+ * along with this program.  If not, see <http://www.gnu.org/licenses/>.
+ *
+ * Authored by: Daniel van Vugt <[e-mail]>
+ */
+
+#include "cutils/log.h"  // Get the final value of LOG_NDEBUG
+#include <gtest/gtest.h>
+
+TEST(Macros, android_verbose_logging_is_disabled)
+{
+    // Ensure verbose logging (ALOGV) is removed. It requires significant
+    // CPU time to constantly format some verbose messages...
+    // This is a regression test for performance bug LP: #1343074.
+    EXPECT_EQ(1, LOG_NDEBUG);
+}