AsyncLogger.h (10920B)
1 /* This Source Code Form is subject to the terms of the Mozilla Public 2 * License, v. 2.0. If a copy of the MPL was not distributed with this 3 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */ 4 5 /* Implementation of an asynchronous lock-free logging system. */ 6 7 #ifndef mozilla_dom_AsyncLogger_h 8 #define mozilla_dom_AsyncLogger_h 9 10 #include <atomic> 11 #include <cinttypes> 12 #include <thread> 13 14 #include "GeckoProfiler.h" 15 #include "mozilla/Attributes.h" 16 #include "mozilla/BaseProfilerMarkerTypes.h" 17 #include "mozilla/Sprintf.h" 18 #include "mozilla/TimeStamp.h" 19 #include "mozilla/dom/UnboundedMPSCQueue.h" 20 21 #if defined(_WIN32) 22 # include <process.h> 23 # define getpid() _getpid() 24 #else 25 # include <unistd.h> 26 #endif 27 28 namespace mozilla { 29 30 // Allows writing 0-terminated C-strings in a buffer, and returns the start 31 // index of the string that's been appended. Automatically truncates the strings 32 // as needed if the storage is too small, returning true when that's the case. 33 class MOZ_STACK_CLASS StringWriter { 34 public: 35 StringWriter(char* aMemory, size_t aLength) 36 : mMemory(aMemory), mWriteIndex(0), mLength(aLength) {} 37 38 bool AppendCString(const char* aString, size_t* aIndexStart) { 39 *aIndexStart = mWriteIndex; 40 if (!aString) { 41 return false; 42 } 43 size_t toCopy = strlen(aString); 44 bool truncated = false; 45 46 if (toCopy > Available()) { 47 truncated = true; 48 toCopy = Available() - 1; 49 } 50 51 memcpy(&(mMemory[mWriteIndex]), aString, toCopy); 52 mWriteIndex += toCopy; 53 mMemory[mWriteIndex] = 0; 54 mWriteIndex++; 55 56 return truncated; 57 } 58 59 private: 60 size_t Available() { 61 MOZ_ASSERT(mLength > mWriteIndex); 62 return mLength - mWriteIndex; 63 } 64 65 char* mMemory; 66 size_t mWriteIndex; 67 size_t mLength; 68 }; 69 70 const size_t PAYLOAD_TOTAL_SIZE = 2 << 9; 71 72 // This class implements a lock-free asynchronous logger, that 73 // adds profiler markers. 74 // Any thread can use this logger without external synchronization and without 75 // being blocked. This log is suitable for use in real-time audio threads. 76 // This class uses a thread internally, and must be started and stopped 77 // manually. 78 // If profiling is disabled, all the calls are no-op and cheap. 79 class AsyncLogger { 80 public: 81 enum class TracingPhase : uint8_t { BEGIN, END, COMPLETE }; 82 83 const char TRACING_PHASE_STRINGS[3] = {'B', 'E', 'X'}; 84 85 struct TextPayload { 86 char mPayload[PAYLOAD_TOTAL_SIZE - MPSC_MSG_RESERVED]; 87 }; 88 89 // The order of the fields is important here to minimize padding. 90 struct TracePayload { 91 #define MEMBERS_EXCEPT_NAME \ 92 /* If this marker is of phase B or E (begin or end), this is the time at \ 93 * which it was captured. */ \ 94 TimeStamp mTimestamp; \ 95 /* The thread on which this tracepoint was gathered. */ \ 96 ProfilerThreadId mTID; \ 97 /* If this marker is of phase X (COMPLETE), this holds the duration of the \ 98 * event in microseconds. Else, the value is not used. */ \ 99 uint32_t mDurationUs; \ 100 /* A trace payload can be either: \ 101 * - Begin - this marks the beginning of a temporal region \ 102 * - End - this marks the end of a temporal region \ 103 * - Complete - this is a timestamp and a length, forming complete a \ 104 * temporal region */ \ 105 TracingPhase mPhase; \ 106 /* Offset at which the comment part of the string starts, in mName */ \ 107 uint8_t mCommentStart; 108 109 MEMBERS_EXCEPT_NAME; 110 111 private: 112 // Mock structure, to know where the first character of the name will be. 113 struct MembersWithChar { 114 MEMBERS_EXCEPT_NAME; 115 char c; 116 }; 117 static constexpr size_t scRemainingSpaceForName = 118 PAYLOAD_TOTAL_SIZE - offsetof(MembersWithChar, c) - 119 ((MPSC_MSG_RESERVED + alignof(MembersWithChar) - 1) & 120 ~(alignof(MembersWithChar) - 1)); 121 #undef MEMBERS_EXCEPT_NAME 122 123 public: 124 // An arbitrary string, usually containing a function signature or a 125 // recognizable tag of some sort, to be displayed when analyzing the 126 // profile. 127 char mName[scRemainingSpaceForName]; 128 }; 129 130 // The goal here is to make it easy on the allocator. We pack a pointer in the 131 // message struct, and we still want to do power of two allocations to 132 // minimize allocator slop. 133 static_assert( 134 sizeof(UnboundedMPSCQueue<TracePayload>::Message) == PAYLOAD_TOTAL_SIZE, 135 "UnboundedMPSCQueue internal allocations has an unexpected size."); 136 137 explicit AsyncLogger() : mThread(nullptr), mRunning(false) {} 138 139 void Start() { 140 MOZ_ASSERT(!mRunning, "Double calls to AsyncLogger::Start"); 141 mRunning = true; 142 Run(); 143 } 144 145 void Stop() { 146 if (mRunning) { 147 mRunning = false; 148 } 149 } 150 151 // Log something that has a beginning and an end 152 void Log(const char* aName, const char* aCategory, const char* aComment, 153 TracingPhase aPhase) { 154 if (!Enabled()) { 155 return; 156 } 157 158 auto* msg = new UnboundedMPSCQueue<TracePayload>::Message(); 159 160 msg->data.mTID = profiler_current_thread_id(); 161 msg->data.mPhase = aPhase; 162 msg->data.mTimestamp = TimeStamp::Now(); 163 msg->data.mDurationUs = 0; // unused, duration is end - begin 164 165 StringWriter writer(msg->data.mName, std::size(msg->data.mName)); 166 167 size_t commentIndex; 168 DebugOnly<bool> truncated = writer.AppendCString(aName, &commentIndex); 169 MOZ_ASSERT(!truncated, "Tracing payload truncated: name"); 170 171 if (aComment) { 172 truncated = writer.AppendCString(aComment, &commentIndex); 173 MOZ_ASSERT(!truncated, "Tracing payload truncated: comment"); 174 msg->data.mCommentStart = commentIndex; 175 } else { 176 msg->data.mCommentStart = 0; 177 } 178 mMessageQueueProfiler.Push(msg); 179 } 180 181 // Log something that has a beginning and a duration 182 void LogDuration(const char* aName, const char* aCategory, uint64_t aDuration, 183 uint64_t aFrames, uint64_t aSampleRate) { 184 if (Enabled()) { 185 auto* msg = new UnboundedMPSCQueue<TracePayload>::Message(); 186 msg->data.mTID = profiler_current_thread_id(); 187 msg->data.mPhase = TracingPhase::COMPLETE; 188 msg->data.mTimestamp = TimeStamp::Now(); 189 msg->data.mDurationUs = 190 (static_cast<double>(aFrames) / aSampleRate) * 1e6; 191 size_t len = std::min(strlen(aName), std::size(msg->data.mName)); 192 memcpy(msg->data.mName, aName, len); 193 msg->data.mName[len] = 0; 194 mMessageQueueProfiler.Push(msg); 195 } 196 } 197 198 bool Enabled() { return mRunning; } 199 200 private: 201 void Run() { 202 mThread.reset(new std::thread([this]() { 203 AUTO_PROFILER_REGISTER_THREAD("AsyncLogger"); 204 while (mRunning) { 205 { 206 struct TracingMarkerWithComment { 207 static constexpr Span<const char> MarkerTypeName() { 208 return MakeStringSpan("Real-Time"); 209 } 210 static void StreamJSONMarkerData( 211 baseprofiler::SpliceableJSONWriter& aWriter, 212 const ProfilerString8View& aText) { 213 aWriter.StringProperty("name", aText); 214 } 215 static MarkerSchema MarkerTypeDisplay() { 216 using MS = MarkerSchema; 217 MS schema{MS::Location::MarkerChart, MS::Location::MarkerTable}; 218 schema.SetChartLabel("{marker.data.name}"); 219 schema.SetTableLabel("{marker.data.name}"); 220 schema.AddKeyLabelFormat("name", "Comment", MS::Format::String, 221 MS::PayloadFlags::Searchable); 222 return schema; 223 } 224 }; 225 226 struct TracingMarker { 227 static constexpr Span<const char> MarkerTypeName() { 228 return MakeStringSpan("Real-time"); 229 } 230 static void StreamJSONMarkerData( 231 baseprofiler::SpliceableJSONWriter& aWriter) {} 232 static MarkerSchema MarkerTypeDisplay() { 233 using MS = MarkerSchema; 234 MS schema{MS::Location::MarkerChart, MS::Location::MarkerTable}; 235 // Nothing outside the defaults. 236 return schema; 237 } 238 }; 239 240 TracePayload message; 241 while (mMessageQueueProfiler.Pop(&message) && mRunning) { 242 if (message.mPhase != TracingPhase::COMPLETE) { 243 if (!message.mCommentStart) { 244 profiler_add_marker( 245 ProfilerString8View::WrapNullTerminatedString( 246 message.mName), 247 geckoprofiler::category::MEDIA_RT, 248 {MarkerThreadId(message.mTID), 249 (message.mPhase == TracingPhase::BEGIN) 250 ? MarkerTiming::IntervalStart(message.mTimestamp) 251 : MarkerTiming::IntervalEnd(message.mTimestamp)}, 252 TracingMarker{}); 253 } else { 254 profiler_add_marker( 255 ProfilerString8View::WrapNullTerminatedString( 256 message.mName), 257 geckoprofiler::category::MEDIA_RT, 258 {MarkerThreadId(message.mTID), 259 (message.mPhase == TracingPhase::BEGIN) 260 ? MarkerTiming::IntervalStart(message.mTimestamp) 261 : MarkerTiming::IntervalEnd(message.mTimestamp)}, 262 TracingMarkerWithComment{}, 263 ProfilerString8View::WrapNullTerminatedString( 264 &(message.mName[message.mCommentStart]))); 265 } 266 } else { 267 profiler_add_marker( 268 ProfilerString8View::WrapNullTerminatedString(message.mName), 269 geckoprofiler::category::MEDIA_RT, 270 {MarkerThreadId(message.mTID), 271 MarkerTiming::Interval( 272 message.mTimestamp, 273 message.mTimestamp + TimeDuration::FromMicroseconds( 274 message.mDurationUs))}, 275 TracingMarker{}); 276 } 277 } 278 } 279 Sleep(); 280 } 281 })); 282 // cleanup is done via mRunning 283 mThread->detach(); 284 } 285 286 uint64_t NowInUs() { 287 static TimeStamp base = TimeStamp::Now(); 288 return (TimeStamp::Now() - base).ToMicroseconds(); 289 } 290 291 void Sleep() { std::this_thread::sleep_for(std::chrono::milliseconds(10)); } 292 293 std::unique_ptr<std::thread> mThread; 294 UnboundedMPSCQueue<TracePayload> mMessageQueueProfiler; 295 std::atomic<bool> mRunning; 296 }; 297 298 } // end namespace mozilla 299 300 #if defined(_WIN32) 301 # undef getpid 302 #endif 303 304 #endif // mozilla_dom_AsyncLogger_h