1.1 --- /dev/null Thu Jan 01 00:00:00 1970 +0000
1.2 +++ b/content/media/Latency.cpp Wed Dec 31 06:09:35 2014 +0100
1.3 @@ -0,0 +1,228 @@
1.4 +/* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
1.5 +/* vim:set ts=2 sw=2 sts=2 et cindent: */
1.6 +/* This Source Code Form is subject to the terms of the Mozilla Public
1.7 + * License, v. 2.0. If a copy of the MPL was not distributed with this
1.8 + * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
1.9 +
1.10 +// We want this available in opt builds
1.11 +#define FORCE_PR_LOG
1.12 +
1.13 +#include "Latency.h"
1.14 +#include "nsThreadUtils.h"
1.15 +#include "prlog.h"
1.16 +#include <cmath>
1.17 +#include <algorithm>
1.18 +
1.19 +#include <mozilla/Services.h>
1.20 +#include <mozilla/StaticPtr.h>
1.21 +#include "nsContentUtils.h"
1.22 +
1.23 +using namespace mozilla;
1.24 +
1.25 +const char* LatencyLogIndex2Strings[] = {
1.26 + "Audio MediaStreamTrack",
1.27 + "Video MediaStreamTrack",
1.28 + "Cubeb",
1.29 + "AudioStream",
1.30 + "NetEQ",
1.31 + "AudioCapture Base",
1.32 + "AudioCapture Samples",
1.33 + "AudioTrackInsertion",
1.34 + "MediaPipeline Audio Insertion",
1.35 + "AudioTransmit",
1.36 + "AudioReceive",
1.37 + "MediaPipelineAudioPlayout",
1.38 + "MediaStream Create",
1.39 + "AudioStream Create",
1.40 + "AudioSendRTP",
1.41 + "AudioRecvRTP"
1.42 +};
1.43 +
1.44 +static StaticRefPtr<AsyncLatencyLogger> gAsyncLogger;
1.45 +
1.46 +PRLogModuleInfo*
1.47 +GetLatencyLog()
1.48 +{
1.49 + static PRLogModuleInfo* sLog;
1.50 + if (!sLog) {
1.51 + sLog = PR_NewLogModule("MediaLatency");
1.52 + }
1.53 + return sLog;
1.54 +}
1.55 +
1.56 +
1.57 +class LogEvent : public nsRunnable
1.58 +{
1.59 +public:
1.60 + LogEvent(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue,
1.61 + TimeStamp aTimeStamp) :
1.62 + mIndex(aIndex),
1.63 + mID(aID),
1.64 + mValue(aValue),
1.65 + mTimeStamp(aTimeStamp)
1.66 + {}
1.67 + LogEvent(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue) :
1.68 + mIndex(aIndex),
1.69 + mID(aID),
1.70 + mValue(aValue),
1.71 + mTimeStamp(TimeStamp())
1.72 + {}
1.73 + ~LogEvent() {}
1.74 +
1.75 + NS_IMETHOD Run() {
1.76 + AsyncLatencyLogger::Get(true)->WriteLog(mIndex, mID, mValue, mTimeStamp);
1.77 + return NS_OK;
1.78 + }
1.79 +
1.80 +protected:
1.81 + AsyncLatencyLogger::LatencyLogIndex mIndex;
1.82 + uint64_t mID;
1.83 + int64_t mValue;
1.84 + TimeStamp mTimeStamp;
1.85 +};
1.86 +
1.87 +void LogLatency(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
1.88 +{
1.89 + AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue);
1.90 +}
1.91 +
1.92 +void LogTime(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
1.93 +{
1.94 + TimeStamp now = TimeStamp::Now();
1.95 + AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue, now);
1.96 +}
1.97 +
1.98 +void LogTime(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
1.99 +{
1.100 + AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue, aTime);
1.101 +}
1.102 +
1.103 +void LogTime(uint32_t aIndex, uint64_t aID, int64_t aValue)
1.104 +{
1.105 + LogTime(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue);
1.106 +}
1.107 +void LogTime(uint32_t aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
1.108 +{
1.109 + LogTime(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue, aTime);
1.110 +}
1.111 +void LogLatency(uint32_t aIndex, uint64_t aID, int64_t aValue)
1.112 +{
1.113 + LogLatency(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue);
1.114 +}
1.115 +
1.116 +/* static */
1.117 +void AsyncLatencyLogger::InitializeStatics()
1.118 +{
1.119 + NS_ASSERTION(NS_IsMainThread(), "Main thread only");
1.120 + GetLatencyLog();
1.121 + gAsyncLogger = new AsyncLatencyLogger();
1.122 +}
1.123 +
1.124 +/* static */
1.125 +void AsyncLatencyLogger::ShutdownLogger()
1.126 +{
1.127 + gAsyncLogger = nullptr;
1.128 +}
1.129 +
1.130 +/* static */
1.131 +AsyncLatencyLogger* AsyncLatencyLogger::Get(bool aStartTimer)
1.132 +{
1.133 + // Users don't generally null-check the result since we should live longer than they
1.134 + MOZ_ASSERT(gAsyncLogger);
1.135 +
1.136 + if (aStartTimer) {
1.137 + gAsyncLogger->Init();
1.138 + }
1.139 + return gAsyncLogger;
1.140 +}
1.141 +
1.142 +NS_IMPL_ISUPPORTS(AsyncLatencyLogger, nsIObserver)
1.143 +
1.144 +AsyncLatencyLogger::AsyncLatencyLogger()
1.145 + : mThread(nullptr),
1.146 + mMutex("AsyncLatencyLogger")
1.147 +{
1.148 + NS_ASSERTION(NS_IsMainThread(), "Main thread only");
1.149 + nsContentUtils::RegisterShutdownObserver(this);
1.150 +}
1.151 +
1.152 +AsyncLatencyLogger::~AsyncLatencyLogger()
1.153 +{
1.154 + AsyncLatencyLogger::Shutdown();
1.155 +}
1.156 +
1.157 +void AsyncLatencyLogger::Shutdown()
1.158 +{
1.159 + nsContentUtils::UnregisterShutdownObserver(this);
1.160 +
1.161 + MutexAutoLock lock(mMutex);
1.162 + if (mThread) {
1.163 + mThread->Shutdown();
1.164 + }
1.165 + mStart = TimeStamp(); // make sure we don't try to restart it for any reason
1.166 +}
1.167 +
1.168 +void AsyncLatencyLogger::Init()
1.169 +{
1.170 + MutexAutoLock lock(mMutex);
1.171 + if (mStart.IsNull()) {
1.172 + nsresult rv = NS_NewNamedThread("Latency Logger", getter_AddRefs(mThread));
1.173 + NS_ENSURE_SUCCESS_VOID(rv);
1.174 + mStart = TimeStamp::Now();
1.175 + }
1.176 +}
1.177 +
1.178 +void AsyncLatencyLogger::GetStartTime(TimeStamp &aStart)
1.179 +{
1.180 + MutexAutoLock lock(mMutex);
1.181 + aStart = mStart;
1.182 +}
1.183 +
1.184 +nsresult
1.185 +AsyncLatencyLogger::Observe(nsISupports* aSubject, const char* aTopic,
1.186 + const char16_t* aData)
1.187 +{
1.188 + MOZ_ASSERT(NS_IsMainThread());
1.189 + if (strcmp(aTopic, NS_XPCOM_SHUTDOWN_OBSERVER_ID) == 0) {
1.190 + Shutdown();
1.191 + }
1.192 + return NS_OK;
1.193 +}
1.194 +
1.195 +// aID is a sub-identifier (in particular a specific MediaStramTrack)
1.196 +void AsyncLatencyLogger::WriteLog(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue,
1.197 + TimeStamp aTimeStamp)
1.198 +{
1.199 + if (aTimeStamp.IsNull()) {
1.200 + PR_LOG(GetLatencyLog(), PR_LOG_DEBUG,
1.201 + ("Latency: %s,%llu,%lld,%lld",
1.202 + LatencyLogIndex2Strings[aIndex], aID, GetTimeStamp(), aValue));
1.203 + } else {
1.204 + PR_LOG(GetLatencyLog(), PR_LOG_DEBUG,
1.205 + ("Latency: %s,%llu,%lld,%lld,%lld",
1.206 + LatencyLogIndex2Strings[aIndex], aID, GetTimeStamp(), aValue,
1.207 + static_cast<int64_t>((aTimeStamp - gAsyncLogger->mStart).ToMilliseconds())));
1.208 + }
1.209 +}
1.210 +
1.211 +int64_t AsyncLatencyLogger::GetTimeStamp()
1.212 +{
1.213 + TimeDuration t = TimeStamp::Now() - mStart;
1.214 + return t.ToMilliseconds();
1.215 +}
1.216 +
1.217 +void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
1.218 +{
1.219 + TimeStamp null;
1.220 + Log(aIndex, aID, aValue, null);
1.221 +}
1.222 +
1.223 +void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
1.224 +{
1.225 + if (PR_LOG_TEST(GetLatencyLog(), PR_LOG_DEBUG)) {
1.226 + nsCOMPtr<nsIRunnable> event = new LogEvent(aIndex, aID, aValue, aTime);
1.227 + if (mThread) {
1.228 + mThread->Dispatch(event, NS_DISPATCH_NORMAL);
1.229 + }
1.230 + }
1.231 +}
