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