From 638c8cdc3234c4119760439e3a868c61785dbffb Mon Sep 17 00:00:00 2001 From: Gerald Squelart Date: Thu, 24 Oct 2019 05:55:02 +0000 Subject: [PATCH] Bug 1540340 - Prevent logging when mainthredio is enabled - r=gregtatum Logging could be intercepted by the I/O interposer, which takes the lock, this could deadlock if the mutex had already been taken in the same thread (e.g., by a "locked" profiler function that wants to log something). Now, functions that hold the lock must use `LOG_LOCKED(lock, ...)`, which will skip logging when the I/O interposer is running. In DEBUG builds, `LOG()` checks that the lock is not owned, to find possible misuses. `LOG()`s outside of platform.cpp were changed to `NS_WARNING`s, because they could not access `gPSMutex` that's defined in platform.cpp; and they're really warnings anyway. Some interposer pauses/resumes have been relocated to more appropriate spots: - Not needed around `locked_profiler_stream_json_for_this_process` anymore, thanks to `LOG_LOCKED` inside. - Definitely needed around `std::ofstream` operations in `locked_profiler_save_profile_to_file`. Differential Revision: https://phabricator.services.mozilla.com/D49896 --HG-- extra : moz-landing-system : lando --- tools/profiler/core/EHABIStackWalk.cpp | 6 +- tools/profiler/core/platform.cpp | 80 +++++++++++-------- tools/profiler/core/platform.h | 40 ++++++++-- tools/profiler/core/shared-libraries-linux.cc | 10 ++- 4 files changed, 90 insertions(+), 46 deletions(-) diff --git a/tools/profiler/core/EHABIStackWalk.cpp b/tools/profiler/core/EHABIStackWalk.cpp index 3eab4c0fb312..6a4fab1a14d5 100644 --- a/tools/profiler/core/EHABIStackWalk.cpp +++ b/tools/profiler/core/EHABIStackWalk.cpp @@ -330,8 +330,8 @@ bool EHInterp::unwind() { checkStack(); while (!mFailed) { uint8_t insn = next(); -#if DEBUG_EHABI_UNWIND - LOG("unwind insn = %02x", (unsigned)insn); +#ifdef DEBUG_EHABI_UNWIND + NS_WARNING("unwind insn = %02x", (unsigned)insn); #endif // Try to put the common cases first. @@ -457,7 +457,7 @@ bool EHInterp::unwind() { // unhandled instruction #ifdef DEBUG_EHABI_UNWIND - LOG("Unhandled EHABI instruction 0x%02x", insn); + NS_WARNING("Unhandled EHABI instruction 0x%02x", insn); #endif mFailed = true; } diff --git a/tools/profiler/core/platform.cpp b/tools/profiler/core/platform.cpp index 7e271229964a..22fb91d83bae 100644 --- a/tools/profiler/core/platform.cpp +++ b/tools/profiler/core/platform.cpp @@ -959,6 +959,8 @@ class ActivePS { } } + PS_GET(ProfilerIOInterposeObserver*, InterposeObserver) + PS_GET_AND_SET(bool, IsPaused) #if defined(GP_OS_linux) @@ -2308,7 +2310,7 @@ profiler_code_address_service_for_presymbolication() { static void locked_profiler_stream_json_for_this_process( PSLockRef aLock, SpliceableJSONWriter& aWriter, double aSinceTime, bool aIsShuttingDown, ProfilerCodeAddressService* aService) { - LOG("locked_profiler_stream_json_for_this_process"); + LOG_LOCKED(aLock, "locked_profiler_stream_json_for_this_process"); MOZ_RELEASE_ASSERT(CorePS::Exists() && ActivePS::Exists(aLock)); @@ -2443,15 +2445,8 @@ bool profiler_stream_json_for_this_process( return false; } -#if !defined(RELEASE_OR_BETA) - ActivePS::PauseIOInterposer(lock); -#endif - locked_profiler_stream_json_for_this_process(lock, aWriter, aSinceTime, aIsShuttingDown, aService); -#if !defined(RELEASE_OR_BETA) - ActivePS::ResumeIOInterposer(lock); -#endif return true; } @@ -2841,7 +2836,9 @@ void SamplerThread::Run() { auto state = localBlocksRingBuffer.GetState(); if (NS_WARN_IF(state.mClearedBlockCount != previousState.mClearedBlockCount)) { - LOG("Stack sample too big for local storage, needed %u bytes", + LOG_LOCKED( + lock, + "Stack sample too big for local storage, needed %u bytes", unsigned(state.mRangeEnd.ConvertToU64() - previousState.mRangeEnd.ConvertToU64())); // There *must* be a CompactStack after a TimeBeforeCompactStack, @@ -2852,7 +2849,9 @@ void SamplerThread::Run() { } else if (state.mRangeEnd.ConvertToU64() - previousState.mRangeEnd.ConvertToU64() >= CorePS::CoreBlocksRingBuffer().BufferLength()->Value()) { - LOG("Stack sample too big for profiler storage, needed %u bytes", + LOG_LOCKED( + lock, + "Stack sample too big for profiler storage, needed %u bytes", unsigned(state.mRangeEnd.ConvertToU64() - previousState.mRangeEnd.ConvertToU64())); // There *must* be a CompactStack after a TimeBeforeCompactStack, @@ -3211,7 +3210,7 @@ void profiler_init(void* aStackTop) { return; } - LOG("- MOZ_PROFILER_STARTUP is set"); + LOG_LOCKED(lock, "- MOZ_PROFILER_STARTUP is set"); // Startup default capacity may be different. capacity = PROFILER_DEFAULT_STARTUP_ENTRIES; @@ -3227,10 +3226,12 @@ void profiler_init(void* aStackTop) { static_cast(capacityLong) <= static_cast(INT32_MAX)) { capacity = PowerOfTwo32(static_cast(capacityLong)); - LOG("- MOZ_PROFILER_STARTUP_ENTRIES = %u", unsigned(capacity.Value())); + LOG_LOCKED(lock, "- MOZ_PROFILER_STARTUP_ENTRIES = %u", + unsigned(capacity.Value())); } else { - LOG("- MOZ_PROFILER_STARTUP_ENTRIES not a valid integer: %s", - startupCapacity); + LOG_LOCKED(lock, + "- MOZ_PROFILER_STARTUP_ENTRIES not a valid integer: %s", + startupCapacity); PrintUsageThenExit(1); } } @@ -3243,10 +3244,11 @@ void profiler_init(void* aStackTop) { if (durationVal > 0.0) { duration = Some(durationVal); } - LOG("- MOZ_PROFILER_STARTUP_DURATION = %f", durationVal); + LOG_LOCKED(lock, "- MOZ_PROFILER_STARTUP_DURATION = %f", durationVal); } else { - LOG("- MOZ_PROFILER_STARTUP_DURATION not a valid float: %s", - startupDuration); + LOG_LOCKED(lock, + "- MOZ_PROFILER_STARTUP_DURATION not a valid float: %s", + startupDuration); PrintUsageThenExit(1); } } @@ -3256,10 +3258,11 @@ void profiler_init(void* aStackTop) { errno = 0; interval = PR_strtod(startupInterval, nullptr); if (errno == 0 && interval > 0.0 && interval <= PROFILER_MAX_INTERVAL) { - LOG("- MOZ_PROFILER_STARTUP_INTERVAL = %f", interval); + LOG_LOCKED(lock, "- MOZ_PROFILER_STARTUP_INTERVAL = %f", interval); } else { - LOG("- MOZ_PROFILER_STARTUP_INTERVAL not a valid float: %s", - startupInterval); + LOG_LOCKED(lock, + "- MOZ_PROFILER_STARTUP_INTERVAL not a valid float: %s", + startupInterval); PrintUsageThenExit(1); } } @@ -3272,9 +3275,12 @@ void profiler_init(void* aStackTop) { errno = 0; features = strtol(startupFeaturesBitfield, nullptr, 10); if (errno == 0 && features != 0) { - LOG("- MOZ_PROFILER_STARTUP_FEATURES_BITFIELD = %d", features); + LOG_LOCKED(lock, "- MOZ_PROFILER_STARTUP_FEATURES_BITFIELD = %d", + features); } else { - LOG("- MOZ_PROFILER_STARTUP_FEATURES_BITFIELD not a valid integer: %s", + LOG_LOCKED( + lock, + "- MOZ_PROFILER_STARTUP_FEATURES_BITFIELD not a valid integer: %s", startupFeaturesBitfield); PrintUsageThenExit(1); } @@ -3289,14 +3295,14 @@ void profiler_init(void* aStackTop) { features = ParseFeaturesFromStringArray(featureStringArray.begin(), featureStringArray.length(), /* aIsStartup */ true); - LOG("- MOZ_PROFILER_STARTUP_FEATURES = %d", features); + LOG_LOCKED(lock, "- MOZ_PROFILER_STARTUP_FEATURES = %d", features); } } const char* startupFilters = getenv("MOZ_PROFILER_STARTUP_FILTERS"); if (startupFilters && startupFilters[0] != '\0') { filters = SplitAtCommas(startupFilters, filterStorage); - LOG("- MOZ_PROFILER_STARTUP_FILTERS = %s", startupFilters); + LOG_LOCKED(lock, "- MOZ_PROFILER_STARTUP_FILTERS = %s", startupFilters); } locked_profiler_start(lock, capacity, interval, features, filters.begin(), @@ -3548,10 +3554,14 @@ Vector profiler_move_exit_profiles() { static void locked_profiler_save_profile_to_file(PSLockRef aLock, const char* aFilename, bool aIsShuttingDown = false) { - LOG("locked_profiler_save_profile_to_file(%s)", aFilename); + LOG_LOCKED(aLock, "locked_profiler_save_profile_to_file(%s)", aFilename); MOZ_RELEASE_ASSERT(CorePS::Exists() && ActivePS::Exists(aLock)); +#if !defined(RELEASE_OR_BETA) + ActivePS::PauseIOInterposer(aLock); +#endif + std::ofstream stream; stream.open(aFilename); if (stream.is_open()) { @@ -3574,6 +3584,10 @@ static void locked_profiler_save_profile_to_file(PSLockRef aLock, stream.close(); } + +#if !defined(RELEASE_OR_BETA) + ActivePS::ResumeIOInterposer(aLock); +#endif } void profiler_save_profile_to_file(const char* aFilename) { @@ -3648,14 +3662,14 @@ static void locked_profiler_start(PSLockRef aLock, PowerOfTwo32 aCapacity, const char** aFilters, uint32_t aFilterCount, const Maybe& aDuration) { if (LOG_TEST) { - LOG("locked_profiler_start"); - LOG("- capacity = %u", unsigned(aCapacity.Value())); - LOG("- duration = %.2f", aDuration ? *aDuration : -1); - LOG("- interval = %.2f", aInterval); + LOG_LOCKED(aLock, "locked_profiler_start"); + LOG_LOCKED(aLock, "- capacity = %u", unsigned(aCapacity.Value())); + LOG_LOCKED(aLock, "- duration = %.2f", aDuration ? *aDuration : -1); + LOG_LOCKED(aLock, "- interval = %.2f", aInterval); #define LOG_FEATURE(n_, str_, Name_, desc_) \ if (ProfilerFeature::Has##Name_(aFeatures)) { \ - LOG("- feature = %s", str_); \ + LOG_LOCKED(aLock, "- feature = %s", str_); \ } PROFILER_FOR_EACH_FEATURE(LOG_FEATURE) @@ -3663,7 +3677,7 @@ static void locked_profiler_start(PSLockRef aLock, PowerOfTwo32 aCapacity, #undef LOG_FEATURE for (uint32_t i = 0; i < aFilterCount; i++) { - LOG("- threads = %s", aFilters[i]); + LOG_LOCKED(aLock, "- threads = %s", aFilters[i]); } } @@ -3872,7 +3886,7 @@ void profiler_ensure_started(PowerOfTwo32 aCapacity, double aInterval, } static MOZ_MUST_USE SamplerThread* locked_profiler_stop(PSLockRef aLock) { - LOG("locked_profiler_stop"); + LOG_LOCKED(aLock, "locked_profiler_stop"); MOZ_RELEASE_ASSERT(CorePS::Exists() && ActivePS::Exists(aLock)); @@ -4094,7 +4108,7 @@ void profiler_unregister_thread() { if (registeredThread) { RefPtr info = registeredThread->Info(); - DEBUG_LOG("profiler_unregister_thread: %s", info->Name()); + DEBUG_LOG_LOCKED(lock, "profiler_unregister_thread: %s", info->Name()); if (ActivePS::Exists(lock)) { ActivePS::UnregisterThread(lock, registeredThread); diff --git a/tools/profiler/core/platform.h b/tools/profiler/core/platform.h index 7245daef8d05..ec59789962b5 100644 --- a/tools/profiler/core/platform.h +++ b/tools/profiler/core/platform.h @@ -50,16 +50,44 @@ extern mozilla::LazyLogModule gProfilerLog; // These are for MOZ_LOG="prof:3" or higher. It's the default logging level for // the profiler, and should be used sparingly. #define LOG_TEST MOZ_LOG_TEST(gProfilerLog, mozilla::LogLevel::Info) -#define LOG(arg, ...) \ - MOZ_LOG(gProfilerLog, mozilla::LogLevel::Info, \ - ("[%d] " arg, profiler_current_process_id(), ##__VA_ARGS__)) +// Use LOG() from any function/scope that does not own the profiler mutex. +#define LOG(arg, ...) \ + do { \ + gPSMutex.AssertCurrentThreadDoesNotOwn(); /* See LOG_LOCKED() */ \ + MOZ_LOG(gProfilerLog, mozilla::LogLevel::Info, \ + ("[%d] " arg, profiler_current_process_id(), ##__VA_ARGS__)); \ + } while (false) +// Use LOG_LOCKED() from any function/scope that owns the profiler mutex. +// This is to avoid deadlocks if the I/O interposer intercepted the logging +// operation, and tried to lock again when recording its stack trace. +#define LOG_LOCKED(lock, arg, ...) \ + do { \ + if (!(ActivePS::Exists(lock) && ActivePS::InterposeObserver(lock))) { \ + MOZ_LOG(gProfilerLog, mozilla::LogLevel::Info, \ + ("[%d] " arg, profiler_current_process_id(), ##__VA_ARGS__)); \ + } \ + } while (false) // These are for MOZ_LOG="prof:4" or higher. It should be used for logging that // is somewhat more verbose than LOG. #define DEBUG_LOG_TEST MOZ_LOG_TEST(gProfilerLog, mozilla::LogLevel::Debug) -#define DEBUG_LOG(arg, ...) \ - MOZ_LOG(gProfilerLog, mozilla::LogLevel::Debug, \ - ("[%d] " arg, profiler_current_process_id(), ##__VA_ARGS__)) +// Use DEBUG_LOG() from any function/scope that does not own the profiler mutex. +#define DEBUG_LOG(arg, ...) \ + do { \ + gPSMutex.AssertCurrentThreadDoesNotOwn(); /* See DEBUG_LOG_LOCKED() */ \ + MOZ_LOG(gProfilerLog, mozilla::LogLevel::Debug, \ + ("[%d] " arg, profiler_current_process_id(), ##__VA_ARGS__)); \ + } while (false) +// Use DEBUG_LOG_LOCKED() from any function/scope that owns the profiler mutex. +// This is to avoid deadlocks if the I/O interposer intercepted the logging +// operation, and tried to lock again when recording its stack trace. +#define DEBUG_LOG_LOCKED(lock, arg, ...) \ + do { \ + if (!(ActivePS::Exists(lock) && ActivePS::InterposeObserver(lock))) { \ + MOZ_LOG(gProfilerLog, mozilla::LogLevel::Debug, \ + ("[%d] " arg, profiler_current_process_id(), ##__VA_ARGS__)); \ + } \ + } while (false) typedef uint8_t* Address; diff --git a/tools/profiler/core/shared-libraries-linux.cc b/tools/profiler/core/shared-libraries-linux.cc index 67a291fd9434..28f7f69e944a 100644 --- a/tools/profiler/core/shared-libraries-linux.cc +++ b/tools/profiler/core/shared-libraries-linux.cc @@ -56,7 +56,7 @@ struct LoadedLibraryInfo { }; #if defined(GP_OS_android) -static void outputMapperLog(const char* aBuf) { LOG("%s", aBuf); } +static void outputMapperLog(const char* aBuf) { NS_WARNING("%s", aBuf); } #endif static nsCString IDtoUUIDString( @@ -161,7 +161,7 @@ SharedLibraryInfo SharedLibraryInfo::GetInfoForSelf() { // readlink failed for whatever reason. Note this, but keep going. exeName[0] = '\0'; exeNameLen = 0; - LOG("SharedLibraryInfo::GetInfoForSelf(): readlink failed"); + NS_WARNING("SharedLibraryInfo::GetInfoForSelf(): readlink failed"); } else { // Assert no buffer overflow. MOZ_RELEASE_ASSERT(exeNameLen >= 0 && @@ -203,7 +203,8 @@ SharedLibraryInfo SharedLibraryInfo::GetInfoForSelf() { continue; } if (ret != 5 && ret != 4) { - LOG("SharedLibraryInfo::GetInfoForSelf(): " + NS_WARNING( + "SharedLibraryInfo::GetInfoForSelf(): " "reading /proc/self/maps failed"); continue; } @@ -220,7 +221,8 @@ SharedLibraryInfo SharedLibraryInfo::GetInfoForSelf() { info.AddSharedLibrary( SharedLibraryAtPath(modulePath, start, end, offset)); if (info.GetSize() > 10000) { - LOG("SharedLibraryInfo::GetInfoForSelf(): " + NS_WARNING( + "SharedLibraryInfo::GetInfoForSelf(): " "implausibly large number of mappings acquired"); break; }