Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media. r?pehrsons draft
authorPaul Adenot <paul@paul.cx>
Tue, 20 Mar 2018 18:22:08 +0100
changeset 776657 b620b6d5c6e46b870805d1bf025c00a93762bb23
parent 776656 87f06724cdc14ba9c70e2c19a6bd181f3812b561
child 776658 e0a2e98f554f48626957c993facf48c3d0be1468
push id104937
push userpaul@paul.cx
push dateTue, 03 Apr 2018 14:51:36 +0000
reviewerspehrsons
bugs1444976
milestone61.0a1
Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media. r?pehrsons Use it like this: > MOZ_DISABLE_CONTENT_SANDBOX=1 MOZ_LOG=MSGTracing:5 MOZ_LOG_FILE=trace.log ./mach run After done, open `trace.log`, remove the junk that MOZ_LOG puts in front with something like `sed 's/.*MSGTracing //' trace.log.child-1`, and add a single `[` at the beginning of the file. Now open `chrome://tracing` and load the file. Lanes are threads, thread 0 is the audio callback thread, the other thread have normal numbers. Thread 1 shows the theoretical budget we have for a particular audio callback. MozReview-Commit-ID: 87woGiFT4ID
dom/media/Tracing.cpp
dom/media/Tracing.h
dom/media/moz.build
new file mode 100644
--- /dev/null
+++ b/dom/media/Tracing.cpp
@@ -0,0 +1,107 @@
+/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* vim: set ts=8 sts=2 et sw=2 tw=80: */
+/* 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/. */
+
+#include "Tracing.h"
+
+#include <inttypes.h>
+#include <cstdio>
+
+#include "AsyncLogger.h"
+#include "mozilla/TimeStamp.h"
+
+using namespace mozilla;
+
+uint64_t
+AutoTracer::NowInUs()
+{
+  static TimeStamp base = TimeStamp::Now();
+  return (TimeStamp::Now() - base).ToMicroseconds();
+}
+
+void
+AutoTracer::PrintEvent(const char* aName,
+                       const char* aCategory,
+                       const char* aComment,
+                       TracingPhase aPhase,
+                       uint64_t aTime,
+                       uint64_t aPID,
+                       uint64_t aThread)
+{
+  mLogger.Log("{\"name\": \"%s\", \"cat\": \"%s\", \"ph\": \"%c\","
+              "\"ts\": %" PRIu64 ", \"pid\": %" PRIu64 ", \"tid\":"
+              " %" PRIu64 ", \"args\": { \"comment\": \"%s\"}},",
+           aName, aCategory, TRACING_PHASE_STRINGS[aPhase],
+           aTime, aPID, aThread, aComment);
+}
+
+void
+AutoTracer::PrintBudget(const char* aName,
+                        const char* aCategory,
+                        const char* aComment,
+                        uint64_t aDuration,
+                        uint64_t aPID,
+                        uint64_t aThread,
+                        uint64_t aFrames)
+{
+  mLogger.Log("{\"name\": \"%s\", \"cat\": \"%s\", \"ph\": \"X\","
+              "\"ts\": %" PRIu64 ", \"dur\": %" PRIu64 ", \"pid\": %" PRIu64 ","
+              "\"tid\": %" PRIu64 ", \"args\": { \"comment\": %" PRIu64 "}},",
+              aName, aCategory, NowInUs(), aDuration, aPID, aThread, aFrames);
+}
+
+AutoTracer::AutoTracer(AsyncLogger& aLogger,
+                       const char* aLocation,
+                       uint64_t aPID,
+                       uint64_t aTID,
+                       EventType aEventType,
+                       uint64_t aFrames,
+                       uint64_t aSampleRate)
+  : mLogger(aLogger)
+  , mLocation(aLocation)
+  , mEventType(aEventType)
+  , mPID(aPID)
+  , mTID(aTID)
+	, mLoggerEnabled(mLogger.Enabled())
+{
+  if (!mLoggerEnabled) {
+    return;
+  }
+  MOZ_ASSERT(aEventType == EventType::BUDGET);
+
+  float durationUS = (static_cast<float>(aFrames) / aSampleRate) * 1e6;
+  PrintBudget(aLocation, "perf", mComment, durationUS, mPID, mTID, aFrames);
+}
+
+AutoTracer::AutoTracer(AsyncLogger& aLogger,
+                       const char* aLocation,
+                       uint64_t aPID,
+                       uint64_t aTID,
+                       EventType aEventType,
+                       const char* aComment)
+  : mLogger(aLogger)
+  , mLocation(aLocation)
+  , mComment(aComment)
+  , mEventType(aEventType)
+  , mPID(aPID)
+  , mTID(aTID)
+	, mLoggerEnabled(mLogger.Enabled())
+{
+  if (!mLoggerEnabled) {
+    return;
+  }
+  MOZ_ASSERT(aEventType == EventType::DURATION);
+  PrintEvent(aLocation, "perf", mComment, TracingPhase::BEGIN, NowInUs(), aPID, aTID);
+}
+
+AutoTracer::~AutoTracer()
+{
+  if (!mLoggerEnabled) {
+    return;
+  }
+  if (mEventType == EventType::DURATION) {
+    PrintEvent(mLocation, "perf", mComment, TracingPhase::END, NowInUs(), mPID, mTID);
+  }
+}
new file mode 100644
--- /dev/null
+++ b/dom/media/Tracing.h
@@ -0,0 +1,137 @@
+/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
+/* vim: set ts=8 sts=2 et sw=2 tw=80: */
+/* 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/. */
+
+#ifndef TRACING_H
+#define TRACING_H
+
+#include <cstdint>
+
+#include "AsyncLogger.h"
+
+#include <mozilla/Attributes.h>
+
+#if defined(_WIN32)
+#include <process.h>
+#define getpid() _getpid()
+#else
+#include <unistd.h>
+#endif
+
+#define TRACING
+
+#ifdef TRACING
+  /* TRACE is for use in the real-time audio rendering thread.
+   * It would be better to always pass in the thread id. However, the thread an
+   * audio callback runs on can change when the underlying audio device change,
+   * and also it seems to be called from a thread pool in a round-robin fashion
+   * when audio remoting is activated, making the traces unreadable.
+   * The thread on which the AudioCallbackDriver::DataCallback is to always
+   * be thread 0, and the budget is set to always be thread 1. This allows
+   * displaying those elements in two separate lanes.
+   * The other thread have "normal" tid. Hashing allows being able to get a
+   * string representation that is unique and guaranteed to be portable. */
+  #define TRACE_AUDIO_CALLBACK(aLogger)                                        \
+    AutoTracer trace(aLogger, __PRETTY_FUNCTION__, getpid(), 0);
+  #define TRACE_AUDIO_CALLBACK_BUDGET(aLogger, aFrames, aSampleRate)           \
+    AutoTracer budget(aLogger, "Real-time budget", getpid(), 1,                \
+                      AutoTracer::EventType::BUDGET, aFrames, aSampleRate);
+  #define TRACE(aLogger)                                                       \
+    AutoTracer trace(aLogger, __PRETTY_FUNCTION__, getpid(),                   \
+                     std::hash<std::thread::id>{}(std::this_thread::get_id()));
+  #define TRACE_COMMENT(aLogger, aComment)                                     \
+    AutoTracer trace(aLogger, __PRETTY_FUNCTION__, getpid(),                   \
+                     std::hash<std::thread::id>{}(std::this_thread::get_id()), \
+                     AutoTracer::EventType::DURATION,                          \
+                     aComment);
+#else
+  #define TRACE_AUDIO_CALLBACK(aLogger)
+  #define TRACE_AUDIO_CALLBACK_BUDGET(aLogger, aFrames, aSampleRate)
+  #define TRACE(aLogger)
+  #define TRACE_COMMENT(aLogger, aComment)
+#endif
+
+
+class MOZ_RAII AutoTracer
+{
+public:
+  enum class EventType
+  {
+    DURATION,
+    BUDGET
+  };
+
+  AutoTracer(mozilla::AsyncLogger& aLogger,
+             const char* aLocation,
+             uint64_t aPID,
+             uint64_t aTID,
+             EventType aEventType = EventType::DURATION,
+             const char* aComment = nullptr);
+  AutoTracer(mozilla::AsyncLogger& aLogger,
+             const char* aLocation,
+             uint64_t aPID,
+             uint64_t aTID,
+             EventType aEventType,
+             uint64_t aSampleRate,
+             uint64_t aFrames);
+  ~AutoTracer();
+private:
+  uint64_t NowInUs();
+
+  enum TracingPhase
+  {
+    BEGIN,
+    END,
+    COMPLETE
+  };
+
+  const char TRACING_PHASE_STRINGS[3] = {
+    'B',
+    'E',
+    'X'
+  };
+
+  void PrintEvent(const char* aName,
+                  const char* aCategory,
+                  const char* aComment,
+                  TracingPhase aPhase,
+                  uint64_t aTime,
+                  uint64_t aPID,
+                  uint64_t aThread);
+
+  void PrintBudget(const char* aName,
+                   const char* aCategory,
+                   const char* aComment,
+                   uint64_t aDuration,
+                   uint64_t aPID,
+                   uint64_t aThread,
+                   uint64_t aFrames);
+
+  // The logger to use. It has a lifetime longer than the block an instance of
+  // this class traces.
+  mozilla::AsyncLogger& mLogger;
+  // The location for this trace point, arbitrary string litteral, often the
+  // name of the calling function, with a static lifetime.
+  const char* mLocation;
+  // A comment for this trace point, abitrary string litteral with a static
+  // lifetime.
+  const char* mComment;
+  // The event type, for now either a budget or a duration.
+  const EventType mEventType;
+  // The process ID of the calling process, will be displayed in a separate
+  // section in the trace visualizer.
+  const uint64_t mPID;
+  // The thread ID of the calling thread, will be displayed in a separate
+  // section in the trace visualizer.
+  const uint64_t mTID;
+  // Whether or not the logger is enabled, controling the output.
+  const bool mLoggerEnabled;
+};
+
+#if defined(_WIN32)
+#undef getpid
+#endif
+
+#endif /* TRACING_H */
--- a/dom/media/moz.build
+++ b/dom/media/moz.build
@@ -149,16 +149,17 @@ EXPORTS += [
     'QueueObject.h',
     'SeekJob.h',
     'SeekTarget.h',
     'SelfRef.h',
     'SharedBuffer.h',
     'StreamTracks.h',
     'ThreadPoolCOMListener.h',
     'TimeUnits.h',
+    'Tracing.h',
     'TrackID.h',
     'TrackUnionStream.h',
     'VideoFrameContainer.h',
     'VideoLimits.h',
     'VideoSegment.h',
     'VideoUtils.h',
     'VorbisUtils.h',
     'XiphExtradata.h',
@@ -260,16 +261,17 @@ UNIFIED_SOURCES += [
     'ReaderProxy.cpp',
     'SeekJob.cpp',
     'StreamTracks.cpp',
     'TextTrack.cpp',
     'TextTrackCue.cpp',
     'TextTrackCueList.cpp',
     'TextTrackList.cpp',
     'TextTrackRegion.cpp',
+    'Tracing.cpp',
     'TrackUnionStream.cpp',
     'VideoFrameContainer.cpp',
     'VideoPlaybackQuality.cpp',
     'VideoSegment.cpp',
     'VideoStreamTrack.cpp',
     'VideoTrack.cpp',
     'VideoTrackList.cpp',
     'VideoUtils.cpp',