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
This commit is contained in:
Paul Adenot 2018-03-20 18:22:08 +01:00
Родитель df3ccd19c4
Коммит 7e374f59ca
5 изменённых файлов: 260 добавлений и 0 удалений

Просмотреть файл

@ -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);
}

Просмотреть файл

@ -25,6 +25,13 @@ class nsIRunnable;
class nsIGlobalObject;
class nsPIDOMWindowInner;
namespace mozilla {
class AsyncLogger;
};
extern mozilla::AsyncLogger gMSGTraceLogger;
template <>
class nsAutoRefTraits<SpeexResamplerState> : public nsPointerRefTraits<SpeexResamplerState>
{

96
dom/media/Tracing.cpp Normal file
Просмотреть файл

@ -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);
}
}

140
dom/media/Tracing.h Normal file
Просмотреть файл

@ -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(__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::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 */

Просмотреть файл

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