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
--- 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