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 785592 9996dc3a130de7a77702776a3d874cad64853184
parent 783621 2c22217616f75d581876294d131d8bdd7b4ec17c
child 785593 e9fded0cecdb65456ea4f910b143d46814438210
push id107261
push userpaul@paul.cx
push dateFri, 20 Apr 2018 11:50:24 +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,sync,raw MOZ_LOG_FILE=trace.log ./mach run 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/MediaStreamGraph.cpp
dom/media/MediaStreamGraph.h
dom/media/Tracing.cpp
dom/media/Tracing.h
dom/media/moz.build
--- a/dom/media/MediaStreamGraph.cpp
+++ b/dom/media/MediaStreamGraph.cpp
@@ -27,25 +27,28 @@
 #include "mozilla/media/MediaUtils.h"
 #include <algorithm>
 #include "GeckoProfiler.h"
 #include "VideoFrameContainer.h"
 #include "mozilla/AbstractThread.h"
 #include "mozilla/Unused.h"
 #include "mtransport/runnable_utils.h"
 #include "VideoUtils.h"
+#include "Tracing.h"
 
 #include "webaudio/blink/DenormalDisabler.h"
 #include "webaudio/blink/HRTFDatabaseLoader.h"
 
 using namespace mozilla::layers;
 using namespace mozilla::dom;
 using namespace mozilla::gfx;
 using namespace mozilla::media;
 
