michael@0: /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
michael@0: /* vim:set ts=2 sw=2 sts=2 et cindent: */
michael@0: /* This Source Code Form is subject to the terms of the Mozilla Public
michael@0:  * License, v. 2.0. If a copy of the MPL was not distributed with this
michael@0:  * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
michael@0: 
michael@0: // We want this available in opt builds
michael@0: #define FORCE_PR_LOG
michael@0: 
michael@0: #include "Latency.h"
michael@0: #include "nsThreadUtils.h"
michael@0: #include "prlog.h"
michael@0: #include <cmath>
michael@0: #include <algorithm>
michael@0: 
michael@0: #include <mozilla/Services.h>
michael@0: #include <mozilla/StaticPtr.h>
michael@0: #include "nsContentUtils.h"
michael@0: 
michael@0: using namespace mozilla;
michael@0: 
michael@0: const char* LatencyLogIndex2Strings[] = {
michael@0:   "Audio MediaStreamTrack",
michael@0:   "Video MediaStreamTrack",
michael@0:   "Cubeb",
michael@0:   "AudioStream",
michael@0:   "NetEQ",
michael@0:   "AudioCapture Base",
michael@0:   "AudioCapture Samples",
michael@0:   "AudioTrackInsertion",
michael@0:   "MediaPipeline Audio Insertion",
michael@0:   "AudioTransmit",
michael@0:   "AudioReceive",
michael@0:   "MediaPipelineAudioPlayout",
michael@0:   "MediaStream Create",
michael@0:   "AudioStream Create",
michael@0:   "AudioSendRTP",
michael@0:   "AudioRecvRTP"
michael@0: };
michael@0: 
michael@0: static StaticRefPtr<AsyncLatencyLogger> gAsyncLogger;
michael@0: 
michael@0: PRLogModuleInfo*
michael@0: GetLatencyLog()
michael@0: {
michael@0:   static PRLogModuleInfo* sLog;
michael@0:   if (!sLog) {
michael@0:     sLog = PR_NewLogModule("MediaLatency");
michael@0:   }
michael@0:   return sLog;
michael@0: }
michael@0: 
michael@0: 
michael@0: class LogEvent : public nsRunnable
michael@0: {
michael@0: public:
michael@0:   LogEvent(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue,
michael@0:            TimeStamp aTimeStamp) :
michael@0:     mIndex(aIndex),
michael@0:     mID(aID),
michael@0:     mValue(aValue),
michael@0:     mTimeStamp(aTimeStamp)
michael@0:   {}
michael@0:   LogEvent(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue) :
michael@0:     mIndex(aIndex),
michael@0:     mID(aID),
michael@0:     mValue(aValue),
michael@0:     mTimeStamp(TimeStamp())
michael@0:   {}
michael@0:   ~LogEvent() {}
michael@0: 
michael@0:   NS_IMETHOD Run() {
michael@0:     AsyncLatencyLogger::Get(true)->WriteLog(mIndex, mID, mValue, mTimeStamp);
michael@0:     return NS_OK;
michael@0:   }
michael@0: 
michael@0: protected:
michael@0:   AsyncLatencyLogger::LatencyLogIndex mIndex;
michael@0:   uint64_t mID;
michael@0:   int64_t mValue;
michael@0:   TimeStamp mTimeStamp;
michael@0: };
michael@0: 
michael@0: void LogLatency(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
michael@0: {
michael@0:   AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue);
michael@0: }
michael@0: 
michael@0: void LogTime(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
michael@0: {
michael@0:   TimeStamp now = TimeStamp::Now();
michael@0:   AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue, now);
michael@0: }
michael@0: 
michael@0: void LogTime(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
michael@0: {
michael@0:   AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue, aTime);
michael@0: }
michael@0: 
michael@0: void LogTime(uint32_t aIndex, uint64_t aID, int64_t aValue)
michael@0: {
michael@0:   LogTime(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue);
michael@0: }
michael@0: void LogTime(uint32_t aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
michael@0: {
michael@0:   LogTime(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue, aTime);
michael@0: }
michael@0: void LogLatency(uint32_t aIndex, uint64_t aID, int64_t aValue)
michael@0: {
michael@0:   LogLatency(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue);
michael@0: }
michael@0: 
michael@0: /* static */
michael@0: void AsyncLatencyLogger::InitializeStatics()
michael@0: {
michael@0:   NS_ASSERTION(NS_IsMainThread(), "Main thread only");
michael@0:   GetLatencyLog();
michael@0:   gAsyncLogger = new AsyncLatencyLogger();
michael@0: }
michael@0: 
michael@0: /* static */
michael@0: void AsyncLatencyLogger::ShutdownLogger()
michael@0: {
michael@0:   gAsyncLogger = nullptr;
michael@0: }
michael@0: 
michael@0: /* static */
michael@0: AsyncLatencyLogger* AsyncLatencyLogger::Get(bool aStartTimer)
michael@0: {
michael@0:   // Users don't generally null-check the result since we should live longer than they
michael@0:   MOZ_ASSERT(gAsyncLogger);
michael@0: 
michael@0:   if (aStartTimer) {
michael@0:     gAsyncLogger->Init();
michael@0:   }
michael@0:   return gAsyncLogger;
michael@0: }
michael@0: 
michael@0: NS_IMPL_ISUPPORTS(AsyncLatencyLogger, nsIObserver)
michael@0: 
michael@0: AsyncLatencyLogger::AsyncLatencyLogger()
michael@0:   : mThread(nullptr),
michael@0:     mMutex("AsyncLatencyLogger")
michael@0: {
michael@0:   NS_ASSERTION(NS_IsMainThread(), "Main thread only");
michael@0:   nsContentUtils::RegisterShutdownObserver(this);
michael@0: }
michael@0: 
michael@0: AsyncLatencyLogger::~AsyncLatencyLogger()
michael@0: {
michael@0:   AsyncLatencyLogger::Shutdown();
michael@0: }
michael@0: 
michael@0: void AsyncLatencyLogger::Shutdown()
michael@0: {
michael@0:   nsContentUtils::UnregisterShutdownObserver(this);
michael@0: 
michael@0:   MutexAutoLock lock(mMutex);
michael@0:   if (mThread) {
michael@0:     mThread->Shutdown();
michael@0:   }
michael@0:   mStart = TimeStamp(); // make sure we don't try to restart it for any reason
michael@0: }
michael@0: 
michael@0: void AsyncLatencyLogger::Init()
michael@0: {
michael@0:   MutexAutoLock lock(mMutex);
michael@0:   if (mStart.IsNull()) {
michael@0:     nsresult rv = NS_NewNamedThread("Latency Logger", getter_AddRefs(mThread));
michael@0:     NS_ENSURE_SUCCESS_VOID(rv);
michael@0:     mStart = TimeStamp::Now();
michael@0:   }
michael@0: }
michael@0: 
michael@0: void AsyncLatencyLogger::GetStartTime(TimeStamp &aStart)
michael@0: {
michael@0:   MutexAutoLock lock(mMutex);
michael@0:   aStart = mStart;
michael@0: }
michael@0: 
michael@0: nsresult
michael@0: AsyncLatencyLogger::Observe(nsISupports* aSubject, const char* aTopic,
michael@0:                             const char16_t* aData)
michael@0: {
michael@0:   MOZ_ASSERT(NS_IsMainThread());
michael@0:   if (strcmp(aTopic, NS_XPCOM_SHUTDOWN_OBSERVER_ID) == 0) {
michael@0:     Shutdown();
michael@0:   }
michael@0:   return NS_OK;
michael@0: }
michael@0: 
michael@0: // aID is a sub-identifier (in particular a specific MediaStramTrack)
michael@0: void AsyncLatencyLogger::WriteLog(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue,
michael@0:                                   TimeStamp aTimeStamp)
michael@0: {
michael@0:   if (aTimeStamp.IsNull()) {
michael@0:     PR_LOG(GetLatencyLog(), PR_LOG_DEBUG,
michael@0:       ("Latency: %s,%llu,%lld,%lld",
michael@0:        LatencyLogIndex2Strings[aIndex], aID, GetTimeStamp(), aValue));
michael@0:   } else {
michael@0:     PR_LOG(GetLatencyLog(), PR_LOG_DEBUG,
michael@0:       ("Latency: %s,%llu,%lld,%lld,%lld",
michael@0:        LatencyLogIndex2Strings[aIndex], aID, GetTimeStamp(), aValue,
michael@0:        static_cast<int64_t>((aTimeStamp - gAsyncLogger->mStart).ToMilliseconds())));
michael@0:   }
michael@0: }
michael@0: 
michael@0: int64_t AsyncLatencyLogger::GetTimeStamp()
michael@0: {
michael@0:   TimeDuration t = TimeStamp::Now() - mStart;
michael@0:   return t.ToMilliseconds();
michael@0: }
michael@0: 
michael@0: void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
michael@0: {
michael@0:   TimeStamp null;
michael@0:   Log(aIndex, aID, aValue, null);
michael@0: }
michael@0: 
michael@0: void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
michael@0: {
michael@0:   if (PR_LOG_TEST(GetLatencyLog(), PR_LOG_DEBUG)) {
michael@0:     nsCOMPtr<nsIRunnable> event = new LogEvent(aIndex, aID, aValue, aTime);
michael@0:     if (mThread) {
michael@0:       mThread->Dispatch(event, NS_DISPATCH_NORMAL);
michael@0:     }
michael@0:   }
michael@0: }