/* This Source Code Form is subject to the terms of the Mozilla Public * License, v. 2.0. If a copy of the MPL was not distributed with this * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ /* Implementation of an asynchronous lock-free logging system. */ #ifndef mozilla_dom_AsyncLogger_h #define mozilla_dom_AsyncLogger_h #include #include #include #include "mozilla/ArrayUtils.h" #include "mozilla/Attributes.h" #include "mozilla/Logging.h" #include "mozilla/MathAlgorithms.h" #include "mozilla/Sprintf.h" #include "GeckoProfiler.h" #ifdef MOZ_GECKO_PROFILER # include "ProfilerMarkerPayload.h" #endif #include "MPSCQueue.h" #if defined(_WIN32) # include # define getpid() _getpid() #else # include #endif namespace mozilla { const size_t PAYLOAD_TOTAL_SIZE = 2 << 9; // This class implements a lock-free asynchronous logger, that outputs to // MOZ_LOG or adds profiler markers (the default). // Any thread can use this logger without external synchronization and without // being blocked. This log is suitable for use in real-time audio threads. // This class uses a thread internally, and must be started and stopped // manually. // If logging/profiling is disabled, all the calls are no-op and cheap. class AsyncLogger { public: enum class TracingPhase : uint8_t { BEGIN, END, COMPLETE }; const char TRACING_PHASE_STRINGS[3] = {'B', 'E', 'X'}; enum AsyncLoggerOutputMode { MOZLOG, PROFILER }; struct TextPayload { char mPayload[PAYLOAD_TOTAL_SIZE - MPSC_MSG_RESERVERD]; }; // On 32bits the struct is packed differently and there is a hole we need to // account for. #if !defined(HAVE_64BIT_BUILD) && \ !(defined(XP_LINUX) && !defined(MOZ_WIDGET_ANDROID)) # define PADDING 8 #else # define PADDING 0 #endif // The order of the fields is important here to minimize padding. struct TracePayload { // If this marker is of phase B or E (begin or end), this is the time at // which it was captured. TimeStamp mTimestamp; // If this marker is of phase X (COMPLETE), this holds the duration of the // event in microseconds. Else, the value is not used. uint32_t mDurationUs; // The thread on which this tracepoint was gathered. int mTID; // An arbitrary string, usually containing a function signature or a // recognizable tag of some sort, to be displayed when analyzing the // profile. char mName[PAYLOAD_TOTAL_SIZE - sizeof(TracingPhase) - sizeof(int) - sizeof(uint32_t) - sizeof(TimeStamp) - MPSC_MSG_RESERVERD - PADDING]; // A trace payload can be either: // - Begin - this marks the beginning of a temporal region // - End - this marks the end of a temporal region // - Complete - this is a timestamp and a length, forming complete a // temporal region TracingPhase mPhase; }; #undef PADDING // The goal here is to make it easy on the allocator. We pack a pointer in the // message struct, and we still want to do power of two allocations to // minimize allocator slop. #if !(defined(XP_LINUX) && !defined(MOZ_WIDGET_ANDROID) && \ (defined(__arm__) || defined(__aarch64__))) static_assert(sizeof(MPSCQueue::Message) <= PAYLOAD_TOTAL_SIZE, "MPSCQueue internal allocations too big."); #endif // aLogModuleName is the name of the MOZ_LOG module. explicit AsyncLogger(const char* aLogModuleName, AsyncLogger::AsyncLoggerOutputMode aMode = AsyncLogger::AsyncLoggerOutputMode::PROFILER) : mThread(nullptr), mLogModule(aLogModuleName), mRunning(false), mMode(aMode) {} void Start() { MOZ_ASSERT(!mRunning, "Double calls to AsyncLogger::Start"); mRunning = true; if (mMode == AsyncLogger::AsyncLoggerOutputMode::MOZLOG) { LogMozLog("["); } Run(); } void Stop() { if (mRunning) { mRunning = false; } } // Log something that has a beginning and an end void Log(const char* aName, const char* aCategory, const char* aComment, TracingPhase aPhase) { if (Enabled()) { if (mMode == AsyncLogger::AsyncLoggerOutputMode::MOZLOG) { LogMozLog( "{\"name\": \"%s\", \"cat\": \"%s\", \"ph\": \"%c\"," "\"ts\": %" PRIu64 ", \"pid\": %d, \"tid\":" " %zu, \"args\": { \"comment\": \"%s\"}},", aName, aCategory, TRACING_PHASE_STRINGS[static_cast(aPhase)], NowInUs(), getpid(), std::hash{}(std::this_thread::get_id()), aComment); } else { #ifdef MOZ_GECKO_PROFILER auto* msg = new MPSCQueue::Message(); msg->data.mTID = profiler_current_thread_id(); msg->data.mPhase = aPhase; msg->data.mTimestamp = TimeStamp::NowUnfuzzed(); msg->data.mDurationUs = 0; // unused, duration is end - begin size_t len = std::min(strlen(aName), ArrayLength(msg->data.mName)); memcpy(msg->data.mName, aName, len); msg->data.mName[len] = 0; mMessageQueueProfiler.Push(msg); #endif } } } // Log something that has a beginning and a duration void LogDuration(const char* aName, const char* aCategory, uint64_t aDuration, uint64_t aFrames, uint64_t aSampleRate) { if (Enabled()) { if (mMode == AsyncLogger::AsyncLoggerOutputMode::MOZLOG) { LogMozLog( "{\"name\": \"%s\", \"cat\": \"%s\", \"ph\": \"X\"," "\"ts\": %" PRIu64 ", \"dur\": %" PRIu64 ", \"pid\": %d," "\"tid\": %zu, \"args\": { \"comment\": \"%" PRIu64 "/%" PRIu64 "\"}},", aName, aCategory, NowInUs(), aDuration, getpid(), std::hash{}(std::this_thread::get_id()), aFrames, aSampleRate); } else { #ifdef MOZ_GECKO_PROFILER auto* msg = new MPSCQueue::Message(); msg->data.mTID = profiler_current_thread_id(); msg->data.mPhase = TracingPhase::COMPLETE; msg->data.mTimestamp = TimeStamp::NowUnfuzzed(); msg->data.mDurationUs = (static_cast(aFrames) / aSampleRate) * 1e6; size_t len = std::min(strlen(aName), ArrayLength(msg->data.mName)); memcpy(msg->data.mName, aName, len); msg->data.mName[len] = 0; mMessageQueueProfiler.Push(msg); #endif } } } void LogMozLog(const char* format, ...) MOZ_FORMAT_PRINTF(2, 3) { auto* msg = new MPSCQueue::Message(); va_list args; va_start(args, format); VsprintfLiteral(msg->data.mPayload, format, args); va_end(args); mMessageQueueLog.Push(msg); } bool Enabled() { return (mMode == AsyncLoggerOutputMode::MOZLOG && MOZ_LOG_TEST(mLogModule, mozilla::LogLevel::Verbose)) #ifdef MOZ_GECKO_PROFILER || (mMode == AsyncLoggerOutputMode::PROFILER && profiler_is_active()) #endif ; } private: void Run() { mThread.reset(new std::thread([this]() { PROFILER_REGISTER_THREAD("AsyncLogger"); while (mRunning) { { TextPayload message; while (mMessageQueueLog.Pop(&message) && mRunning) { MOZ_LOG(mLogModule, mozilla::LogLevel::Verbose, ("%s", message.mPayload)); } } #ifdef MOZ_GECKO_PROFILER { TracePayload message; while (mMessageQueueProfiler.Pop(&message) && mRunning) { if (message.mPhase != TracingPhase::COMPLETE) { TracingKind kind = message.mPhase == TracingPhase::BEGIN ? TracingKind::TRACING_INTERVAL_START : TracingKind::TRACING_INTERVAL_END; TracingMarkerPayload payload("media", kind, message.mTimestamp); profiler_add_marker_for_thread( message.mTID, JS::ProfilingCategoryPair::MEDIA_RT, message.mName, payload); } else { mozilla::TimeStamp end = message.mTimestamp + TimeDuration::FromMicroseconds(message.mDurationUs); BudgetMarkerPayload payload(message.mTimestamp, end); profiler_add_marker_for_thread( message.mTID, JS::ProfilingCategoryPair::MEDIA_RT, message.mName, payload); } } } #endif Sleep(); } PROFILER_UNREGISTER_THREAD(); })); // cleanup is done via mRunning mThread->detach(); } uint64_t NowInUs() { static TimeStamp base = TimeStamp::NowUnfuzzed(); return (TimeStamp::NowUnfuzzed() - base).ToMicroseconds(); } void Sleep() { std::this_thread::sleep_for(std::chrono::milliseconds(10)); } std::unique_ptr mThread; mozilla::LazyLogModule mLogModule; MPSCQueue mMessageQueueLog; #ifdef MOZ_GECKO_PROFILER MPSCQueue mMessageQueueProfiler; #endif std::atomic mRunning; std::atomic mMode; }; } // end namespace mozilla #if defined(_WIN32) # undef getpid #endif #endif // mozilla_dom_AsyncLogger_h