Merge lp:~vanvugt/mir/fix-1343074-0.5 into lp:mir/0.5

[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.

Backported from development-branch.

[PS Jenkins bot (ps-jenkins)]

FAILED: Continuous integration, rev:1782
http://jenkins.qa.ubuntu.com/job/mir-0.5-ci/6/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-amd64-ci/6
        deb: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-amd64-ci/6/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-ci/6
        deb: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-ci/6/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-utopic-i386-build/1007
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-utopic-amd64-build/1013
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-utopic-touch/1002/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3394
        deb: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3394/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/2129/console
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/10115

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-0.5-ci/6/rebuild

review: Needs Fixing (continuous-integration)

[Cemil Azizoglu (cemil-azizoglu)]

Same failure in jenkins.

lgtm, nevertheless.

review: Approve

[Daniel van Vugt (vanvugt)]

The failure seems to be a general infrastructure problem. Not this branch.

Please wait and don't top approve this while we land an emergency fix today...
https://code.launchpad.net/~mir-team/mir/0.5/+merge/227627

[PS Jenkins bot (ps-jenkins)]

FAILED: Continuous integration, rev:1783
http://jenkins.qa.ubuntu.com/job/mir-0.5-ci/11/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-amd64-ci/11
        deb: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-amd64-ci/11/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-ci/11
        deb: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-ci/11/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-utopic-i386-build/1032
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-utopic-amd64-build/1038
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-utopic-touch/1024/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3488
        deb: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3488/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/2147/console
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/10194

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-0.5-ci/11/rebuild

review: Needs Fixing (continuous-integration)

[Kevin DuBois (kdub)]

review: Approve

[PS Jenkins bot (ps-jenkins)]

FAILED: Continuous integration, rev:1784
http://jenkins.qa.ubuntu.com/job/mir-0.5-ci/16/
Executed test runs:
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-amd64-ci/16
        deb: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-amd64-ci/16/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-ci/16
        deb: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-ci/16/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-utopic-i386-build/1061
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-utopic-amd64-build/1067
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-utopic-touch/1052/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3643
        deb: http://jenkins.qa.ubuntu.com/job/generic-mediumtests-builder-utopic-armhf/3643/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/2168/console
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/10322

Click here to trigger a rebuild:
http://s-jenkins.ubuntu-ci:8080/job/mir-0.5-ci/16/rebuild

review: Needs Fixing (continuous-integration)

[Andreas Pokorny (andreas-pokorny)]

review: Approve

[PS Jenkins bot (ps-jenkins)]

FAILED: Autolanding.
More details in the following jenkins job:
http://jenkins.qa.ubuntu.com/job/mir-0.5-autolanding/3/
Executed test runs:
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-amd64-autolanding/3/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-autolanding/3
        deb: http://jenkins.qa.ubuntu.com/job/mir-0.5-utopic-armhf-autolanding/3/artifact/work/output/*zip*/output.zip
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-android-utopic-i386-build/1102
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-clang-utopic-amd64-build/1108
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-utopic-touch/1093/console
    SUCCESS: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-utopic-armhf/28
        deb: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-builder-utopic-armhf/28/artifact/work/output/*zip*/output.zip
    FAILURE: http://jenkins.qa.ubuntu.com/job/mir-mediumtests-runner-mako/2213/console
    SUCCESS: http://s-jenkins.ubuntu-ci:8080/job/touch-flash-device/10503

review: Needs Fixing (continuous-integration)

[Cemil Azizoglu (cemil-azizoglu)]

Since 0.5 will not be the RTM, no point in committing this. We should use devel until 0.6 is branched out.

review: Needs Resubmitting

Unmerged revisions

1784. By Daniel van Vugt on 2014-07-24

Merge latest 0.5 branch

1783. By Daniel van Vugt on 2014-07-22

Merge latest lp:mir/0.5

1782. By Daniel van Vugt on 2014-07-21

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.

1781. By Cemil Azizoglu on 2014-07-16

Manual-merge with lp:~mir-team/mir/enable-late-release-0.5-backport.

1780. By Daniel van Vugt on 2014-07-16

Mention another bug fix we forgot - LP: #1189775

1779. By Daniel van Vugt on 2014-07-16

changelog: Document enhancements for 0.5.0

1778. By Daniel van Vugt on 2014-07-16

Restore changelog entry for 0.4.1. If we do retain a separate packaging
branch then it will have to be present.

1777. By Daniel van Vugt on 2014-07-16

Revert unidentified changes introduced in r1774. If anyone finds they need
them we can add them back in, with some explanation.

1776. By kevin gunn on 2014-07-15

update changelog

1775. By Cemil Azizoglu on 2014-07-15

Now change it to 0.5.0 to resolve the conflict.

=== 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-24 03:11:52 +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-24 03:11:52 +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-16 04:59:13 +0000
+++ CMakeLists.txt	2014-07-24 03:11:52 +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-24 03:11:52 +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-24 03:11:52 +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);
+}