diff --git a/libc/bionic/malloc_common_dynamic.cpp b/libc/bionic/malloc_common_dynamic.cpp index e12c24712..3ccaed673 100644 --- a/libc/bionic/malloc_common_dynamic.cpp +++ b/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; } diff --git a/libc/malloc_debug/Config.cpp b/libc/malloc_debug/Config.cpp index dd20b5cd5..dbd3eac4a 100644 --- a/libc/malloc_debug/Config.cpp +++ b/libc/malloc_debug/Config.cpp @@ -135,6 +135,9 @@ const std::unordered_map 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, diff --git a/libc/malloc_debug/Config.h b/libc/malloc_debug/Config.h index 011dc77bd..1b5c748e9 100644 --- a/libc/malloc_debug/Config.h +++ b/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. diff --git a/libc/malloc_debug/PointerData.cpp b/libc/malloc_debug/PointerData.cpp index 6c7d8fa15..617d128c7 100644 --- a/libc/malloc_debug/PointerData.cpp +++ b/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(), - 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 @@ 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(), - 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 93b9b1ea1..bebc1c141 100644 --- a/libc/malloc_debug/README.md +++ b/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. diff --git a/libc/malloc_debug/RecordData.cpp b/libc/malloc_debug/RecordData.cpp index aea25133e..5c550c0f2 100644 --- a/libc/malloc_debug/RecordData.cpp +++ b/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(), - 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 093bdee8c..114579626 100644 --- a/libc/malloc_debug/malloc_debug.cpp +++ b/libc/malloc_debug/malloc_debug.cpp @@ -30,6 +30,7 @@ #include #include #include +#include #include #include #include @@ -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; } diff --git a/libc/malloc_debug/tests/malloc_debug_config_tests.cpp b/libc/malloc_debug/tests/malloc_debug_config_tests.cpp index fb54ee54f..42d1415ac 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 @@ 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()); +} diff --git a/libc/malloc_debug/tests/malloc_debug_system_tests.cpp b/libc/malloc_debug/tests/malloc_debug_system_tests.cpp index 4fcd04c81..71e8ebf73 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(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{"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( diff --git a/libc/malloc_debug/tests/malloc_debug_unit_tests.cpp b/libc/malloc_debug/tests/malloc_debug_unit_tests.cpp index 66955db59..f611f3da7 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 @@ 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( - "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 @@ TEST_F(MallocDebugTest, get_malloc_leak_info_single) { 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 @@ TEST_F(MallocDebugTest, get_malloc_leak_info_multi) { 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 @@ TEST_F(MallocDebugTest, get_malloc_backtrace_with_header) { 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 @@ 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( - "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 @@ TEST_F(MallocDebugTest, backtrace_same_stack) { 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 @@ TEST_F(MallocDebugTest, backtrace_same_stack_zygote) { 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 @@ TEST_F(MallocDebugTest, backtrace_same_stack_mix_zygote) { 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 @@ 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( - "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 @@ TEST_F(MallocDebugTest, zygote_set) { 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 @@ void VerifyRecordAllocs() { 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 @@ 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( - "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 @@ 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( - "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 @@ 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());