Line data Source code
1 : /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
2 : /* vim:set ts=2 sw=2 sts=2 et cindent: */
3 : /* This Source Code Form is subject to the terms of the Mozilla Public
4 : * License, v. 2.0. If a copy of the MPL was not distributed with this
5 : * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
6 :
7 : #include "Latency.h"
8 : #include "nsThreadUtils.h"
9 : #include "mozilla/Logging.h"
10 : #include <cmath>
11 : #include <algorithm>
12 :
13 : #include <mozilla/Services.h>
14 : #include <mozilla/StaticPtr.h>
15 : #include "nsContentUtils.h"
16 :
17 : using namespace mozilla;
18 :
19 : const char* LatencyLogIndex2Strings[] = {
20 : "Audio MediaStreamTrack",
21 : "Video MediaStreamTrack",
22 : "Cubeb",
23 : "AudioStream",
24 : "NetEQ",
25 : "AudioCapture Base",
26 : "AudioCapture Samples",
27 : "AudioTrackInsertion",
28 : "MediaPipeline Audio Insertion",
29 : "AudioTransmit",
30 : "AudioReceive",
31 : "MediaPipelineAudioPlayout",
32 : "MediaStream Create",
33 : "AudioStream Create",
34 : "AudioSendRTP",
35 : "AudioRecvRTP"
36 : };
37 :
38 3 : static StaticRefPtr<AsyncLatencyLogger> gAsyncLogger;
39 :
40 : LogModule*
41 3 : GetLatencyLog()
42 : {
43 : static LazyLogModule sLog("MediaLatency");
44 3 : return sLog;
45 : }
46 :
47 : class LogEvent : public Runnable
48 : {
49 : public:
50 0 : LogEvent(AsyncLatencyLogger::LatencyLogIndex aIndex,
51 : uint64_t aID,
52 : int64_t aValue,
53 : TimeStamp aTimeStamp)
54 0 : : mozilla::Runnable("LogEvent")
55 : , mIndex(aIndex)
56 : , mID(aID)
57 : , mValue(aValue)
58 0 : , mTimeStamp(aTimeStamp)
59 0 : {}
60 : LogEvent(AsyncLatencyLogger::LatencyLogIndex aIndex,
61 : uint64_t aID,
62 : int64_t aValue)
63 : : mozilla::Runnable("LogEvent")
64 : , mIndex(aIndex)
65 : , mID(aID)
66 : , mValue(aValue)
67 : , mTimeStamp(TimeStamp())
68 : {}
69 0 : ~LogEvent() {}
70 :
71 0 : NS_IMETHOD Run() override {
72 0 : AsyncLatencyLogger::Get(true)->WriteLog(mIndex, mID, mValue, mTimeStamp);
73 0 : return NS_OK;
74 : }
75 :
76 : protected:
77 : AsyncLatencyLogger::LatencyLogIndex mIndex;
78 : uint64_t mID;
79 : int64_t mValue;
80 : TimeStamp mTimeStamp;
81 : };
82 :
83 0 : void LogLatency(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
84 : {
85 0 : AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue);
86 0 : }
87 :
88 0 : void LogTime(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
89 : {
90 0 : TimeStamp now = TimeStamp::Now();
91 0 : AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue, now);
92 0 : }
93 :
94 0 : void LogTime(AsyncLatencyLogger::LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
95 : {
96 0 : AsyncLatencyLogger::Get()->Log(aIndex, aID, aValue, aTime);
97 0 : }
98 :
99 0 : void LogTime(uint32_t aIndex, uint64_t aID, int64_t aValue)
100 : {
101 0 : LogTime(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue);
102 0 : }
103 0 : void LogTime(uint32_t aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
104 : {
105 0 : LogTime(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue, aTime);
106 0 : }
107 0 : void LogLatency(uint32_t aIndex, uint64_t aID, int64_t aValue)
108 : {
109 0 : LogLatency(static_cast<AsyncLatencyLogger::LatencyLogIndex>(aIndex), aID, aValue);
110 0 : }
111 :
112 : /* static */
113 3 : void AsyncLatencyLogger::InitializeStatics()
114 : {
115 3 : NS_ASSERTION(NS_IsMainThread(), "Main thread only");
116 :
117 : //Make sure that the underlying logger is allocated.
118 3 : GetLatencyLog();
119 3 : gAsyncLogger = new AsyncLatencyLogger();
120 3 : }
121 :
122 : /* static */
123 0 : void AsyncLatencyLogger::ShutdownLogger()
124 : {
125 0 : gAsyncLogger = nullptr;
126 0 : }
127 :
128 : /* static */
129 0 : AsyncLatencyLogger* AsyncLatencyLogger::Get(bool aStartTimer)
130 : {
131 : // Users don't generally null-check the result since we should live longer than they
132 0 : MOZ_ASSERT(gAsyncLogger);
133 :
134 0 : if (aStartTimer) {
135 0 : gAsyncLogger->Init();
136 : }
137 0 : return gAsyncLogger;
138 : }
139 :
140 6 : NS_IMPL_ISUPPORTS(AsyncLatencyLogger, nsIObserver)
141 :
142 3 : AsyncLatencyLogger::AsyncLatencyLogger()
143 : : mThread(nullptr),
144 3 : mMutex("AsyncLatencyLogger")
145 : {
146 3 : NS_ASSERTION(NS_IsMainThread(), "Main thread only");
147 3 : nsContentUtils::RegisterShutdownObserver(this);
148 3 : }
149 :
150 0 : AsyncLatencyLogger::~AsyncLatencyLogger()
151 : {
152 0 : AsyncLatencyLogger::Shutdown();
153 0 : }
154 :
155 0 : void AsyncLatencyLogger::Shutdown()
156 : {
157 0 : nsContentUtils::UnregisterShutdownObserver(this);
158 :
159 0 : MutexAutoLock lock(mMutex);
160 0 : if (mThread) {
161 0 : mThread->Shutdown();
162 : }
163 0 : mStart = TimeStamp(); // make sure we don't try to restart it for any reason
164 0 : }
165 :
166 0 : void AsyncLatencyLogger::Init()
167 : {
168 0 : MutexAutoLock lock(mMutex);
169 0 : if (mStart.IsNull()) {
170 0 : nsresult rv = NS_NewNamedThread("Latency Logger", getter_AddRefs(mThread));
171 0 : NS_ENSURE_SUCCESS_VOID(rv);
172 0 : mStart = TimeStamp::Now();
173 : }
174 : }
175 :
176 0 : void AsyncLatencyLogger::GetStartTime(TimeStamp &aStart)
177 : {
178 0 : MutexAutoLock lock(mMutex);
179 0 : aStart = mStart;
180 0 : }
181 :
182 : nsresult
183 0 : AsyncLatencyLogger::Observe(nsISupports* aSubject, const char* aTopic,
184 : const char16_t* aData)
185 : {
186 0 : MOZ_ASSERT(NS_IsMainThread());
187 0 : if (strcmp(aTopic, NS_XPCOM_SHUTDOWN_OBSERVER_ID) == 0) {
188 0 : Shutdown();
189 : }
190 0 : return NS_OK;
191 : }
192 :
193 : // aID is a sub-identifier (in particular a specific MediaStramTrack)
194 0 : void AsyncLatencyLogger::WriteLog(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue,
195 : TimeStamp aTimeStamp)
196 : {
197 0 : if (aTimeStamp.IsNull()) {
198 0 : MOZ_LOG(GetLatencyLog(), LogLevel::Debug,
199 : ("Latency: %s,%" PRIu64 ",%" PRId64 ",%" PRId64,
200 : LatencyLogIndex2Strings[aIndex], aID, GetTimeStamp(), aValue));
201 : } else {
202 0 : MOZ_LOG(GetLatencyLog(), LogLevel::Debug,
203 : ("Latency: %s,%" PRIu64 ",%" PRId64 ",%" PRId64 ",%" PRId64,
204 : LatencyLogIndex2Strings[aIndex], aID, GetTimeStamp(), aValue,
205 : static_cast<int64_t>((aTimeStamp - gAsyncLogger->mStart).ToMilliseconds())));
206 : }
207 0 : }
208 :
209 0 : int64_t AsyncLatencyLogger::GetTimeStamp()
210 : {
211 0 : TimeDuration t = TimeStamp::Now() - mStart;
212 0 : return t.ToMilliseconds();
213 : }
214 :
215 0 : void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue)
216 : {
217 0 : TimeStamp null;
218 0 : Log(aIndex, aID, aValue, null);
219 0 : }
220 :
221 0 : void AsyncLatencyLogger::Log(LatencyLogIndex aIndex, uint64_t aID, int64_t aValue, TimeStamp &aTime)
222 : {
223 0 : if (MOZ_LOG_TEST(GetLatencyLog(), LogLevel::Debug)) {
224 0 : nsCOMPtr<nsIRunnable> event = new LogEvent(aIndex, aID, aValue, aTime);
225 0 : if (mThread) {
226 0 : mThread->Dispatch(event, NS_DISPATCH_NORMAL);
227 : }
228 : }
229 0 : }
|
