Merge "Disable info messages by default for malloc debug." am: e6fd53b751

am: f2905f4ce3

Change-Id: Iddb4900532ef816f8bf061a142cd0ec74b45a850

libc/bionic/malloc_common_dynamic.cpp

@@ -307,8 +307,6 @@ bool FinishInstallHooks(libc_globals* globals, const char* options, const char*
     atomic_store(&globals->current_dispatch_table, &globals->malloc_dispatch_table);
   }
 
-  info_log("%s: malloc %s enabled", getprogname(), prefix);
-
   // Use atexit to trigger the cleanup function. This avoids a problem
   // where another atexit function is used to cleanup allocated memory,
   // but the finalize function was already called. This particular error
@@ -316,7 +314,7 @@ bool FinishInstallHooks(libc_globals* globals, const char* options, const char*
   int ret_value = __cxa_atexit(MallocFiniImpl, nullptr, nullptr);
   if (ret_value != 0) {
     // We don't consider this a fatal error.
-    info_log("failed to set atexit cleanup function: %d", ret_value);
+    warning_log("failed to set atexit cleanup function: %d", ret_value);
   }
   return true;
 }

libc/malloc_debug/Config.cpp

@@ -135,6 +135,9 @@ const std::unordered_map<std::string, Config::OptionInfo> Config::kOptions = {
     {
         "abort_on_error", {ABORT_ON_ERROR, &Config::VerifyValueEmpty},
     },
+    {
+        "verbose", {VERBOSE, &Config::VerifyValueEmpty},
+    },
 };
 
 bool Config::ParseValue(const std::string& option, const std::string& value, size_t min_value,

libc/malloc_debug/Config.h

@@ -45,6 +45,7 @@ constexpr uint64_t LEAK_TRACK = 0x100;
 constexpr uint64_t RECORD_ALLOCS = 0x200;
 constexpr uint64_t BACKTRACE_FULL = 0x400;
 constexpr uint64_t ABORT_ON_ERROR = 0x800;
+constexpr uint64_t VERBOSE = 0x1000;
 
 // In order to guarantee posix compliance, set the minimum alignment
 // to 8 bytes for 32 bit systems and 16 bytes for 64 bit systems.

libc/malloc_debug/PointerData.cpp

@@ -105,8 +105,10 @@ bool PointerData::Initialize(const Config& config) NO_THREAD_SAFETY_ANALYSIS {
       error_log("Unable to set up backtrace signal enable function: %s", strerror(errno));
       return false;
     }
-    info_log("%s: Run: 'kill -%d %d' to enable backtracing.", getprogname(),
+    if (config.options() & VERBOSE) {
-             config.backtrace_signal(), getpid());
+      info_log("%s: Run: 'kill -%d %d' to enable backtracing.", getprogname(),
+               config.backtrace_signal(), getpid());
+    }
   }
 
   if (config.options() & BACKTRACE) {
@@ -117,8 +119,10 @@ bool PointerData::Initialize(const Config& config) NO_THREAD_SAFETY_ANALYSIS {
       error_log("Unable to set up backtrace dump signal function: %s", strerror(errno));
       return false;
     }
-    info_log("%s: Run: 'kill -%d %d' to dump the backtrace.", getprogname(),
+    if (config.options() & VERBOSE) {
-             config.backtrace_dump_signal(), getpid());
+      info_log("%s: Run: 'kill -%d %d' to dump the backtrace.", getprogname(),
+               config.backtrace_dump_signal(), getpid());
+    }
   }
 
   backtrace_dump_ = false;

libc/malloc_debug/README.md

@@ -401,6 +401,21 @@ log message.
 **NOTE**: If leak\_track is enabled, no abort occurs if leaks have been
 detected when the process is exiting.
 
+### verbose
+As of Android Q, all info messages will be turned off by default. For example,
+in Android P and older, enabling malloc debug would result in this message
+in the log:
+
+    08-16 15:54:16.060 26947 26947 I libc    : /system/bin/app_process64: malloc debug enabled
+
+In android Q, this message will not be displayed because these info messages
+slow down process start up. However, if you want to re-enable these messages,
+add the verbose option. All of the "Run XXX" messages are also silenced unless
+the verbose option is specified. This is an example of the type
+of messages that are no longer displayed:
+
+    09-10 01:03:50.070   557   557 I malloc_debug: /system/bin/audioserver: Run: 'kill -47 557' to dump the backtrace.
+
 Additional Errors
 -----------------
 There are a few other error messages that might appear in the log.