+mozilla::AsyncLogger gMSGTraceLogger("MSGTracing");
+
 namespace mozilla {
 
 LazyLogModule gMediaStreamGraphLog("MediaStreamGraph");
 #ifdef LOG
 #undef LOG
 #endif // LOG
 #define LOG(type, msg) MOZ_LOG(gMediaStreamGraphLog, type, msg)
 
@@ -63,16 +66,20 @@ enum SourceMediaStream::TrackCommands : 
 static nsDataHashtable<nsUint32HashKey, MediaStreamGraphImpl*> gGraphs;
 
 MediaStreamGraphImpl::~MediaStreamGraphImpl()
 {
   MOZ_ASSERT(mStreams.IsEmpty() && mSuspendedStreams.IsEmpty(),
              "All streams should have been destroyed by messages from the main thread");
   LOG(LogLevel::Debug, ("MediaStreamGraph %p destroyed", this));
   LOG(LogLevel::Debug, ("MediaStreamGraphImpl::~MediaStreamGraphImpl"));
+
+#ifdef TRACING
+  gMSGTraceLogger.Stop();
+#endif
 }
 
 void
 MediaStreamGraphImpl::AddStreamGraphThread(MediaStream* aStream)
 {
   MOZ_ASSERT(OnGraphThreadOrNotRunning());
   aStream->mTracksStartTime = mProcessedTime;
 
@@ -3609,16 +3616,22 @@ MediaStreamGraphImpl::MediaStreamGraphIm
 {
   if (mRealtime) {
     if (aDriverRequested == AUDIO_THREAD_DRIVER) {
       AudioCallbackDriver* driver = new AudioCallbackDriver(this);
       mDriver = driver;
     } else {
       mDriver = new SystemClockDriver(this);
     }
+
+#ifdef TRACING
+    // This is a noop if the logger has not been enabled.
+    gMSGTraceLogger.Start();
+    gMSGTraceLogger.Log("[");
+#endif
   } else {
     mDriver = new OfflineClockDriver(this, MEDIA_GRAPH_TARGET_PERIOD_MS);
   }
 
   mLastMainThreadUpdate = TimeStamp::Now();
 
   RegisterWeakAsyncMemoryReporter(this);
 }
--- a/dom/media/MediaStreamGraph.h
+++ b/dom/media/MediaStreamGraph.h
@@ -20,16 +20,23 @@
 #include "nsIRunnable.h"
 #include "nsTArray.h"
 #include <speex/speex_resampler.h>
 
 class nsIRunnable;
 class nsIGlobalObject;
 class nsPIDOMWindowInner;
 
+namespace mozilla {
+  class AsyncLogger;
+};
+
+extern mozilla::AsyncLogger gMSGTraceLogger;
+
+
 template <>
 class nsAutoRefTraits<SpeexResamplerState> : public nsPointerRefTraits<SpeexResamplerState>
 {
   public:
   static void Release(SpeexResamplerState* aState) { speex_resampler_destroy(aState); }
 };
 
 namespace mozilla {
new file mode 100644
--- /dev/null
+++ b/dom/media/Tracing.cpp
@@ -0,0 +1,102 @@
+/* -*- 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[static_cast<int>(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)
+{
+  MOZ_ASSERT(aEventType == EventType::BUDGET);
+
+  if (aLogger.Enabled()) {
+    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)
+{
+  MOZ_ASSERT(aEventType == EventType::DURATION);
+  if (aLogger.Enabled()) {
+    PrintEvent(aLocation, "perf", mComment, TracingPhase::BEGIN, NowInUs(), aPID, aTID);
+  }
+}
+
+AutoTracer::~AutoTracer()
+{
+  if (mEventType == EventType::DURATION) {
+    if (mLogger.Enabled()) {
+      PrintEvent(mLocation, "perf", mComment, TracingPhase::END, NowInUs(), mPID, mTID);
+    }
+  }
+}
new file mode 100644
--- /dev/null
+++ b/dom/media/Tracing.h
@@ -0,0 +1,140 @@
+/* -*- 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
+
+#if defined(_MSC_VER)
+// MSVC
+#define FUNCTION_SIGNATURE  __FUNCSIG__
+#elif defined(__GNUC__)
+// gcc, clang
+#define FUNCTION_SIGNATURE __PRETTY_FUNCTION__
+#endif
+
+#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()                                               \
+    AutoTracer trace(gMSGTraceLogger, FUNCTION_SIGNATURE, getpid(), 0);
+  #define TRACE_AUDIO_CALLBACK_BUDGET(aFrames, aSampleRate)                    \
+    AutoTracer budget(gMSGTraceLogger, "Real-time budget", getpid(), 1,        \
+                      AutoTracer::EventType::BUDGET, aFrames, aSampleRate);
+  #define TRACE()                                                              \
+    AutoTracer trace(gMSGTraceLogger, FUNCTION_SIGNATURE, getpid(),            \
+                     std::hash<std::thread::id>{}(std::this_thread::get_id()));
+  #define TRACE_COMMENT(aComment)                                              \
+    AutoTracer trace(gMSGTraceLogger, FUNCTION_SIGNATURE, getpid(),            \
+                     std::hash<std::thread::id>{}(std::this_thread::get_id()), \
+                     AutoTracer::EventType::DURATION,                          \
+                     aComment);
+#else
+  #define TRACE_AUDIO_CALLBACK()
+  #define TRACE_AUDIO_CALLBACK_BUDGET(aFrames, aSampleRate)
+  #define TRACE()
+  #define TRACE_COMMENT(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 class 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 musdt have a lifetime longer than the block an
+  // instance of this class traces.
+  mozilla::AsyncLogger& mLogger;
+  // The location for this trace point, arbitrary string literal, often the
+  // name of the calling function, with a static lifetime.
+  const char* mLocation;
+  // A comment for this trace point, abitrary string literal 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. Traces are grouped by PID in the
+  // vizualizer.
+  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;
+};
+
+#if defined(_WIN32)
+#undef getpid
+#endif
+
+#endif /* TRACING_H */
--- a/dom/media/moz.build
+++ b/dom/media/moz.build
@@ -84,16 +84,17 @@ XPIDL_SOURCES += [
     'nsIMediaManager.idl',
 ]
 
 XPIDL_MODULE = 'dom_media'
 
 EXPORTS += [
     'ADTSDecoder.h',
     'ADTSDemuxer.h',
+    'AsyncLogger.h',
     'AudioBufferUtils.h',
     'AudioChannelFormat.h',
     'AudioCompactor.h',
     'AudioConfig.h',
     'AudioConverter.h',
     'AudioMixer.h',
     'AudioPacketizer.h',
     'AudioSampleFormat.h',
@@ -149,16 +150,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 +262,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',
@@ -323,16 +326,17 @@ LOCAL_INCLUDES += [
 
 if CONFIG['MOZ_WEBRTC']:
     LOCAL_INCLUDES += [
         '/media/webrtc/signaling/src/common',
         '/media/webrtc/trunk',
     ]
 
 DEFINES['MOZILLA_INTERNAL_API'] = True
+DEFINES['TRACING'] = True
 
 if CONFIG['MOZ_ANDROID_HLS_SUPPORT']:
     DEFINES['MOZ_ANDROID_HLS_SUPPORT'] = True
 
 include('/ipc/chromium/chromium-config.mozbuild')
 
 # Suppress some GCC warnings being treated as errors:
 #  - about attributes on forward declarations for types that are already