/* 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/BaseProfilerMarkerTypes.h" #include "mozilla/MathAlgorithms.h" #include "mozilla/Sprintf.h" #include "mozilla/TimeStamp.h" #include "GeckoProfiler.h" #include "MPSCQueue.h" #if defined(_WIN32) # include # define getpid() _getpid() #else # include #endif namespace mozilla { // Allows writing 0-terminated C-strings in a buffer, and returns the start // index of the string that's been appended. Automatically truncates the strings // as needed if the storage is too small, returning true when that's the case. class MOZ_STACK_CLASS StringWriter { public: StringWriter(char* aMemory, size_t aLength) : mMemory(aMemory), mWriteIndex(0), mLength(aLength) {} bool AppendCString(const char* aString, size_t* aIndexStart) { *aIndexStart = mWriteIndex; if (!aString) { return false; } size_t toCopy = strlen(aString); bool truncated = false; if (toCopy > Available()) { truncated = true; toCopy = Available() - 1; } memcpy(&(mMemory[mWriteIndex]), aString, toCopy); mWriteIndex += toCopy; mMemory[mWriteIndex] = 0; mWriteIndex++; return truncated; } private: size_t Available() { MOZ_ASSERT(mLength > mWriteIndex); return mLength - mWriteIndex; } char* mMemory; size_t mWriteIndex; size_t mLength; }; const size_t PAYLOAD_TOTAL_SIZE = 2 << 9; // This class implements a lock-free asynchronous logger, that // adds profiler markers. // 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 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'}; struct TextPayload { char mPayload[PAYLOAD_TOTAL_SIZE - MPSC_MSG_RESERVED]; }; // The order of the fields is important here to minimize padding. struct TracePayload { #define MEMBERS_EXCEPT_NAME \ /* If this marker is of phase B or E (begin or end), this is the time at \ * which it was captured. */ \ TimeStamp mTimestamp; \ /* The thread on which this tracepoint was gathered. */ \ ProfilerThreadId mTID; \ /* 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; \ /* 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; \ /* Offset at which the comment part of the string starts, in mName */ \ uint8_t mCommentStart; MEMBERS_EXCEPT_NAME; private: // Mock structure, to know where the first character of the name will be. struct MembersWithChar { MEMBERS_EXCEPT_NAME; char c; }; static constexpr size_t scRemainingSpaceForName = PAYLOAD_TOTAL_SIZE - offsetof(MembersWithChar, c) - ((MPSC_MSG_RESERVED + alignof(MembersWithChar) - 1) & ~(alignof(MembersWithChar) - 1)); #undef MEMBERS_EXCEPT_NAME public: // An arbitrary string, usually containing a function signature or a // recognizable tag of some sort, to be displayed when analyzing the // profile. char mName[scRemainingSpaceForName]; }; // 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::Message) == PAYLOAD_TOTAL_SIZE, "MPSCQueue internal allocations has an unexpected size."); explicit AsyncLogger() : mThread(nullptr), mRunning(false) {} void Start() { MOZ_ASSERT(!mRunning, "Double calls to AsyncLogger::Start"); mRunning = true; 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()) { return; } auto* msg = new MPSCQueue::Message(); msg->data.mTID = profiler_current_thread_id(); msg->data.mPhase = aPhase; msg->data.mTimestamp = TimeStamp::Now(); msg->data.mDurationUs = 0; // unused, duration is end - begin StringWriter writer(msg->data.mName, ArrayLength(msg->data.mName)); size_t commentIndex; DebugOnly truncated = writer.AppendCString(aName, &commentIndex); MOZ_ASSERT(!truncated, "Tracing payload truncated: name"); if (aComment) { truncated = writer.AppendCString(aComment, &commentIndex); MOZ_ASSERT(!truncated, "Tracing payload truncated: comment"); msg->data.mCommentStart = commentIndex; } else { msg->data.mCommentStart = 0; } mMessageQueueProfiler.Push(msg); } // 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()) { auto* msg = new MPSCQueue::Message(); msg->data.mTID = profiler_current_thread_id(); msg->data.mPhase = TracingPhase::COMPLETE; msg->data.mTimestamp = TimeStamp::Now(); 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); } } bool Enabled() { return profiler_is_active(); } private: void Run() { mThread.reset(new std::thread([this]() { AUTO_PROFILER_REGISTER_THREAD("AsyncLogger"); while (mRunning) { { struct TracingMarkerWithComment { static constexpr Span MarkerTypeName() { return MakeStringSpan("Real-Time"); } static void StreamJSONMarkerData( baseprofiler::SpliceableJSONWriter& aWriter, const ProfilerString8View& aText) { aWriter.StringProperty("name", aText); } static MarkerSchema MarkerTypeDisplay() { using MS = MarkerSchema; MS schema{MS::Location::markerChart, MS::Location::markerTable}; schema.SetChartLabel("{marker.data.name}"); schema.SetTableLabel("{marker.name} - {marker.data.name}"); schema.AddKeyLabelFormat("name", "Comment", MarkerSchema::Format::string); return schema; } }; struct TracingMarker { static constexpr Span MarkerTypeName() { return MakeStringSpan("Real-time"); } 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) { if (!message.mCommentStart) { 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)}, TracingMarker{}); } else { 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)}, TracingMarkerWithComment{}, ProfilerString8View::WrapNullTerminatedString( &(message.mName[message.mCommentStart]))); } } 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))}, TracingMarker{}); } } } Sleep(); } })); // cleanup is done via mRunning mThread->detach(); } uint64_t NowInUs() { static TimeStamp base = TimeStamp::Now(); return (TimeStamp::Now() - base).ToMicroseconds(); } void Sleep() { std::this_thread::sleep_for(std::chrono::milliseconds(10)); } std::unique_ptr mThread; MPSCQueue mMessageQueueProfiler; std::atomic mRunning; }; } // end namespace mozilla #if defined(_WIN32) # undef getpid #endif #endif // mozilla_dom_AsyncLogger_h