diff options
author | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-28 14:29:10 +0000 |
---|---|---|
committer | Daniel Baumann <daniel.baumann@progress-linux.org> | 2024-04-28 14:29:10 +0000 |
commit | 2aa4a82499d4becd2284cdb482213d541b8804dd (patch) | |
tree | b80bf8bf13c3766139fbacc530efd0dd9d54394c /dom/media/AsyncLogger.h | |
parent | Initial commit. (diff) | |
download | firefox-2aa4a82499d4becd2284cdb482213d541b8804dd.tar.xz firefox-2aa4a82499d4becd2284cdb482213d541b8804dd.zip |
Adding upstream version 86.0.1.upstream/86.0.1upstream
Signed-off-by: Daniel Baumann <daniel.baumann@progress-linux.org>
Diffstat (limited to 'dom/media/AsyncLogger.h')
-rw-r--r-- | dom/media/AsyncLogger.h | 269 |
1 files changed, 269 insertions, 0 deletions
diff --git a/dom/media/AsyncLogger.h b/dom/media/AsyncLogger.h new file mode 100644 index 0000000000..7edd17fd8b --- /dev/null +++ b/dom/media/AsyncLogger.h @@ -0,0 +1,269 @@ +/* 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 <atomic> +#include <thread> +#include <cinttypes> +#include "mozilla/ArrayUtils.h" +#include "mozilla/Attributes.h" +#include "mozilla/Logging.h" +#include "mozilla/MathAlgorithms.h" +#include "mozilla/Sprintf.h" +#include "GeckoProfiler.h" +#include "MPSCQueue.h" + +#if defined(_WIN32) +# include <process.h> +# define getpid() _getpid() +#else +# include <unistd.h> +#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]; + }; + + // 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) - + // Really, we'd want alignof(TracePayload), but it's not fully + // declared yet. The alignment is going to be that of TimeStamp. + ((MPSC_MSG_RESERVERD + alignof(TimeStamp) - 1) & + ~(alignof(TimeStamp) - 1))]; + // 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; + }; + + // 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. + static_assert(sizeof(MPSCQueue<TracePayload>::Message) == PAYLOAD_TOTAL_SIZE, + "MPSCQueue internal allocations has an unexpected size."); + + // 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<int>(aPhase)], + NowInUs(), getpid(), + std::hash<std::thread::id>{}(std::this_thread::get_id()), aComment); + } else { +#ifdef MOZ_GECKO_PROFILER + auto* msg = new MPSCQueue<TracePayload>::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::thread::id>{}(std::this_thread::get_id()), aFrames, + aSampleRate); + } else { +#ifdef MOZ_GECKO_PROFILER + auto* msg = new MPSCQueue<TracePayload>::Message(); + msg->data.mTID = profiler_current_thread_id(); + msg->data.mPhase = TracingPhase::COMPLETE; + msg->data.mTimestamp = TimeStamp::NowUnfuzzed(); + msg->data.mDurationUs = + (static_cast<double>(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<TextPayload>::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 + { + struct BudgetMarker { + static constexpr Span<const char> MarkerTypeName() { + return MakeStringSpan("Budget"); + } + static void StreamJSONMarkerData( + baseprofiler::SpliceableJSONWriter& aWriter) {} + static MarkerSchema MarkerTypeDisplay() { + using MS = MarkerSchema; + MS schema{MS::Location::markerChart, MS::Location::markerTable}; + // Nothing outside the defaults. + return schema; + } + }; + + TracePayload message; + while (mMessageQueueProfiler.Pop(&message) && mRunning) { + if (message.mPhase != TracingPhase::COMPLETE) { + profiler_add_marker( + ProfilerString8View::WrapNullTerminatedString(message.mName), + geckoprofiler::category::MEDIA_RT, + {MarkerThreadId(message.mTID), + (message.mPhase == TracingPhase::BEGIN) + ? MarkerTiming::IntervalStart(message.mTimestamp) + : MarkerTiming::IntervalEnd(message.mTimestamp)}, + BudgetMarker{}); + } else { + profiler_add_marker( + ProfilerString8View::WrapNullTerminatedString(message.mName), + geckoprofiler::category::MEDIA_RT, + {MarkerThreadId(message.mTID), + MarkerTiming::Interval( + message.mTimestamp, + message.mTimestamp + TimeDuration::FromMicroseconds( + message.mDurationUs))}, + BudgetMarker{}); + } + } + } +#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<std::thread> mThread; + mozilla::LazyLogModule mLogModule; + MPSCQueue<TextPayload> mMessageQueueLog; +#ifdef MOZ_GECKO_PROFILER + MPSCQueue<TracePayload> mMessageQueueProfiler; +#endif + std::atomic<bool> mRunning; + std::atomic<AsyncLoggerOutputMode> mMode; +}; + +} // end namespace mozilla + +#if defined(_WIN32) +# undef getpid +#endif + +#endif // mozilla_dom_AsyncLogger_h |