From 7e374f59ca3d8d73738cb0a48373edd941c2e773 Mon Sep 17 00:00:00 2001 From: Paul Adenot Date: Tue, 20 Mar 2018 18:22:08 +0100 Subject: [PATCH] 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 --HG-- extra : rebase_source : 52d0b6a3b054238c79f1b224d6cbfcbaec743a67 extra : source : 14929579ba3f71f14c9d81b6ed88563d35da11e0 --- dom/media/MediaStreamGraph.cpp | 13 +++ dom/media/MediaStreamGraph.h | 7 ++ dom/media/Tracing.cpp | 96 ++++++++++++++++++++++ dom/media/Tracing.h | 140 +++++++++++++++++++++++++++++++++ dom/media/moz.build | 4 + 5 files changed, 260 insertions(+) create mode 100644 dom/media/Tracing.cpp create mode 100644 dom/media/Tracing.h diff --git a/dom/media/MediaStreamGraph.cpp b/dom/media/MediaStreamGraph.cpp index 76e518ce0d0a..2651813b4f0a 100644 --- a/dom/media/MediaStreamGraph.cpp +++ b/dom/media/MediaStreamGraph.cpp @@ -32,6 +32,7 @@ #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" @@ -41,6 +42,8 @@ using namespace mozilla::dom; using namespace mozilla::gfx; using namespace mozilla::media; +mozilla::AsyncLogger gMSGTraceLogger("MSGTracing"); + namespace mozilla { LazyLogModule gMediaStreamGraphLog("MediaStreamGraph"); @@ -68,6 +71,10 @@ MediaStreamGraphImpl::~MediaStreamGraphImpl() "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 @@ -3614,6 +3621,12 @@ MediaStreamGraphImpl::MediaStreamGraphImpl(GraphDriverType aDriverRequested, } 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); } diff --git a/dom/media/MediaStreamGraph.h b/dom/media/MediaStreamGraph.h index 5f9dca39db9c..55e3684d0caf 100644 --- a/dom/media/MediaStreamGraph.h +++ b/dom/media/MediaStreamGraph.h @@ -25,6 +25,13 @@ class nsIRunnable; class nsIGlobalObject; class nsPIDOMWindowInner; +namespace mozilla { + class AsyncLogger; +}; + +extern mozilla::AsyncLogger gMSGTraceLogger; + + template <> class nsAutoRefTraits : public nsPointerRefTraits { diff --git a/dom/media/Tracing.cpp b/dom/media/Tracing.cpp new file mode 100644 index 000000000000..9770c4f90539 --- /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 +#include + +#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(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(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); + } +} diff --git a/dom/media/Tracing.h b/dom/media/Tracing.h new file mode 100644 index 000000000000..ece7a3dce386 --- /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 + +#include "AsyncLogger.h" + +#include + +#if defined(_WIN32) +#include +#define getpid() _getpid() +#else +#include +#endif + +#if defined(__FUNCSIG__) +// 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::this_thread::get_id())); + #define TRACE_COMMENT(aComment) \ + AutoTracer trace(gMSGTraceLogger, FUNCTION_SIGNATURE, getpid(), \ + std::hash{}(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 */ diff --git a/dom/media/moz.build b/dom/media/moz.build index 5fe6ac6207ba..7dd983eb8939 100644 --- a/dom/media/moz.build +++ b/dom/media/moz.build @@ -89,6 +89,7 @@ XPIDL_MODULE = 'dom_media' EXPORTS += [ 'ADTSDecoder.h', 'ADTSDemuxer.h', + 'AsyncLogger.h', 'AudioBufferUtils.h', 'AudioChannelFormat.h', 'AudioCompactor.h', @@ -154,6 +155,7 @@ EXPORTS += [ 'StreamTracks.h', 'ThreadPoolCOMListener.h', 'TimeUnits.h', + 'Tracing.h', 'TrackID.h', 'TrackUnionStream.h', 'VideoFrameContainer.h', @@ -265,6 +267,7 @@ UNIFIED_SOURCES += [ 'TextTrackCueList.cpp', 'TextTrackList.cpp', 'TextTrackRegion.cpp', + 'Tracing.cpp', 'TrackUnionStream.cpp', 'VideoFrameContainer.cpp', 'VideoPlaybackQuality.cpp', @@ -328,6 +331,7 @@ if CONFIG['MOZ_WEBRTC']: ] DEFINES['MOZILLA_INTERNAL_API'] = True +DEFINES['TRACING'] = True if CONFIG['MOZ_ANDROID_HLS_SUPPORT']: DEFINES['MOZ_ANDROID_HLS_SUPPORT'] = True