libc/malloc_debug/RecordData.cpp

@@ -181,8 +181,10 @@ bool RecordData::Initialize(const Config& config) {
   }
   pthread_setspecific(key_, nullptr);
 
-  info_log("%s: Run: 'kill -%d %d' to dump the allocation records.", getprogname(),
+  if (config.options() & VERBOSE) {
-           config.record_allocs_signal(), getpid());
+    info_log("%s: Run: 'kill -%d %d' to dump the allocation records.", getprogname(),
+             config.record_allocs_signal(), getpid());
+  }
 
   num_entries_ = config.record_allocs_num_entries();
   entries_ = new const RecordEntry*[num_entries_];

libc/malloc_debug/malloc_debug.cpp

@@ -30,6 +30,7 @@
 #include <inttypes.h>
 #include <malloc.h>
 #include <stdio.h>
+#include <stdlib.h>
 #include <string.h>
 #include <sys/cdefs.h>
 #include <sys/param.h>
@@ -252,6 +253,10 @@ bool debug_initialize(const MallocDispatch* malloc_dispatch, int* malloc_zygote_
   // of different error cases.
   backtrace_startup();
 
+  if (g_debug->config().options() & VERBOSE) {
+    info_log("%s: malloc debug enabled", getprogname());
+  }
+
   return true;
 }
 

libc/malloc_debug/tests/malloc_debug_config_tests.cpp

@@ -743,3 +743,21 @@ TEST_F(MallocDebugConfigTest, trigger_abort_fail) {
       "which does not take a value\n");
   ASSERT_STREQ((log_msg + usage_string).c_str(), getFakeLogPrint().c_str());
 }
+
+TEST_F(MallocDebugConfigTest, verbose) {
+  ASSERT_TRUE(InitConfig("verbose")) << getFakeLogPrint();
+  ASSERT_EQ(VERBOSE, config->options());
+
+  ASSERT_STREQ("", getFakeLogBuf().c_str());
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
+}
+
+TEST_F(MallocDebugConfigTest, trigger_verbose_fail) {
+  ASSERT_FALSE(InitConfig("verbose=200")) << getFakeLogPrint();
+
+  ASSERT_STREQ("", getFakeLogBuf().c_str());
+  std::string log_msg(
+      "6 malloc_debug malloc_testing: value set for option 'verbose' "
+      "which does not take a value\n");
+  ASSERT_STREQ((log_msg + usage_string).c_str(), getFakeLogPrint().c_str());
+}

libc/malloc_debug/tests/malloc_debug_system_tests.cpp

@@ -195,7 +195,7 @@ TEST(MallocTests, DISABLED_smoke) {}
 
 TEST(MallocDebugSystemTest, smoke) {
   pid_t pid;
-  ASSERT_NO_FATAL_FAILURE(Exec("MallocTests.DISABLED_smoke", "backtrace", &pid));
+  ASSERT_NO_FATAL_FAILURE(Exec("MallocTests.DISABLED_smoke", "verbose backtrace", &pid));
 
   ASSERT_NO_FATAL_FAILURE(FindStrings(pid, std::vector<const char*>{"malloc debug enabled"}));
 }
