Disable info messages by default for malloc debug.
Add a new option verbose for malloc debug that is not enabled by default.
This disables all of the info log messages. It turns out these log
messages can add a measurable amount of time and can change the boot up.
Bug: 129239269
Test: Adjusted unit tests pass.
Test: Verified no messages unless verbose option used.
Change-Id: I805cb7c8ecb44de88119574e59d784877cacc383
diff --git a/libc/bionic/malloc_common_dynamic.cpp b/libc/bionic/malloc_common_dynamic.cpp
index e12c247..3ccaed6 100644
--- a/libc/bionic/malloc_common_dynamic.cpp
+++ b/libc/bionic/malloc_common_dynamic.cpp
@@ -307,8 +307,6 @@
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 @@
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;
}
diff --git a/libc/malloc_debug/Config.cpp b/libc/malloc_debug/Config.cpp
index dd20b5c..dbd3eac 100644
--- a/libc/malloc_debug/Config.cpp
+++ b/libc/malloc_debug/Config.cpp
@@ -135,6 +135,9 @@
{
"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,
diff --git a/libc/malloc_debug/Config.h b/libc/malloc_debug/Config.h
index 011dc77..1b5c748 100644
--- a/libc/malloc_debug/Config.h
+++ b/libc/malloc_debug/Config.h
@@ -45,6 +45,7 @@
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.
diff --git a/libc/malloc_debug/PointerData.cpp b/libc/malloc_debug/PointerData.cpp
index 6c7d8fa..617d128 100644
--- a/libc/malloc_debug/PointerData.cpp
+++ b/libc/malloc_debug/PointerData.cpp
@@ -105,8 +105,10 @@
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(),
- config.backtrace_signal(), getpid());
+ if (config.options() & VERBOSE) {
+ info_log("%s: Run: 'kill -%d %d' to enable backtracing.", getprogname(),
+ config.backtrace_signal(), getpid());
+ }
}
if (config.options() & BACKTRACE) {
@@ -117,8 +119,10 @@
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(),
- config.backtrace_dump_signal(), getpid());
+ if (config.options() & VERBOSE) {
+ info_log("%s: Run: 'kill -%d %d' to dump the backtrace.", getprogname(),
+ config.backtrace_dump_signal(), getpid());
+ }
}
backtrace_dump_ = false;
diff --git a/libc/malloc_debug/README.md b/libc/malloc_debug/README.md
index 93b9b1e..bebc1c1 100644
--- a/libc/malloc_debug/README.md
+++ b/libc/malloc_debug/README.md
@@ -401,6 +401,21 @@
**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.
diff --git a/libc/malloc_debug/RecordData.cpp b/libc/malloc_debug/RecordData.cpp
index aea2513..5c550c0 100644
--- a/libc/malloc_debug/RecordData.cpp
+++ b/libc/malloc_debug/RecordData.cpp
@@ -181,8 +181,10 @@
}
pthread_setspecific(key_, nullptr);
- info_log("%s: Run: 'kill -%d %d' to dump the allocation records.", getprogname(),
- config.record_allocs_signal(), getpid());
+ if (config.options() & VERBOSE) {
+ 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_];
diff --git a/libc/malloc_debug/malloc_debug.cpp b/libc/malloc_debug/malloc_debug.cpp
index 093bdee..1145796 100644
--- a/libc/malloc_debug/malloc_debug.cpp
+++ b/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 @@
// of different error cases.
backtrace_startup();
+ if (g_debug->config().options() & VERBOSE) {
+ info_log("%s: malloc debug enabled", getprogname());
+ }
+
return true;
}
diff --git a/libc/malloc_debug/tests/malloc_debug_config_tests.cpp b/libc/malloc_debug/tests/malloc_debug_config_tests.cpp
index fb54ee5..42d1415 100644
--- a/libc/malloc_debug/tests/malloc_debug_config_tests.cpp
+++ b/libc/malloc_debug/tests/malloc_debug_config_tests.cpp
@@ -743,3 +743,21 @@
"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());
+}
diff --git a/libc/malloc_debug/tests/malloc_debug_system_tests.cpp b/libc/malloc_debug/tests/malloc_debug_system_tests.cpp
index 4fcd04c..71e8ebf 100644
--- a/libc/malloc_debug/tests/malloc_debug_system_tests.cpp
+++ b/libc/malloc_debug/tests/malloc_debug_system_tests.cpp
@@ -195,7 +195,7 @@
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 @@
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(
diff --git a/libc/malloc_debug/tests/malloc_debug_unit_tests.cpp b/libc/malloc_debug/tests/malloc_debug_unit_tests.cpp
index 66955db..f611f3d 100644
--- a/libc/malloc_debug/tests/malloc_debug_unit_tests.cpp
+++ b/libc/malloc_debug/tests/malloc_debug_unit_tests.cpp
@@ -154,7 +154,7 @@
return diff;
}
-void VerifyAllocCalls(bool backtrace_enabled) {
+void VerifyAllocCalls(bool all_options) {
size_t alloc_size = 1024;
// Verify debug_malloc.
@@ -209,21 +209,28 @@
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 @@
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, 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 @@
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 @@
ASSERT_EQ(0U, backtrace_size);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, get_malloc_leak_info_single) {
@@ -1143,10 +1186,7 @@
debug_free(pointer);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, get_malloc_leak_info_multi) {
@@ -1226,10 +1266,7 @@
debug_free(pointers[2]);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, get_malloc_backtrace_with_header) {
@@ -1261,10 +1298,7 @@
initialized = false;
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
static std::string SanitizeHeapData(const std::string& data) {
@@ -1375,9 +1409,6 @@
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 @@
debug_free_malloc_leak_info(info);
ASSERT_STREQ("", getFakeLogBuf().c_str());
- 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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, backtrace_same_stack) {
@@ -1712,10 +1737,7 @@
debug_free(pointers[3]);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, backtrace_same_stack_zygote) {
@@ -1774,10 +1796,7 @@
debug_free(pointers[3]);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, backtrace_same_stack_mix_zygote) {
@@ -1844,10 +1863,7 @@
debug_free(pointers[3]);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, backtrace_frame_data_nullptr_same_size) {
@@ -1891,10 +1907,7 @@
debug_free(pointers[3]);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, overflow) {
@@ -2022,10 +2035,7 @@
debug_free(pointer);
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
}
TEST_F(MallocDebugTest, max_size) {
@@ -2193,10 +2203,7 @@
ASSERT_STREQ(expected.c_str(), actual.c_str());
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
debug_free(pointer);
}
@@ -2251,10 +2258,7 @@
ASSERT_STREQ(expected.c_str(), actual.c_str());
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
debug_free(pointer);
}
@@ -2293,10 +2297,7 @@
ASSERT_STREQ(expected.c_str(), actual.c_str());
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());
- ASSERT_STREQ(expected_log.c_str(), getFakeLogPrint().c_str());
+ ASSERT_STREQ("", getFakeLogPrint().c_str());
debug_free(pointer);
}
@@ -2348,9 +2349,6 @@
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());
