Bug 1444976 - Use the AsyncLog to implement a tracing subsystem for real-time media. r=pehrsons
☠☠ backed out by 0e45c13b34e8 ☠ ☠
authorPaul Adenot <paul@paul.cx>
Tue, 20 Mar 2018 18:22:08 +0100
changeset 467681 35ca96cabe3c19d20868ba2453faf3fffa8df61b
parent 467680 2512c9c24244babd77b3413825b176c54ac60836
child 467682 79b7ee8b01ee122b3f7122f926e5ae9dc1132a96
push id9165
push userasasaki@mozilla.com
push dateThu, 26 Apr 2018 21:04:54 +0000
treeherdermozilla-beta@064c3804de2e [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewerspehrsons
bugs1444976
milestone61.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
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,96 @@
+/* -*- 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);
+
+  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);
+  PrintEvent(aLocation, "perf", mComment, TracingPhase::BEGIN, NowInUs(), aPID, aTID);
+}
+
+AutoTracer::~AutoTracer()
+{
+  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,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',
@@ -148,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',
@@ -258,16 +260,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',
@@ -321,16 +324,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