@@ -399,7 +399,7 @@ static void VerifyLeak(const char* test_prefix) {
     pid_t pid;
     SCOPED_TRACE(testing::Message() << functions[i].name << " expected size " << functions[i].size);
     std::string test = std::string("MallocTests.DISABLED_") + test_prefix + functions[i].name;
-    EXPECT_NO_FATAL_FAILURE(Exec(test.c_str(), "backtrace leak_track", &pid));
+    EXPECT_NO_FATAL_FAILURE(Exec(test.c_str(), "verbose backtrace leak_track", &pid));
 
     std::string expected_leak = android::base::StringPrintf("leaked block of size %zu at", functions[i].size);
     EXPECT_NO_FATAL_FAILURE(FindStrings(

libc/malloc_debug/tests/malloc_debug_unit_tests.cpp

@@ -154,7 +154,7 @@ std::string ShowDiffs(uint8_t* a, uint8_t* b, size_t size) {
   return diff;
 }
 
-void VerifyAllocCalls(bool backtrace_enabled) {
+void VerifyAllocCalls(bool all_options) {
   size_t alloc_size = 1024;
 
   // Verify debug_malloc.
@@ -209,21 +209,28 @@ void VerifyAllocCalls(bool backtrace_enabled) {
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   std::string expected_log;
-  if (backtrace_enabled) {
+  if (all_options) {
+    expected_log += android::base::StringPrintf(
+        "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to enable backtracing.\n",
+        SIGRTMAX - 19, getpid());
     expected_log += android::base::StringPrintf(
         "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
         SIGRTMAX - 17, getpid());
+    expected_log += android::base::StringPrintf(
+        "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the allocation records.\n",
+        SIGRTMAX - 18, getpid());
   }
+  expected_log += "4 malloc_debug malloc_testing: malloc debug enabled\n";
   ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, fill_generic) {
-  Init("fill");
+  Init("verbose fill");
   VerifyAllocCalls(false);
 }
 
 TEST_F(MallocDebugTest, fill_on_alloc_generic) {
-  Init("fill_on_alloc");
+  Init("verbose fill_on_alloc");
   VerifyAllocCalls(false);
 }
 
@@ -241,6 +248,46 @@ TEST_F(MallocDebugTest, fill_on_alloc_partial) {
   ASSERT_STREQ("", getFakeLogPrint().c_str());
 }
 
+TEST_F(MallocDebugTest, verbose_only) {
+  Init("verbose");
+
+  ASSERT_STREQ("", getFakeLogBuf().c_str());
+  ASSERT_STREQ("4 malloc_debug malloc_testing: malloc debug enabled\n", getFakeLogPrint().c_str());
+}
+
+TEST_F(MallocDebugTest, verbose_backtrace_enable_on_signal) {
+  Init("verbose backtrace_enable_on_signal");
+
+  std::string expected_log = android::base::StringPrintf(
+      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to enable backtracing.\n",
+      SIGRTMAX - 19, getpid());
+  expected_log += android::base::StringPrintf(
+      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
+      SIGRTMAX - 17, getpid());
+  expected_log += "4 malloc_debug malloc_testing: malloc debug enabled\n";
+  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+}
+
+TEST_F(MallocDebugTest, verbose_backtrace) {
+  Init("verbose backtrace");
+
+  std::string expected_log = android::base::StringPrintf(
+      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
+      SIGRTMAX - 17, getpid());
+  expected_log += "4 malloc_debug malloc_testing: malloc debug enabled\n";
+  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+}
+
+TEST_F(MallocDebugTest, verbose_record_allocs) {
+  Init("verbose record_allocs");
+
+  std::string expected_log = android::base::StringPrintf(
+      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the allocation records.\n",
+      SIGRTMAX - 18, getpid());
+  expected_log += "4 malloc_debug malloc_testing: malloc debug enabled\n";
+  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+}
+
 TEST_F(MallocDebugTest, fill_on_free) {
   Init("fill_on_free free_track free_track_backtrace_num_frames=0");
 
@@ -302,7 +349,9 @@ TEST_F(MallocDebugTest, free_track_partial) {
 }
 
 TEST_F(MallocDebugTest, all_options) {
-  Init("guard backtrace fill expand_alloc free_track leak_track");
+  Init(
+      "guard backtrace backtrace_enable_on_signal fill expand_alloc free_track leak_track "
+      "record_allocs verify_pointers abort_on_error verbose");
   VerifyAllocCalls(true);
 }
 
@@ -667,9 +716,6 @@ TEST_F(MallocDebugTest, leak_track_no_frees_with_backtrace) {
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   std::string expected_log = android::base::StringPrintf(
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  expected_log += android::base::StringPrintf(
       "6 malloc_debug +++ malloc_testing leaked block of size 1024 at %p (leak 1 of 3)\n",
       pointer3);
   expected_log += "6 malloc_debug Backtrace at time of allocation:\n";
@@ -1096,10 +1142,7 @@ TEST_F(MallocDebugTest, get_malloc_leak_info_empty) {
   ASSERT_EQ(0U, backtrace_size);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, get_malloc_leak_info_single) {
@@ -1143,10 +1186,7 @@ TEST_F(MallocDebugTest, get_malloc_leak_info_single) {
   debug_free(pointer);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, get_malloc_leak_info_multi) {
@@ -1226,10 +1266,7 @@ TEST_F(MallocDebugTest, get_malloc_leak_info_multi) {
   debug_free(pointers[2]);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, get_malloc_backtrace_with_header) {
@@ -1261,10 +1298,7 @@ TEST_F(MallocDebugTest, get_malloc_backtrace_with_header) {
   initialized = false;
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 static std::string SanitizeHeapData(const std::string& data) {
@@ -1375,9 +1409,6 @@ END
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   std::string expected_log = android::base::StringPrintf(
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  expected_log += android::base::StringPrintf(
       "6 malloc_debug Dumping to file: /data/local/tmp/backtrace_heap.%d.txt\n\n", getpid());
   ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
@@ -1649,13 +1680,7 @@ TEST_F(MallocDebugTest, backtrace_enable_on_signal) {
   debug_free_malloc_leak_info(info);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to enable backtracing.\n",
-      SIGRTMAX - 19, getpid());
-  expected_log += android::base::StringPrintf(
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, backtrace_same_stack) {
@@ -1712,10 +1737,7 @@ TEST_F(MallocDebugTest, backtrace_same_stack) {
   debug_free(pointers[3]);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, backtrace_same_stack_zygote) {
@@ -1774,10 +1796,7 @@ TEST_F(MallocDebugTest, backtrace_same_stack_zygote) {
   debug_free(pointers[3]);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, backtrace_same_stack_mix_zygote) {
@@ -1844,10 +1863,7 @@ TEST_F(MallocDebugTest, backtrace_same_stack_mix_zygote) {
   debug_free(pointers[3]);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, backtrace_frame_data_nullptr_same_size) {
@@ -1891,10 +1907,7 @@ TEST_F(MallocDebugTest, backtrace_frame_data_nullptr_same_size) {
   debug_free(pointers[3]);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, overflow) {
@@ -2022,10 +2035,7 @@ TEST_F(MallocDebugTest, zygote_set) {
   debug_free(pointer);
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the backtrace.\n",
-      SIGRTMAX - 17, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 }
 
 TEST_F(MallocDebugTest, max_size) {
@@ -2193,10 +2203,7 @@ void VerifyRecordAllocs() {
   ASSERT_STREQ(expected.c_str(), actual.c_str());
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the allocation records.\n",
-      SIGRTMAX - 18, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 
   debug_free(pointer);
 }
@@ -2251,10 +2258,7 @@ TEST_F(MallocDebugTest, record_allocs_max) {
   ASSERT_STREQ(expected.c_str(), actual.c_str());
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the allocation records.\n",
-      SIGRTMAX - 18, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 
   debug_free(pointer);
 }
@@ -2293,10 +2297,7 @@ TEST_F(MallocDebugTest, record_allocs_thread_done) {
   ASSERT_STREQ(expected.c_str(), actual.c_str());
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
-  std::string expected_log = android::base::StringPrintf(
+  ASSERT_STREQ("", getFakeLogPrint().c_str());
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the allocation records.\n",
-      SIGRTMAX - 18, getpid());
-  ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
 
   debug_free(pointer);
 }
@@ -2348,9 +2349,6 @@ TEST_F(MallocDebugTest, record_allocs_file_name_fail) {
 
   ASSERT_STREQ("", getFakeLogBuf().c_str());
   std::string expected_log = android::base::StringPrintf(
-      "4 malloc_debug malloc_testing: Run: 'kill -%d %d' to dump the allocation records.\n",
-      SIGRTMAX - 18, getpid());
-  expected_log += android::base::StringPrintf(
       "6 malloc_debug Cannot create record alloc file %s: Too many symbolic links encountered\n",
       RECORD_ALLOCS_FILE);
   ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());