1 /* -*- Mode: C++; tab-width: 2; indent-tabs-mode: nil; c-basic-offset: 2 -*- */
2 /* vim: set ts=8 sts=2 et sw=2 tw=80: */
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 // This file tests a lot of the profiler_*() functions in GeckoProfiler.h.
8 // Most of the tests just check that nothing untoward (e.g. crashes, deadlocks)
9 // happens when calling these functions. They don't do much inspection of
10 // profiler internals.
11
12 #include "GeckoProfiler.h"
13 #include "platform.h"
14 #include "ProfileBuffer.h"
15 #include "ProfileJSONWriter.h"
16 #include "ProfilerMarkerPayload.h"
17
18 #include "js/Initialization.h"
19 #include "js/Printf.h"
20 #include "jsapi.h"
21 #include "json/json.h"
22 #include "mozilla/Atomics.h"
23 #include "mozilla/BlocksRingBuffer.h"
24 #include "mozilla/ProfileBufferEntrySerializationGeckoExtensions.h"
25 #include "mozilla/UniquePtrExtensions.h"
26 #include "mozilla/net/HttpBaseChannel.h"
27 #include "nsIThread.h"
28 #include "nsThreadUtils.h"
29
30 #include "gtest/gtest.h"
31
32 #include <cstring>
33
34 // Note: profiler_init() has already been called in XRE_main(), so we can't
35 // test it here. Likewise for profiler_shutdown(), and AutoProfilerInit
36 // (which is just an RAII wrapper for profiler_init() and profiler_shutdown()).
37
38 using namespace mozilla;
39
TEST(BaseProfiler,BlocksRingBuffer)40 TEST(BaseProfiler, BlocksRingBuffer)
41 {
42 constexpr uint32_t MBSize = 256;
43 uint8_t buffer[MBSize * 3];
44 for (size_t i = 0; i < MBSize * 3; ++i) {
45 buffer[i] = uint8_t('A' + i);
46 }
47 BlocksRingBuffer rb(BlocksRingBuffer::ThreadSafety::WithMutex,
48 &buffer[MBSize], MakePowerOfTwo32<MBSize>());
49
50 {
51 nsCString cs(NS_LITERAL_CSTRING("nsCString"));
52 nsString s(NS_LITERAL_STRING("nsString"));
53 nsAutoCString acs(NS_LITERAL_CSTRING("nsAutoCString"));
54 nsAutoString as(NS_LITERAL_STRING("nsAutoString"));
55 nsAutoCStringN<8> acs8(NS_LITERAL_CSTRING("nsAutoCStringN"));
56 nsAutoStringN<8> as8(NS_LITERAL_STRING("nsAutoStringN"));
57 JS::UniqueChars jsuc = JS_smprintf("%s", "JS::UniqueChars");
58
59 rb.PutObjects(cs, s, acs, as, acs8, as8, jsuc);
60 }
61
62 rb.ReadEach([](ProfileBufferEntryReader& aER) {
63 ASSERT_EQ(aER.ReadObject<nsCString>(), NS_LITERAL_CSTRING("nsCString"));
64 ASSERT_EQ(aER.ReadObject<nsString>(), NS_LITERAL_STRING("nsString"));
65 ASSERT_EQ(aER.ReadObject<nsAutoCString>(),
66 NS_LITERAL_CSTRING("nsAutoCString"));
67 ASSERT_EQ(aER.ReadObject<nsAutoString>(),
68 NS_LITERAL_STRING("nsAutoString"));
69 ASSERT_EQ(aER.ReadObject<nsAutoCStringN<8>>(),
70 NS_LITERAL_CSTRING("nsAutoCStringN"));
71 ASSERT_EQ(aER.ReadObject<nsAutoStringN<8>>(),
72 NS_LITERAL_STRING("nsAutoStringN"));
73 auto jsuc2 = aER.ReadObject<JS::UniqueChars>();
74 ASSERT_TRUE(!!jsuc2);
75 ASSERT_TRUE(strcmp(jsuc2.get(), "JS::UniqueChars") == 0);
76 });
77
78 // Everything around the sub-buffer should be unchanged.
79 for (size_t i = 0; i < MBSize; ++i) {
80 ASSERT_EQ(buffer[i], uint8_t('A' + i));
81 }
82 for (size_t i = MBSize * 2; i < MBSize * 3; ++i) {
83 ASSERT_EQ(buffer[i], uint8_t('A' + i));
84 }
85 }
86
87 typedef Vector<const char*> StrVec;
88
InactiveFeaturesAndParamsCheck()89 static void InactiveFeaturesAndParamsCheck() {
90 int entries;
91 Maybe<double> duration;
92 double interval;
93 uint32_t features;
94 StrVec filters;
95 uint64_t activeBrowsingContextID;
96
97 ASSERT_TRUE(!profiler_is_active());
98 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::MainThreadIO));
99 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::NativeAllocations));
100
101 profiler_get_start_params(&entries, &duration, &interval, &features, &filters,
102 &activeBrowsingContextID);
103
104 ASSERT_TRUE(entries == 0);
105 ASSERT_TRUE(duration == Nothing());
106 ASSERT_TRUE(interval == 0);
107 ASSERT_TRUE(features == 0);
108 ASSERT_TRUE(filters.empty());
109 ASSERT_TRUE(activeBrowsingContextID == 0);
110 }
111
ActiveParamsCheck(int aEntries,double aInterval,uint32_t aFeatures,const char ** aFilters,size_t aFiltersLen,uint64_t aActiveBrowsingContextID,const Maybe<double> & aDuration=Nothing ())112 static void ActiveParamsCheck(int aEntries, double aInterval,
113 uint32_t aFeatures, const char** aFilters,
114 size_t aFiltersLen,
115 uint64_t aActiveBrowsingContextID,
116 const Maybe<double>& aDuration = Nothing()) {
117 int entries;
118 Maybe<double> duration;
119 double interval;
120 uint32_t features;
121 StrVec filters;
122 uint64_t activeBrowsingContextID;
123
124 profiler_get_start_params(&entries, &duration, &interval, &features, &filters,
125 &activeBrowsingContextID);
126
127 ASSERT_TRUE(entries == aEntries);
128 ASSERT_TRUE(duration == aDuration);
129 ASSERT_TRUE(interval == aInterval);
130 ASSERT_TRUE(features == aFeatures);
131 ASSERT_TRUE(filters.length() == aFiltersLen);
132 ASSERT_TRUE(activeBrowsingContextID == aActiveBrowsingContextID);
133 for (size_t i = 0; i < aFiltersLen; i++) {
134 ASSERT_TRUE(strcmp(filters[i], aFilters[i]) == 0);
135 }
136 }
137
TEST(GeckoProfiler,FeaturesAndParams)138 TEST(GeckoProfiler, FeaturesAndParams)
139 {
140 InactiveFeaturesAndParamsCheck();
141
142 // Try a couple of features and filters.
143 {
144 uint32_t features = ProfilerFeature::JS | ProfilerFeature::Threads;
145 const char* filters[] = {"GeckoMain", "Compositor"};
146
147 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
148 features, filters, MOZ_ARRAY_LENGTH(filters), 100,
149 Some(PROFILER_DEFAULT_DURATION));
150
151 ASSERT_TRUE(profiler_is_active());
152 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::MainThreadIO));
153 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::IPCMessages));
154
155 ActiveParamsCheck(PROFILER_DEFAULT_ENTRIES.Value(),
156 PROFILER_DEFAULT_INTERVAL, features, filters,
157 MOZ_ARRAY_LENGTH(filters), 100,
158 Some(PROFILER_DEFAULT_DURATION));
159
160 profiler_stop();
161
162 InactiveFeaturesAndParamsCheck();
163 }
164
165 // Try some different features and filters.
166 {
167 uint32_t features =
168 ProfilerFeature::MainThreadIO | ProfilerFeature::IPCMessages;
169 const char* filters[] = {"GeckoMain", "Foo", "Bar"};
170
171 // Testing with some arbitrary buffer size (as could be provided by
172 // external code), which we convert to the appropriate power of 2.
173 profiler_start(PowerOfTwo32(999999), 3, features, filters,
174 MOZ_ARRAY_LENGTH(filters), 123, Some(25.0));
175
176 ASSERT_TRUE(profiler_is_active());
177 ASSERT_TRUE(profiler_feature_active(ProfilerFeature::MainThreadIO));
178 ASSERT_TRUE(profiler_feature_active(ProfilerFeature::IPCMessages));
179
180 // Profiler::Threads is added because filters has multiple entries.
181 ActiveParamsCheck(PowerOfTwo32(999999).Value(), 3,
182 features | ProfilerFeature::Threads, filters,
183 MOZ_ARRAY_LENGTH(filters), 123, Some(25.0));
184
185 profiler_stop();
186
187 InactiveFeaturesAndParamsCheck();
188 }
189
190 // Try with no duration
191 {
192 uint32_t features =
193 ProfilerFeature::MainThreadIO | ProfilerFeature::IPCMessages;
194 const char* filters[] = {"GeckoMain", "Foo", "Bar"};
195
196 profiler_start(PowerOfTwo32(999999), 3, features, filters,
197 MOZ_ARRAY_LENGTH(filters), 0, Nothing());
198
199 ASSERT_TRUE(profiler_is_active());
200 ASSERT_TRUE(profiler_feature_active(ProfilerFeature::MainThreadIO));
201 ASSERT_TRUE(profiler_feature_active(ProfilerFeature::IPCMessages));
202
203 // Profiler::Threads is added because filters has multiple entries.
204 ActiveParamsCheck(PowerOfTwo32(999999).Value(), 3,
205 features | ProfilerFeature::Threads, filters,
206 MOZ_ARRAY_LENGTH(filters), 0, Nothing());
207
208 profiler_stop();
209
210 InactiveFeaturesAndParamsCheck();
211 }
212
213 // Try all supported features, and filters that match all threads.
214 {
215 uint32_t availableFeatures = profiler_get_available_features();
216 const char* filters[] = {""};
217
218 profiler_start(PowerOfTwo32(88888), 10, availableFeatures, filters,
219 MOZ_ARRAY_LENGTH(filters), 0, Some(15.0));
220
221 ASSERT_TRUE(profiler_is_active());
222 ASSERT_TRUE(profiler_feature_active(ProfilerFeature::MainThreadIO));
223 ASSERT_TRUE(profiler_feature_active(ProfilerFeature::IPCMessages));
224
225 ActiveParamsCheck(PowerOfTwo32(88888).Value(), 10, availableFeatures,
226 filters, MOZ_ARRAY_LENGTH(filters), 0, Some(15.0));
227
228 // Don't call profiler_stop() here.
229 }
230
231 // Try no features, and filters that match no threads.
232 {
233 uint32_t features = 0;
234 const char* filters[] = {"NoThreadWillMatchThis"};
235
236 // Second profiler_start() call in a row without an intervening
237 // profiler_stop(); this will do an implicit profiler_stop() and restart.
238 profiler_start(PowerOfTwo32(0), 0, features, filters,
239 MOZ_ARRAY_LENGTH(filters), 0, Some(0.0));
240
241 ASSERT_TRUE(profiler_is_active());
242 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::MainThreadIO));
243 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::IPCMessages));
244
245 // Entries and intervals go to defaults if 0 is specified.
246 ActiveParamsCheck(PROFILER_DEFAULT_ENTRIES.Value(),
247 PROFILER_DEFAULT_INTERVAL,
248 features | ProfilerFeature::Threads, filters,
249 MOZ_ARRAY_LENGTH(filters), 0, Nothing());
250
251 profiler_stop();
252
253 InactiveFeaturesAndParamsCheck();
254
255 // These calls are no-ops.
256 profiler_stop();
257 profiler_stop();
258
259 InactiveFeaturesAndParamsCheck();
260 }
261 }
262
TEST(GeckoProfiler,EnsureStarted)263 TEST(GeckoProfiler, EnsureStarted)
264 {
265 InactiveFeaturesAndParamsCheck();
266
267 uint32_t features = ProfilerFeature::JS | ProfilerFeature::Threads;
268 const char* filters[] = {"GeckoMain", "Compositor"};
269 {
270 // Inactive -> Active
271 profiler_ensure_started(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
272 features, filters, MOZ_ARRAY_LENGTH(filters), 0,
273 Some(PROFILER_DEFAULT_DURATION));
274
275 ActiveParamsCheck(
276 PROFILER_DEFAULT_ENTRIES.Value(), PROFILER_DEFAULT_INTERVAL, features,
277 filters, MOZ_ARRAY_LENGTH(filters), 0, Some(PROFILER_DEFAULT_DURATION));
278 }
279
280 {
281 // Active -> Active with same settings
282
283 Maybe<ProfilerBufferInfo> info0 = profiler_get_buffer_info();
284 ASSERT_TRUE(info0->mRangeEnd > 0);
285
286 // First, write some samples into the buffer.
287 PR_Sleep(PR_MillisecondsToInterval(500));
288
289 Maybe<ProfilerBufferInfo> info1 = profiler_get_buffer_info();
290 ASSERT_TRUE(info1->mRangeEnd > info0->mRangeEnd);
291
292 // Call profiler_ensure_started with the same settings as before.
293 // This operation must not clear our buffer!
294 profiler_ensure_started(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
295 features, filters, MOZ_ARRAY_LENGTH(filters), 0,
296 Some(PROFILER_DEFAULT_DURATION));
297
298 ActiveParamsCheck(
299 PROFILER_DEFAULT_ENTRIES.Value(), PROFILER_DEFAULT_INTERVAL, features,
300 filters, MOZ_ARRAY_LENGTH(filters), 0, Some(PROFILER_DEFAULT_DURATION));
301
302 // Check that our position in the buffer stayed the same or advanced, but
303 // not by much, and the range-start after profiler_ensure_started shouldn't
304 // have passed the range-end before.
305 Maybe<ProfilerBufferInfo> info2 = profiler_get_buffer_info();
306 ASSERT_TRUE(info2->mRangeEnd >= info1->mRangeEnd);
307 ASSERT_TRUE(info2->mRangeEnd - info1->mRangeEnd <
308 info1->mRangeEnd - info0->mRangeEnd);
309 ASSERT_TRUE(info2->mRangeStart < info1->mRangeEnd);
310 }
311
312 {
313 // Active -> Active with *different* settings
314
315 Maybe<ProfilerBufferInfo> info1 = profiler_get_buffer_info();
316
317 // Call profiler_ensure_started with a different feature set than the one
318 // it's currently running with. This is supposed to stop and restart the
319 // profiler, thereby discarding the buffer contents.
320 uint32_t differentFeatures = features | ProfilerFeature::Leaf;
321 profiler_ensure_started(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
322 differentFeatures, filters,
323 MOZ_ARRAY_LENGTH(filters), 0);
324
325 ActiveParamsCheck(PROFILER_DEFAULT_ENTRIES.Value(),
326 PROFILER_DEFAULT_INTERVAL, differentFeatures, filters,
327 MOZ_ARRAY_LENGTH(filters), 0);
328
329 // Check the the buffer was cleared, so its range-start should be at/after
330 // its range-end before.
331 Maybe<ProfilerBufferInfo> info2 = profiler_get_buffer_info();
332 ASSERT_TRUE(info2->mRangeStart >= info1->mRangeEnd);
333 }
334
335 {
336 // Active -> Inactive
337
338 profiler_stop();
339
340 InactiveFeaturesAndParamsCheck();
341 }
342 }
343
TEST(GeckoProfiler,DifferentThreads)344 TEST(GeckoProfiler, DifferentThreads)
345 {
346 InactiveFeaturesAndParamsCheck();
347
348 nsCOMPtr<nsIThread> thread;
349 nsresult rv = NS_NewNamedThread("GeckoProfGTest", getter_AddRefs(thread));
350 ASSERT_TRUE(NS_SUCCEEDED(rv));
351
352 // Control the profiler on a background thread and verify flags on the
353 // main thread.
354 {
355 uint32_t features = ProfilerFeature::JS | ProfilerFeature::Threads;
356 const char* filters[] = {"GeckoMain", "Compositor"};
357
358 thread->Dispatch(
359 NS_NewRunnableFunction("GeckoProfiler_DifferentThreads_Test::TestBody",
360 [&]() {
361 profiler_start(PROFILER_DEFAULT_ENTRIES,
362 PROFILER_DEFAULT_INTERVAL,
363 features, filters,
364 MOZ_ARRAY_LENGTH(filters), 0);
365 }),
366 NS_DISPATCH_SYNC);
367
368 ASSERT_TRUE(profiler_is_active());
369 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::MainThreadIO));
370 ASSERT_TRUE(!profiler_feature_active(ProfilerFeature::IPCMessages));
371
372 ActiveParamsCheck(PROFILER_DEFAULT_ENTRIES.Value(),
373 PROFILER_DEFAULT_INTERVAL, features, filters,
374 MOZ_ARRAY_LENGTH(filters), 0);
375
376 thread->Dispatch(
377 NS_NewRunnableFunction("GeckoProfiler_DifferentThreads_Test::TestBody",
378 [&]() { profiler_stop(); }),
379 NS_DISPATCH_SYNC);
380
381 InactiveFeaturesAndParamsCheck();
382 }
383
384 // Control the profiler on the main thread and verify flags on a
385 // background thread.
386 {
387 uint32_t features = ProfilerFeature::JS | ProfilerFeature::Threads;
388 const char* filters[] = {"GeckoMain", "Compositor"};
389
390 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
391 features, filters, MOZ_ARRAY_LENGTH(filters), 0);
392
393 thread->Dispatch(
394 NS_NewRunnableFunction(
395 "GeckoProfiler_DifferentThreads_Test::TestBody",
396 [&]() {
397 ASSERT_TRUE(profiler_is_active());
398 ASSERT_TRUE(
399 !profiler_feature_active(ProfilerFeature::MainThreadIO));
400 ASSERT_TRUE(
401 !profiler_feature_active(ProfilerFeature::IPCMessages));
402
403 ActiveParamsCheck(PROFILER_DEFAULT_ENTRIES.Value(),
404 PROFILER_DEFAULT_INTERVAL, features, filters,
405 MOZ_ARRAY_LENGTH(filters), 0);
406 }),
407 NS_DISPATCH_SYNC);
408
409 profiler_stop();
410
411 thread->Dispatch(
412 NS_NewRunnableFunction("GeckoProfiler_DifferentThreads_Test::TestBody",
413 [&]() { InactiveFeaturesAndParamsCheck(); }),
414 NS_DISPATCH_SYNC);
415 }
416
417 thread->Shutdown();
418 }
419
TEST(GeckoProfiler,GetBacktrace)420 TEST(GeckoProfiler, GetBacktrace)
421 {
422 ASSERT_TRUE(!profiler_get_backtrace());
423
424 {
425 uint32_t features = ProfilerFeature::StackWalk;
426 const char* filters[] = {"GeckoMain"};
427
428 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
429 features, filters, MOZ_ARRAY_LENGTH(filters), 0);
430
431 // These will be destroyed while the profiler is active.
432 static const int N = 100;
433 {
434 UniqueProfilerBacktrace u[N];
435 for (int i = 0; i < N; i++) {
436 u[i] = profiler_get_backtrace();
437 ASSERT_TRUE(u[i]);
438 }
439 }
440
441 // These will be destroyed after the profiler stops.
442 UniqueProfilerBacktrace u[N];
443 for (int i = 0; i < N; i++) {
444 u[i] = profiler_get_backtrace();
445 ASSERT_TRUE(u[i]);
446 }
447
448 profiler_stop();
449 }
450
451 ASSERT_TRUE(!profiler_get_backtrace());
452 }
453
TEST(GeckoProfiler,Pause)454 TEST(GeckoProfiler, Pause)
455 {
456 uint32_t features = ProfilerFeature::StackWalk;
457 const char* filters[] = {"GeckoMain"};
458
459 ASSERT_TRUE(!profiler_is_paused());
460 ASSERT_TRUE(!profiler_can_accept_markers());
461
462 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
463 filters, MOZ_ARRAY_LENGTH(filters), 0);
464
465 ASSERT_TRUE(!profiler_is_paused());
466 ASSERT_TRUE(profiler_can_accept_markers());
467
468 // Check that we are writing samples while not paused.
469 Maybe<ProfilerBufferInfo> info1 = profiler_get_buffer_info();
470 PR_Sleep(PR_MillisecondsToInterval(500));
471 Maybe<ProfilerBufferInfo> info2 = profiler_get_buffer_info();
472 ASSERT_TRUE(info1->mRangeEnd != info2->mRangeEnd);
473
474 // Check that we are writing markers while not paused.
475 info1 = profiler_get_buffer_info();
476 PROFILER_ADD_MARKER("Not paused", OTHER);
477 info2 = profiler_get_buffer_info();
478 ASSERT_TRUE(info1->mRangeEnd != info2->mRangeEnd);
479
480 profiler_pause();
481
482 ASSERT_TRUE(profiler_is_paused());
483 ASSERT_TRUE(!profiler_can_accept_markers());
484
485 // Check that we are not writing samples while paused.
486 info1 = profiler_get_buffer_info();
487 PR_Sleep(PR_MillisecondsToInterval(500));
488 info2 = profiler_get_buffer_info();
489 ASSERT_TRUE(info1->mRangeEnd == info2->mRangeEnd);
490
491 // Check that we are now writing markers while paused.
492 info1 = profiler_get_buffer_info();
493 PROFILER_ADD_MARKER("Paused", OTHER);
494 info2 = profiler_get_buffer_info();
495 ASSERT_TRUE(info1->mRangeEnd == info2->mRangeEnd);
496
497 profiler_resume();
498
499 ASSERT_TRUE(!profiler_is_paused());
500 ASSERT_TRUE(profiler_can_accept_markers());
501
502 profiler_stop();
503
504 ASSERT_TRUE(!profiler_is_paused());
505 ASSERT_TRUE(!profiler_can_accept_markers());
506 }
507
508 // A class that keeps track of how many instances have been created, streamed,
509 // and destroyed.
510 class GTestMarkerPayload : public ProfilerMarkerPayload {
511 public:
GTestMarkerPayload(int aN)512 explicit GTestMarkerPayload(int aN) : mN(aN) { ++sNumCreated; }
513
~GTestMarkerPayload()514 virtual ~GTestMarkerPayload() { ++sNumDestroyed; }
515
516 DECL_STREAM_PAYLOAD
517
518 private:
GTestMarkerPayload(CommonProps && aCommonProps,int aN)519 GTestMarkerPayload(CommonProps&& aCommonProps, int aN)
520 : ProfilerMarkerPayload(std::move(aCommonProps)), mN(aN) {
521 ++sNumDeserialized;
522 }
523
524 int mN;
525
526 public:
527 // The number of GTestMarkerPayload instances that have been created,
528 // streamed, and destroyed.
529 static int sNumCreated;
530 static int sNumSerialized;
531 static int sNumDeserialized;
532 static int sNumStreamed;
533 static int sNumDestroyed;
534 };
535
536 int GTestMarkerPayload::sNumCreated = 0;
537 int GTestMarkerPayload::sNumSerialized = 0;
538 int GTestMarkerPayload::sNumDeserialized = 0;
539 int GTestMarkerPayload::sNumStreamed = 0;
540 int GTestMarkerPayload::sNumDestroyed = 0;
541
TagAndSerializationBytes() const542 ProfileBufferEntryWriter::Length GTestMarkerPayload::TagAndSerializationBytes()
543 const {
544 return CommonPropsTagAndSerializationBytes() +
545 ProfileBufferEntryWriter::SumBytes(mN);
546 }
547
SerializeTagAndPayload(ProfileBufferEntryWriter & aEntryWriter) const548 void GTestMarkerPayload::SerializeTagAndPayload(
549 ProfileBufferEntryWriter& aEntryWriter) const {
550 static const DeserializerTag tag = TagForDeserializer(Deserialize);
551 SerializeTagAndCommonProps(tag, aEntryWriter);
552 aEntryWriter.WriteObject(mN);
553 ++sNumSerialized;
554 }
555
556 // static
Deserialize(ProfileBufferEntryReader & aEntryReader)557 UniquePtr<ProfilerMarkerPayload> GTestMarkerPayload::Deserialize(
558 ProfileBufferEntryReader& aEntryReader) {
559 ProfilerMarkerPayload::CommonProps props =
560 DeserializeCommonProps(aEntryReader);
561 auto n = aEntryReader.ReadObject<int>();
562 return UniquePtr<ProfilerMarkerPayload>(
563 new GTestMarkerPayload(std::move(props), n));
564 }
565
StreamPayload(SpliceableJSONWriter & aWriter,const mozilla::TimeStamp & aStartTime,UniqueStacks & aUniqueStacks) const566 void GTestMarkerPayload::StreamPayload(SpliceableJSONWriter& aWriter,
567 const mozilla::TimeStamp& aStartTime,
568 UniqueStacks& aUniqueStacks) const {
569 StreamCommonProps("gtest", aWriter, aStartTime, aUniqueStacks);
570 char buf[64];
571 SprintfLiteral(buf, "gtest-%d", mN);
572 aWriter.IntProperty(buf, mN);
573 ++sNumStreamed;
574 }
575
TEST(GeckoProfiler,Markers)576 TEST(GeckoProfiler, Markers)
577 {
578 uint32_t features = ProfilerFeature::StackWalk;
579 const char* filters[] = {"GeckoMain"};
580
581 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
582 filters, MOZ_ARRAY_LENGTH(filters), 0);
583
584 profiler_tracing_marker("A", "tracing event",
585 JS::ProfilingCategoryPair::OTHER, TRACING_EVENT);
586 PROFILER_TRACING_MARKER("A", "tracing start", OTHER, TRACING_INTERVAL_START);
587 PROFILER_TRACING_MARKER("A", "tracing end", OTHER, TRACING_INTERVAL_END);
588
589 UniqueProfilerBacktrace bt = profiler_get_backtrace();
590 profiler_tracing_marker("B", "tracing event with stack",
591 JS::ProfilingCategoryPair::OTHER, TRACING_EVENT,
592 std::move(bt));
593
594 { AUTO_PROFILER_TRACING_MARKER("C", "auto tracing", OTHER); }
595
596 PROFILER_ADD_MARKER("M1", OTHER);
597 PROFILER_ADD_MARKER_WITH_PAYLOAD("M2", OTHER, TracingMarkerPayload,
598 ("C", TRACING_EVENT));
599 PROFILER_ADD_MARKER("M3", OTHER);
600 PROFILER_ADD_MARKER_WITH_PAYLOAD(
601 "M4", OTHER, TracingMarkerPayload,
602 ("C", TRACING_EVENT, mozilla::Nothing(), profiler_get_backtrace()));
603
604 for (int i = 0; i < 10; i++) {
605 PROFILER_ADD_MARKER_WITH_PAYLOAD("M5", OTHER, GTestMarkerPayload, (i));
606 }
607 // The GTestMarkerPayloads should have been created, serialized, and
608 // destroyed.
609 EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10);
610 EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10);
611 EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0);
612 EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0);
613 EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10);
614
615 // Create three strings: two that are the maximum allowed length, and one that
616 // is one char longer.
617 static const size_t kMax = ProfileBuffer::kMaxFrameKeyLength;
618 UniquePtr<char[]> okstr1 = MakeUnique<char[]>(kMax);
619 UniquePtr<char[]> okstr2 = MakeUnique<char[]>(kMax);
620 UniquePtr<char[]> longstr = MakeUnique<char[]>(kMax + 1);
621 UniquePtr<char[]> longstrCut = MakeUnique<char[]>(kMax + 1);
622 for (size_t i = 0; i < kMax; i++) {
623 okstr1[i] = 'a';
624 okstr2[i] = 'b';
625 longstr[i] = 'c';
626 longstrCut[i] = 'c';
627 }
628 okstr1[kMax - 1] = '\0';
629 okstr2[kMax - 1] = '\0';
630 longstr[kMax] = '\0';
631 longstrCut[kMax] = '\0';
632 // Should be output as-is.
633 AUTO_PROFILER_LABEL_DYNAMIC_CSTR("", LAYOUT, "");
634 AUTO_PROFILER_LABEL_DYNAMIC_CSTR("", LAYOUT, okstr1.get());
635 // Should be output as label + space + okstr2.
636 AUTO_PROFILER_LABEL_DYNAMIC_CSTR("okstr2", LAYOUT, okstr2.get());
637 // Should be output with kMax length, ending with "...\0".
638 AUTO_PROFILER_LABEL_DYNAMIC_CSTR("", LAYOUT, longstr.get());
639 ASSERT_EQ(longstrCut[kMax - 4], 'c');
640 longstrCut[kMax - 4] = '.';
641 ASSERT_EQ(longstrCut[kMax - 3], 'c');
642 longstrCut[kMax - 3] = '.';
643 ASSERT_EQ(longstrCut[kMax - 2], 'c');
644 longstrCut[kMax - 2] = '.';
645 ASSERT_EQ(longstrCut[kMax - 1], 'c');
646 longstrCut[kMax - 1] = '\0';
647
648 // Used in markers below.
649 TimeStamp ts1 = TimeStamp::NowUnfuzzed();
650
651 // Sleep briefly to ensure a sample is taken and the pending markers are
652 // processed.
653 PR_Sleep(PR_MillisecondsToInterval(500));
654
655 // Used in markers below.
656 TimeStamp ts2 = TimeStamp::NowUnfuzzed();
657 // ts1 and ts2 should be different thanks to the sleep.
658 EXPECT_NE(ts1, ts2);
659
660 // Test most marker payloads.
661
662 // Keep this one first! (It's used to record `ts1` and `ts2`, to compare
663 // to serialized numbers in other markers.)
664 PROFILER_ADD_MARKER_WITH_PAYLOAD(
665 "FileIOMarkerPayload marker", OTHER, FileIOMarkerPayload,
666 ("operation", "source", "filename", ts1, ts2, nullptr));
667
668 PROFILER_ADD_MARKER_WITH_PAYLOAD(
669 "FileIOMarkerPayload marker off-MT", OTHER, FileIOMarkerPayload,
670 ("operation2", "source2", "filename2", ts1, ts2, nullptr, Some(123)));
671
672 // Other markers in alphabetical order of payload class names.
673
674 PROFILER_ADD_MARKER_WITH_PAYLOAD(
675 "DOMEventMarkerPayload marker", OTHER, DOMEventMarkerPayload,
676 (NS_LITERAL_STRING("dom event"), ts1, "category", TRACING_EVENT,
677 mozilla::Nothing()));
678
679 {
680 const char gcMajorJSON[] = "42";
681 const auto len = strlen(gcMajorJSON);
682 char* buffer =
683 static_cast<char*>(js::SystemAllocPolicy{}.pod_malloc<char>(len + 1));
684 strncpy(buffer, gcMajorJSON, len);
685 buffer[len] = '\0';
686 PROFILER_ADD_MARKER_WITH_PAYLOAD("GCMajorMarkerPayload marker", OTHER,
687 GCMajorMarkerPayload,
688 (ts1, ts2, JS::UniqueChars(buffer)));
689 }
690
691 {
692 const char gcMinorJSON[] = "43";
693 const auto len = strlen(gcMinorJSON);
694 char* buffer =
695 static_cast<char*>(js::SystemAllocPolicy{}.pod_malloc<char>(len + 1));
696 strncpy(buffer, gcMinorJSON, len);
697 buffer[len] = '\0';
698 PROFILER_ADD_MARKER_WITH_PAYLOAD("GCMinorMarkerPayload marker", OTHER,
699 GCMinorMarkerPayload,
700 (ts1, ts2, JS::UniqueChars(buffer)));
701 }
702
703 {
704 const char gcSliceJSON[] = "44";
705 const auto len = strlen(gcSliceJSON);
706 char* buffer =
707 static_cast<char*>(js::SystemAllocPolicy{}.pod_malloc<char>(len + 1));
708 strncpy(buffer, gcSliceJSON, len);
709 buffer[len] = '\0';
710 PROFILER_ADD_MARKER_WITH_PAYLOAD("GCSliceMarkerPayload marker", OTHER,
711 GCSliceMarkerPayload,
712 (ts1, ts2, JS::UniqueChars(buffer)));
713 }
714
715 PROFILER_ADD_MARKER_WITH_PAYLOAD("HangMarkerPayload marker", OTHER,
716 HangMarkerPayload, (ts1, ts2));
717
718 PROFILER_ADD_MARKER_WITH_PAYLOAD("LogMarkerPayload marker", OTHER,
719 LogMarkerPayload, ("module", "text", ts1));
720
721 PROFILER_ADD_MARKER_WITH_PAYLOAD("LongTaskMarkerPayload marker", OTHER,
722 LongTaskMarkerPayload, (ts1, ts2));
723
724 PROFILER_ADD_MARKER_WITH_PAYLOAD("NativeAllocationMarkerPayload marker",
725 OTHER, NativeAllocationMarkerPayload,
726 (ts1, 9876543210, 1234, 5678, nullptr));
727
728 PROFILER_ADD_MARKER_WITH_PAYLOAD(
729 "NetworkMarkerPayload start marker", OTHER, NetworkMarkerPayload,
730 (1, "http://mozilla.org/", NetworkLoadType::LOAD_START, ts1, ts2, 34, 56,
731 net::kCacheHit, 78));
732
733 PROFILER_ADD_MARKER_WITH_PAYLOAD(
734 "NetworkMarkerPayload stop marker", OTHER, NetworkMarkerPayload,
735 (12, "http://mozilla.org/", NetworkLoadType::LOAD_STOP, ts1, ts2, 34, 56,
736 net::kCacheUnresolved, 78, nullptr, nullptr, nullptr,
737 Some(nsDependentCString(NS_LITERAL_CSTRING("text/html").get()))));
738
739 PROFILER_ADD_MARKER_WITH_PAYLOAD(
740 "NetworkMarkerPayload redirect marker", OTHER, NetworkMarkerPayload,
741 (123, "http://mozilla.org/", NetworkLoadType::LOAD_REDIRECT, ts1, ts2, 34,
742 56, net::kCacheUnresolved, 78, nullptr, "http://example.com/"));
743
744 PROFILER_ADD_MARKER_WITH_PAYLOAD(
745 "PrefMarkerPayload marker", OTHER, PrefMarkerPayload,
746 ("preference name", mozilla::Nothing(), mozilla::Nothing(),
747 NS_LITERAL_CSTRING("preference value"), ts1));
748
749 nsCString screenshotURL = NS_LITERAL_CSTRING("url");
750 PROFILER_ADD_MARKER_WITH_PAYLOAD(
751 "ScreenshotPayload marker", OTHER, ScreenshotPayload,
752 (ts1, std::move(screenshotURL), mozilla::gfx::IntSize(12, 34),
753 uintptr_t(0x45678u)));
754
755 PROFILER_ADD_MARKER_WITH_PAYLOAD("TextMarkerPayload marker 1", OTHER,
756 TextMarkerPayload,
757 (NS_LITERAL_CSTRING("text"), ts1));
758
759 PROFILER_ADD_MARKER_WITH_PAYLOAD("TextMarkerPayload marker 2", OTHER,
760 TextMarkerPayload,
761 (NS_LITERAL_CSTRING("text"), ts1, ts2));
762
763 PROFILER_ADD_MARKER_WITH_PAYLOAD(
764 "UserTimingMarkerPayload marker mark", OTHER, UserTimingMarkerPayload,
765 (NS_LITERAL_STRING("mark name"), ts1, mozilla::Nothing()));
766
767 PROFILER_ADD_MARKER_WITH_PAYLOAD(
768 "UserTimingMarkerPayload marker measure", OTHER, UserTimingMarkerPayload,
769 (NS_LITERAL_STRING("measure name"), Some(NS_LITERAL_STRING("start mark")),
770 Some(NS_LITERAL_STRING("end mark")), ts1, ts2, mozilla::Nothing()));
771
772 PROFILER_ADD_MARKER_WITH_PAYLOAD("VsyncMarkerPayload marker", OTHER,
773 VsyncMarkerPayload, (ts1));
774
775 PROFILER_ADD_MARKER_WITH_PAYLOAD(
776 "IPCMarkerPayload marker", IPC, IPCMarkerPayload,
777 (1111, 1, 3 /* PAPZ::Msg_LayerTransforms */, mozilla::ipc::ParentSide,
778 mozilla::ipc::MessageDirection::eSending, false, ts1));
779
780 SpliceableChunkedJSONWriter w;
781 w.Start();
782 EXPECT_TRUE(profiler_stream_json_for_this_process(w));
783 w.End();
784
785 // The GTestMarkerPayloads should have been deserialized, streamed, and
786 // destroyed.
787 EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0);
788 EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0);
789 EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10);
790 EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10);
791 EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10);
792
793 UniquePtr<char[]> profile = w.WriteFunc()->CopyData();
794 ASSERT_TRUE(!!profile.get());
795
796 // Expected markers, in order.
797 enum State {
798 S_tracing_event,
799 S_tracing_start,
800 S_tracing_end,
801 S_tracing_event_with_stack,
802 S_tracing_auto_tracing_start,
803 S_tracing_auto_tracing_end,
804 S_M1,
805 S_tracing_M2_C,
806 S_M3,
807 S_tracing_M4_C_stack,
808 S_M5_gtest0,
809 S_M5_gtest1,
810 S_M5_gtest2,
811 S_M5_gtest3,
812 S_M5_gtest4,
813 S_M5_gtest5,
814 S_M5_gtest6,
815 S_M5_gtest7,
816 S_M5_gtest8,
817 S_M5_gtest9,
818 S_FileIOMarkerPayload,
819 S_FileIOMarkerPayloadOffMT,
820 S_DOMEventMarkerPayload,
821 S_GCMajorMarkerPayload,
822 S_GCMinorMarkerPayload,
823 S_GCSliceMarkerPayload,
824 S_HangMarkerPayload,
825 S_LogMarkerPayload,
826 S_LongTaskMarkerPayload,
827 S_NativeAllocationMarkerPayload,
828 S_NetworkMarkerPayload_start,
829 S_NetworkMarkerPayload_stop,
830 S_NetworkMarkerPayload_redirect,
831 S_PrefMarkerPayload,
832 S_ScreenshotPayload,
833 S_TextMarkerPayload1,
834 S_TextMarkerPayload2,
835 S_UserTimingMarkerPayload_mark,
836 S_UserTimingMarkerPayload_measure,
837 S_VsyncMarkerPayload,
838 S_IPCMarkerPayload,
839
840 S_LAST,
841 } state = State(0);
842
843 // These will be set when first read from S_FileIOMarkerPayload, then
844 // compared in following markers.
845 // TODO: Compute these values from the timestamps.
846 double ts1Double = 0.0;
847 double ts2Double = 0.0;
848
849 // Extract JSON.
850 Json::Value parsedRoot;
851 Json::CharReaderBuilder builder;
852 const std::unique_ptr<Json::CharReader> reader(builder.newCharReader());
853 ASSERT_TRUE(reader->parse(profile.get(), strchr(profile.get(), '\0'),
854 &parsedRoot, nullptr));
855
856 // Use const root, we only want to test what's in the profile, not change it.
857 const Json::Value& root = parsedRoot;
858 ASSERT_TRUE(root.isObject());
859
860 // We have a root object.
861
862 // Most common test: Checks that the given value is present, is of the
863 // expected type, and has the expected value.
864 #define EXPECT_EQ_JSON(GETTER, TYPE, VALUE) \
865 if ((GETTER).isNull()) { \
866 EXPECT_FALSE((GETTER).isNull()); \
867 } else if (!(GETTER).is##TYPE()) { \
868 EXPECT_TRUE((GETTER).is##TYPE()); \
869 } else { \
870 EXPECT_EQ((GETTER).as##TYPE(), (VALUE)); \
871 }
872
873 // Checks that the given value is present, and is a valid index into the
874 // stringTable, pointing at the expected string.
875 #define EXPECT_EQ_STRINGTABLE(GETTER, STRING) \
876 if ((GETTER).isNull()) { \
877 EXPECT_FALSE((GETTER).isNull()); \
878 } else if (!(GETTER).isUInt()) { \
879 EXPECT_TRUE((GETTER).isUInt()); \
880 } else { \
881 EXPECT_LT((GETTER).asUInt(), stringTable.size()); \
882 EXPECT_EQ_JSON(stringTable[(GETTER).asUInt()], String, (STRING)); \
883 }
884
885 {
886 const Json::Value& threads = root["threads"];
887 ASSERT_TRUE(!threads.isNull());
888 ASSERT_TRUE(threads.isArray());
889 ASSERT_EQ(threads.size(), 1u);
890
891 // root.threads is a 1-element array.
892
893 {
894 const Json::Value& thread0 = threads[0];
895 ASSERT_TRUE(thread0.isObject());
896
897 // root.threads[0] is an object.
898
899 // Keep a reference to the string table in this block, it will be used
900 // below.
901 const Json::Value& stringTable = thread0["stringTable"];
902 ASSERT_TRUE(stringTable.isArray());
903
904 // Test the expected labels in the string table.
905 bool foundEmpty = false;
906 bool foundOkstr1 = false;
907 bool foundOkstr2 = false;
908 const std::string okstr2Label = std::string("okstr2 ") + okstr2.get();
909 bool foundTooLong = false;
910 for (const auto& s : stringTable) {
911 ASSERT_TRUE(s.isString());
912 std::string sString = s.asString();
913 if (sString.empty()) {
914 EXPECT_FALSE(foundEmpty);
915 foundEmpty = true;
916 } else if (sString == okstr1.get()) {
917 EXPECT_FALSE(foundOkstr1);
918 foundOkstr1 = true;
919 } else if (sString == okstr2Label) {
920 EXPECT_FALSE(foundOkstr2);
921 foundOkstr2 = true;
922 } else if (sString == longstrCut.get()) {
923 EXPECT_FALSE(foundTooLong);
924 foundTooLong = true;
925 } else {
926 EXPECT_NE(sString, longstr.get());
927 }
928 }
929 EXPECT_TRUE(foundEmpty);
930 EXPECT_TRUE(foundOkstr1);
931 EXPECT_TRUE(foundOkstr2);
932 EXPECT_TRUE(foundTooLong);
933
934 {
935 const Json::Value& markers = thread0["markers"];
936 ASSERT_TRUE(markers.isObject());
937
938 // root.threads[0].markers is an object.
939
940 {
941 const Json::Value& data = markers["data"];
942 ASSERT_TRUE(data.isArray());
943
944 // root.threads[0].markers.data is an array.
945
946 for (const Json::Value& marker : data) {
947 ASSERT_TRUE(marker.isArray());
948 ASSERT_GE(marker.size(), 3u);
949 ASSERT_LE(marker.size(), 4u);
950
951 // root.threads[0].markers.data[i] is an array with 3 or 4 elements.
952
953 ASSERT_TRUE(marker[0].isUInt()); // name id
954 const Json::Value& name = stringTable[marker[0].asUInt()];
955 ASSERT_TRUE(name.isString());
956 std::string nameString = name.asString();
957
958 EXPECT_TRUE(marker[1].isNumeric()); // timestamp
959
960 EXPECT_TRUE(marker[2].isUInt()); // category
961
962 if (marker.size() == 3u) {
963 // root.threads[0].markers.data[i] is an array with 3 elements,
964 // so there is no payload.
965 if (nameString == "M1") {
966 ASSERT_EQ(state, S_M1);
967 state = State(state + 1);
968 } else if (nameString == "M3") {
969 ASSERT_EQ(state, S_M3);
970 state = State(state + 1);
971 }
972 } else {
973 // root.threads[0].markers.data[i] is an array with 4 elements,
974 // so there is a payload.
975 const Json::Value& payload = marker[3];
976 ASSERT_TRUE(payload.isObject());
977
978 // root.threads[0].markers.data[i][3] is an object (payload).
979
980 // It should at least have a "type" string.
981 const Json::Value& type = payload["type"];
982 ASSERT_TRUE(type.isString());
983 std::string typeString = type.asString();
984
985 if (nameString == "tracing event") {
986 EXPECT_EQ(state, S_tracing_event);
987 state = State(S_tracing_event + 1);
988 EXPECT_EQ(typeString, "tracing");
989 EXPECT_EQ_JSON(payload["category"], String, "A");
990 EXPECT_TRUE(payload["interval"].isNull());
991 EXPECT_TRUE(payload["stack"].isNull());
992
993 } else if (nameString == "tracing start") {
994 EXPECT_EQ(state, S_tracing_start);
995 state = State(S_tracing_start + 1);
996 EXPECT_EQ(typeString, "tracing");
997 EXPECT_EQ_JSON(payload["category"], String, "A");
998 EXPECT_EQ_JSON(payload["interval"], String, "start");
999 EXPECT_TRUE(payload["stack"].isNull());
1000
1001 } else if (nameString == "tracing end") {
1002 EXPECT_EQ(state, S_tracing_end);
1003 state = State(S_tracing_end + 1);
1004 EXPECT_EQ(typeString, "tracing");
1005 EXPECT_EQ_JSON(payload["category"], String, "A");
1006 EXPECT_EQ_JSON(payload["interval"], String, "end");
1007 EXPECT_TRUE(payload["stack"].isNull());
1008
1009 } else if (nameString == "tracing event with stack") {
1010 EXPECT_EQ(state, S_tracing_event_with_stack);
1011 state = State(S_tracing_event_with_stack + 1);
1012 EXPECT_EQ(typeString, "tracing");
1013 EXPECT_EQ_JSON(payload["category"], String, "B");
1014 EXPECT_TRUE(payload["interval"].isNull());
1015 EXPECT_TRUE(payload["stack"].isObject());
1016
1017 } else if (nameString == "auto tracing") {
1018 switch (state) {
1019 case S_tracing_auto_tracing_start:
1020 state = State(S_tracing_auto_tracing_start + 1);
1021 EXPECT_EQ_JSON(payload["category"], String, "C");
1022 EXPECT_EQ_JSON(payload["interval"], String, "start");
1023 EXPECT_TRUE(payload["stack"].isNull());
1024 break;
1025 case S_tracing_auto_tracing_end:
1026 state = State(S_tracing_auto_tracing_end + 1);
1027 EXPECT_EQ_JSON(payload["category"], String, "C");
1028 EXPECT_EQ_JSON(payload["interval"], String, "end");
1029 ASSERT_TRUE(payload["stack"].isNull());
1030 break;
1031 default:
1032 EXPECT_TRUE(state == S_tracing_auto_tracing_start ||
1033 state == S_tracing_auto_tracing_end);
1034 break;
1035 }
1036
1037 } else if (nameString == "M2") {
1038 EXPECT_EQ(state, S_tracing_M2_C);
1039 state = State(S_tracing_M2_C + 1);
1040 EXPECT_EQ(typeString, "tracing");
1041 EXPECT_EQ_JSON(payload["category"], String, "C");
1042 EXPECT_TRUE(payload["interval"].isNull());
1043 EXPECT_TRUE(payload["stack"].isNull());
1044
1045 } else if (nameString == "M4") {
1046 EXPECT_EQ(state, S_tracing_M4_C_stack);
1047 state = State(S_tracing_M4_C_stack + 1);
1048 EXPECT_EQ(typeString, "tracing");
1049 EXPECT_EQ_JSON(payload["category"], String, "C");
1050 EXPECT_TRUE(payload["interval"].isNull());
1051 EXPECT_TRUE(payload["stack"].isObject());
1052
1053 } else if (nameString == "M5") {
1054 EXPECT_EQ(typeString, "gtest");
1055 // It should only have one more element (apart from "type").
1056 ASSERT_EQ(payload.size(), 2u);
1057 const auto itEnd = payload.end();
1058 for (auto it = payload.begin(); it != itEnd; ++it) {
1059 std::string key = it.name();
1060 if (key != "type") {
1061 const Json::Value& value = *it;
1062 ASSERT_TRUE(value.isInt());
1063 int valueInt = value.asInt();
1064 // We expect `"gtest-<i>" : <i>`.
1065 EXPECT_EQ(state, State(S_M5_gtest0 + valueInt));
1066 state = State(state + 1);
1067 EXPECT_EQ(key,
1068 std::string("gtest-") + std::to_string(valueInt));
1069 }
1070 }
1071
1072 } else if (nameString == "FileIOMarkerPayload marker") {
1073 EXPECT_EQ(state, S_FileIOMarkerPayload);
1074 state = State(S_FileIOMarkerPayload + 1);
1075 EXPECT_EQ(typeString, "FileIO");
1076
1077 // Record start and end times, to compare with timestamps in
1078 // following markers.
1079 EXPECT_EQ(ts1Double, 0.0);
1080 ts1Double = payload["startTime"].asDouble();
1081 EXPECT_NE(ts1Double, 0.0);
1082 EXPECT_EQ(ts2Double, 0.0);
1083 ts2Double = payload["endTime"].asDouble();
1084 EXPECT_NE(ts2Double, 0.0);
1085
1086 // Start timestamp is also stored in marker outside of payload.
1087 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1088
1089 EXPECT_TRUE(payload["stack"].isNull());
1090 EXPECT_EQ_JSON(payload["operation"], String, "operation");
1091 EXPECT_EQ_JSON(payload["source"], String, "source");
1092 EXPECT_EQ_JSON(payload["filename"], String, "filename");
1093 EXPECT_FALSE(payload.isMember("threadId"));
1094
1095 } else if (nameString == "FileIOMarkerPayload marker off-MT") {
1096 EXPECT_EQ(state, S_FileIOMarkerPayloadOffMT);
1097 state = State(S_FileIOMarkerPayloadOffMT + 1);
1098 EXPECT_EQ(typeString, "FileIO");
1099 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1100 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1101 // Start timestamp is also stored in marker outside of payload.
1102 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1103 EXPECT_TRUE(payload["stack"].isNull());
1104 EXPECT_EQ_JSON(payload["operation"], String, "operation2");
1105 EXPECT_EQ_JSON(payload["source"], String, "source2");
1106 EXPECT_EQ_JSON(payload["filename"], String, "filename2");
1107 EXPECT_EQ_JSON(payload["threadId"], Int, 123);
1108
1109 } else if (nameString == "DOMEventMarkerPayload marker") {
1110 EXPECT_EQ(state, S_DOMEventMarkerPayload);
1111 state = State(S_DOMEventMarkerPayload + 1);
1112 EXPECT_EQ(typeString, "tracing");
1113 EXPECT_TRUE(payload["stack"].isNull());
1114 EXPECT_EQ_JSON(payload["category"], String, "category");
1115 EXPECT_TRUE(payload["interval"].isNull());
1116 EXPECT_EQ_JSON(payload["timeStamp"], Double, ts1Double);
1117 EXPECT_EQ_JSON(payload["eventType"], String, "dom event");
1118
1119 } else if (nameString == "GCMajorMarkerPayload marker") {
1120 EXPECT_EQ(state, S_GCMajorMarkerPayload);
1121 state = State(S_GCMajorMarkerPayload + 1);
1122 EXPECT_EQ(typeString, "GCMajor");
1123 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1124 // Start timestamp is also stored in marker outside of payload.
1125 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1126 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1127 EXPECT_TRUE(payload["stack"].isNull());
1128 EXPECT_EQ_JSON(payload["timings"], Int, 42);
1129
1130 } else if (nameString == "GCMinorMarkerPayload marker") {
1131 EXPECT_EQ(state, S_GCMinorMarkerPayload);
1132 state = State(S_GCMinorMarkerPayload + 1);
1133 EXPECT_EQ(typeString, "GCMinor");
1134 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1135 // Start timestamp is also stored in marker outside of payload.
1136 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1137 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1138 EXPECT_TRUE(payload["stack"].isNull());
1139 EXPECT_EQ_JSON(payload["nursery"], Int, 43);
1140
1141 } else if (nameString == "GCSliceMarkerPayload marker") {
1142 EXPECT_EQ(state, S_GCSliceMarkerPayload);
1143 state = State(S_GCSliceMarkerPayload + 1);
1144 EXPECT_EQ(typeString, "GCSlice");
1145 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1146 // Start timestamp is also stored in marker outside of payload.
1147 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1148 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1149 EXPECT_TRUE(payload["stack"].isNull());
1150 EXPECT_EQ_JSON(payload["timings"], Int, 44);
1151
1152 } else if (nameString == "HangMarkerPayload marker") {
1153 EXPECT_EQ(state, S_HangMarkerPayload);
1154 state = State(S_HangMarkerPayload + 1);
1155 EXPECT_EQ(typeString, "BHR-detected hang");
1156 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1157 // Start timestamp is also stored in marker outside of payload.
1158 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1159 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1160 EXPECT_TRUE(payload["stack"].isNull());
1161
1162 } else if (nameString == "LogMarkerPayload marker") {
1163 EXPECT_EQ(state, S_LogMarkerPayload);
1164 state = State(S_LogMarkerPayload + 1);
1165 EXPECT_EQ(typeString, "Log");
1166 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1167 // Start timestamp is also stored in marker outside of payload.
1168 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1169 EXPECT_EQ_JSON(payload["endTime"], Double, ts1Double);
1170 EXPECT_TRUE(payload["stack"].isNull());
1171 EXPECT_EQ_JSON(payload["name"], String, "text");
1172 EXPECT_EQ_JSON(payload["module"], String, "module");
1173
1174 } else if (nameString == "LongTaskMarkerPayload marker") {
1175 EXPECT_EQ(state, S_LongTaskMarkerPayload);
1176 state = State(S_LongTaskMarkerPayload + 1);
1177 EXPECT_EQ(typeString, "MainThreadLongTask");
1178 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1179 // Start timestamp is also stored in marker outside of payload.
1180 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1181 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1182 EXPECT_TRUE(payload["stack"].isNull());
1183 EXPECT_EQ_JSON(payload["category"], String, "LongTask");
1184
1185 } else if (nameString == "NativeAllocationMarkerPayload marker") {
1186 EXPECT_EQ(state, S_NativeAllocationMarkerPayload);
1187 state = State(S_NativeAllocationMarkerPayload + 1);
1188 EXPECT_EQ(typeString, "Native allocation");
1189 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1190 // Start timestamp is also stored in marker outside of payload.
1191 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1192 EXPECT_EQ_JSON(payload["endTime"], Double, ts1Double);
1193 EXPECT_TRUE(payload["stack"].isNull());
1194 EXPECT_EQ_JSON(payload["size"], Int64, 9876543210);
1195 EXPECT_EQ_JSON(payload["memoryAddress"], Int64, 1234);
1196 EXPECT_EQ_JSON(payload["threadId"], Int64, 5678);
1197
1198 } else if (nameString == "NetworkMarkerPayload start marker") {
1199 EXPECT_EQ(state, S_NetworkMarkerPayload_start);
1200 state = State(S_NetworkMarkerPayload_start + 1);
1201 EXPECT_EQ(typeString, "Network");
1202 EXPECT_EQ_JSON(payload["id"], Int64, 1);
1203 EXPECT_EQ_JSON(payload["URI"], String, "http://mozilla.org/");
1204 EXPECT_EQ_JSON(payload["pri"], Int64, 34);
1205 EXPECT_EQ_JSON(payload["count"], Int64, 56);
1206 EXPECT_EQ_JSON(payload["cache"], String, "Hit");
1207 EXPECT_EQ_JSON(payload["RedirectURI"], String, "");
1208 EXPECT_TRUE(payload["contentType"].isNull());
1209
1210 } else if (nameString == "NetworkMarkerPayload stop marker") {
1211 EXPECT_EQ(state, S_NetworkMarkerPayload_stop);
1212 state = State(S_NetworkMarkerPayload_stop + 1);
1213 EXPECT_EQ(typeString, "Network");
1214 EXPECT_EQ_JSON(payload["id"], Int64, 12);
1215 EXPECT_EQ_JSON(payload["URI"], String, "http://mozilla.org/");
1216 EXPECT_EQ_JSON(payload["pri"], Int64, 34);
1217 EXPECT_EQ_JSON(payload["count"], Int64, 56);
1218 EXPECT_EQ_JSON(payload["cache"], String, "Unresolved");
1219 EXPECT_EQ_JSON(payload["RedirectURI"], String, "");
1220 EXPECT_EQ_JSON(payload["contentType"], String, "text/html");
1221
1222 } else if (nameString == "NetworkMarkerPayload redirect marker") {
1223 EXPECT_EQ(state, S_NetworkMarkerPayload_redirect);
1224 state = State(S_NetworkMarkerPayload_redirect + 1);
1225 EXPECT_EQ(typeString, "Network");
1226 EXPECT_EQ_JSON(payload["id"], Int64, 123);
1227 EXPECT_EQ_JSON(payload["URI"], String, "http://mozilla.org/");
1228 EXPECT_EQ_JSON(payload["pri"], Int64, 34);
1229 EXPECT_EQ_JSON(payload["count"], Int64, 56);
1230 EXPECT_EQ_JSON(payload["cache"], String, "Unresolved");
1231 EXPECT_EQ_JSON(payload["RedirectURI"], String,
1232 "http://example.com/");
1233 EXPECT_TRUE(payload["contentType"].isNull());
1234
1235 } else if (nameString == "PrefMarkerPayload marker") {
1236 EXPECT_EQ(state, S_PrefMarkerPayload);
1237 state = State(S_PrefMarkerPayload + 1);
1238 EXPECT_EQ(typeString, "PreferenceRead");
1239 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1240 // Start timestamp is also stored in marker outside of payload.
1241 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1242 EXPECT_EQ_JSON(payload["endTime"], Double, ts1Double);
1243 EXPECT_TRUE(payload["stack"].isNull());
1244 EXPECT_EQ_JSON(payload["prefAccessTime"], Double, ts1Double);
1245 EXPECT_EQ_JSON(payload["prefName"], String, "preference name");
1246 EXPECT_EQ_JSON(payload["prefKind"], String, "Shared");
1247 EXPECT_EQ_JSON(payload["prefType"], String,
1248 "Preference not found");
1249 EXPECT_EQ_JSON(payload["prefValue"], String,
1250 "preference value");
1251
1252 } else if (nameString == "ScreenshotPayload marker") {
1253 EXPECT_EQ(state, S_ScreenshotPayload);
1254 state = State(S_ScreenshotPayload + 1);
1255 EXPECT_EQ(typeString, "CompositorScreenshot");
1256 EXPECT_EQ_STRINGTABLE(payload["url"], "url");
1257 EXPECT_EQ_JSON(payload["windowID"], String, "0x45678");
1258 EXPECT_EQ_JSON(payload["windowWidth"], Int, 12);
1259 EXPECT_EQ_JSON(payload["windowHeight"], Int, 34);
1260
1261 } else if (nameString == "TextMarkerPayload marker 1") {
1262 EXPECT_EQ(state, S_TextMarkerPayload1);
1263 state = State(S_TextMarkerPayload1 + 1);
1264 EXPECT_EQ(typeString, "Text");
1265 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1266 // Start timestamp is also stored in marker outside of payload.
1267 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1268 EXPECT_EQ_JSON(payload["endTime"], Double, ts1Double);
1269 EXPECT_TRUE(payload["stack"].isNull());
1270 EXPECT_EQ_JSON(payload["name"], String, "text");
1271
1272 } else if (nameString == "TextMarkerPayload marker 2") {
1273 EXPECT_EQ(state, S_TextMarkerPayload2);
1274 state = State(S_TextMarkerPayload2 + 1);
1275 EXPECT_EQ(typeString, "Text");
1276 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1277 // Start timestamp is also stored in marker outside of payload.
1278 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1279 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1280 EXPECT_TRUE(payload["stack"].isNull());
1281 EXPECT_EQ_JSON(payload["name"], String, "text");
1282
1283 } else if (nameString == "UserTimingMarkerPayload marker mark") {
1284 EXPECT_EQ(state, S_UserTimingMarkerPayload_mark);
1285 state = State(S_UserTimingMarkerPayload_mark + 1);
1286 EXPECT_EQ(typeString, "UserTiming");
1287 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1288 // Start timestamp is also stored in marker outside of payload.
1289 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1290 EXPECT_EQ_JSON(payload["endTime"], Double, ts1Double);
1291 EXPECT_TRUE(payload["stack"].isNull());
1292 EXPECT_EQ_JSON(payload["name"], String, "mark name");
1293 EXPECT_EQ_JSON(payload["entryType"], String, "mark");
1294
1295 } else if (nameString ==
1296 "UserTimingMarkerPayload marker measure") {
1297 EXPECT_EQ(state, S_UserTimingMarkerPayload_measure);
1298 state = State(S_UserTimingMarkerPayload_measure + 1);
1299 EXPECT_EQ(typeString, "UserTiming");
1300 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1301 // Start timestamp is also stored in marker outside of payload.
1302 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1303 EXPECT_EQ_JSON(payload["endTime"], Double, ts2Double);
1304 EXPECT_TRUE(payload["stack"].isNull());
1305 EXPECT_EQ_JSON(payload["name"], String, "measure name");
1306 EXPECT_EQ_JSON(payload["entryType"], String, "measure");
1307 EXPECT_EQ_JSON(payload["startMark"], String, "start mark");
1308 EXPECT_EQ_JSON(payload["endMark"], String, "end mark");
1309
1310 } else if (nameString == "VsyncMarkerPayload marker") {
1311 EXPECT_EQ(state, S_VsyncMarkerPayload);
1312 state = State(S_VsyncMarkerPayload + 1);
1313 EXPECT_EQ(typeString, "VsyncTimestamp");
1314 // Timestamp is stored in marker outside of payload.
1315 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1316 EXPECT_TRUE(payload["stack"].isNull());
1317
1318 } else if (nameString == "IPCMarkerPayload marker") {
1319 EXPECT_EQ(state, S_IPCMarkerPayload);
1320 state = State(S_IPCMarkerPayload + 1);
1321 EXPECT_EQ(typeString, "IPC");
1322 EXPECT_EQ_JSON(payload["startTime"], Double, ts1Double);
1323 // Start timestamp is also stored in marker outside of payload.
1324 EXPECT_EQ_JSON(marker[1], Double, ts1Double);
1325 EXPECT_EQ_JSON(payload["endTime"], Double, ts1Double);
1326 EXPECT_TRUE(payload["stack"].isNull());
1327 EXPECT_EQ_JSON(payload["otherPid"], Int, 1111);
1328 EXPECT_EQ_JSON(payload["messageSeqno"], Int, 1);
1329 EXPECT_EQ_JSON(payload["messageType"], String,
1330 "PAPZ::Msg_LayerTransforms");
1331 EXPECT_EQ_JSON(payload["side"], String, "parent");
1332 EXPECT_EQ_JSON(payload["direction"], String, "sending");
1333 EXPECT_EQ_JSON(payload["sync"], Bool, false);
1334 }
1335 } // marker with payload
1336 } // for (marker:data)
1337 } // markers.data
1338 } // markers
1339 } // thread0
1340 } // threads
1341
1342 // We should have read all expected markers.
1343 EXPECT_EQ(state, S_LAST);
1344
1345 Maybe<ProfilerBufferInfo> info = profiler_get_buffer_info();
1346 MOZ_RELEASE_ASSERT(info.isSome());
1347 printf("Profiler buffer range: %llu .. %llu (%llu bytes)\n",
1348 static_cast<unsigned long long>(info->mRangeStart),
1349 static_cast<unsigned long long>(info->mRangeEnd),
1350 // sizeof(ProfileBufferEntry) == 9
1351 (static_cast<unsigned long long>(info->mRangeEnd) -
1352 static_cast<unsigned long long>(info->mRangeStart)) *
1353 9);
1354 printf("Stats: min(ns) .. mean(ns) .. max(ns) [count]\n");
1355 printf("- Intervals: %7.1f .. %7.1f .. %7.1f [%u]\n",
1356 info->mIntervalsNs.min, info->mIntervalsNs.sum / info->mIntervalsNs.n,
1357 info->mIntervalsNs.max, info->mIntervalsNs.n);
1358 printf("- Overheads: %7.1f .. %7.1f .. %7.1f [%u]\n",
1359 info->mOverheadsNs.min, info->mOverheadsNs.sum / info->mOverheadsNs.n,
1360 info->mOverheadsNs.max, info->mOverheadsNs.n);
1361 printf(" - Locking: %7.1f .. %7.1f .. %7.1f [%u]\n",
1362 info->mLockingsNs.min, info->mLockingsNs.sum / info->mLockingsNs.n,
1363 info->mLockingsNs.max, info->mLockingsNs.n);
1364 printf(" - Clearning: %7.1f .. %7.1f .. %7.1f [%u]\n",
1365 info->mCleaningsNs.min, info->mCleaningsNs.sum / info->mCleaningsNs.n,
1366 info->mCleaningsNs.max, info->mCleaningsNs.n);
1367 printf(" - Counters: %7.1f .. %7.1f .. %7.1f [%u]\n",
1368 info->mCountersNs.min, info->mCountersNs.sum / info->mCountersNs.n,
1369 info->mCountersNs.max, info->mCountersNs.n);
1370 printf(" - Threads: %7.1f .. %7.1f .. %7.1f [%u]\n",
1371 info->mThreadsNs.min, info->mThreadsNs.sum / info->mThreadsNs.n,
1372 info->mThreadsNs.max, info->mThreadsNs.n);
1373
1374 profiler_stop();
1375
1376 // Nothing more should have happened to the GTestMarkerPayloads.
1377 EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0 + 0);
1378 EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0 + 0);
1379 EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10 + 0);
1380 EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10 + 0);
1381 EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10 + 0);
1382
1383 // Try to add markers while the profiler is stopped.
1384 for (int i = 0; i < 10; i++) {
1385 PROFILER_ADD_MARKER_WITH_PAYLOAD("M5", OTHER, GTestMarkerPayload, (i));
1386 }
1387
1388 // Warning: this could be racy
1389 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1390 filters, MOZ_ARRAY_LENGTH(filters), 0);
1391
1392 EXPECT_TRUE(profiler_stream_json_for_this_process(w));
1393
1394 profiler_stop();
1395
1396 // The second set of GTestMarkerPayloads should not have been serialized or
1397 // streamed.
1398 EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0 + 0 + 10);
1399 EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0 + 0 + 0);
1400 EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10 + 0 + 0);
1401 EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10 + 0 + 0);
1402 EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10 + 0 + 10);
1403 }
1404
1405 // The duration limit will be removed from Firefox, see bug 1632365.
1406 #if 0
1407 TEST(GeckoProfiler, DurationLimit)
1408 {
1409 uint32_t features = ProfilerFeature::StackWalk;
1410 const char* filters[] = {"GeckoMain"};
1411
1412 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1413 filters, MOZ_ARRAY_LENGTH(filters), 0, Some(1.5));
1414
1415 // Clear up the counters after the last test.
1416 GTestMarkerPayload::sNumCreated = 0;
1417 GTestMarkerPayload::sNumSerialized = 0;
1418 GTestMarkerPayload::sNumDeserialized = 0;
1419 GTestMarkerPayload::sNumStreamed = 0;
1420 GTestMarkerPayload::sNumDestroyed = 0;
1421
1422 PROFILER_ADD_MARKER_WITH_PAYLOAD("M1", OTHER, GTestMarkerPayload, (1));
1423 PR_Sleep(PR_MillisecondsToInterval(1100));
1424 PROFILER_ADD_MARKER_WITH_PAYLOAD("M2", OTHER, GTestMarkerPayload, (2));
1425 PR_Sleep(PR_MillisecondsToInterval(500));
1426
1427 SpliceableChunkedJSONWriter w;
1428 ASSERT_TRUE(profiler_stream_json_for_this_process(w));
1429
1430 // Both markers created, serialized, destroyed; Only the first marker should
1431 // have been deserialized, streamed, and destroyed again.
1432 EXPECT_EQ(GTestMarkerPayload::sNumCreated, 2);
1433 EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 2);
1434 EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 1);
1435 EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 1);
1436 EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 3);
1437 }
1438 #endif
1439
1440 #define COUNTER_NAME "TestCounter"
1441 #define COUNTER_DESCRIPTION "Test of counters in profiles"
1442 #define COUNTER_NAME2 "Counter2"
1443 #define COUNTER_DESCRIPTION2 "Second Test of counters in profiles"
1444
1445 PROFILER_DEFINE_COUNT_TOTAL(TestCounter, COUNTER_NAME, COUNTER_DESCRIPTION);
1446 PROFILER_DEFINE_COUNT_TOTAL(TestCounter2, COUNTER_NAME2, COUNTER_DESCRIPTION2);
1447
TEST(GeckoProfiler,Counters)1448 TEST(GeckoProfiler, Counters)
1449 {
1450 uint32_t features = ProfilerFeature::Threads;
1451 const char* filters[] = {"GeckoMain", "Compositor"};
1452
1453 // Inactive -> Active
1454 profiler_ensure_started(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
1455 features, filters, MOZ_ARRAY_LENGTH(filters), 0);
1456
1457 AUTO_PROFILER_COUNT_TOTAL(TestCounter, 10);
1458 PR_Sleep(PR_MillisecondsToInterval(200));
1459 AUTO_PROFILER_COUNT_TOTAL(TestCounter, 7);
1460 PR_Sleep(PR_MillisecondsToInterval(200));
1461 AUTO_PROFILER_COUNT_TOTAL(TestCounter, -17);
1462 PR_Sleep(PR_MillisecondsToInterval(200));
1463
1464 // Verify we got counters in the output
1465 SpliceableChunkedJSONWriter w;
1466 ASSERT_TRUE(profiler_stream_json_for_this_process(w));
1467
1468 UniquePtr<char[]> profile = w.WriteFunc()->CopyData();
1469
1470 // counter name and description should appear as is.
1471 ASSERT_TRUE(strstr(profile.get(), COUNTER_NAME));
1472 ASSERT_TRUE(strstr(profile.get(), COUNTER_DESCRIPTION));
1473 ASSERT_FALSE(strstr(profile.get(), COUNTER_NAME2));
1474 ASSERT_FALSE(strstr(profile.get(), COUNTER_DESCRIPTION2));
1475
1476 AUTO_PROFILER_COUNT_TOTAL(TestCounter2, 10);
1477 PR_Sleep(PR_MillisecondsToInterval(200));
1478
1479 ASSERT_TRUE(profiler_stream_json_for_this_process(w));
1480
1481 profile = w.WriteFunc()->CopyData();
1482 ASSERT_TRUE(strstr(profile.get(), COUNTER_NAME));
1483 ASSERT_TRUE(strstr(profile.get(), COUNTER_DESCRIPTION));
1484 ASSERT_TRUE(strstr(profile.get(), COUNTER_NAME2));
1485 ASSERT_TRUE(strstr(profile.get(), COUNTER_DESCRIPTION2));
1486
1487 profiler_stop();
1488 }
1489
TEST(GeckoProfiler,Time)1490 TEST(GeckoProfiler, Time)
1491 {
1492 uint32_t features = ProfilerFeature::StackWalk;
1493 const char* filters[] = {"GeckoMain"};
1494
1495 double t1 = profiler_time();
1496 double t2 = profiler_time();
1497 ASSERT_TRUE(t1 <= t2);
1498
1499 // profiler_start() restarts the timer used by profiler_time().
1500 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1501 filters, MOZ_ARRAY_LENGTH(filters), 0);
1502
1503 double t3 = profiler_time();
1504 double t4 = profiler_time();
1505 ASSERT_TRUE(t3 <= t4);
1506
1507 profiler_stop();
1508
1509 double t5 = profiler_time();
1510 double t6 = profiler_time();
1511 ASSERT_TRUE(t4 <= t5 && t1 <= t6);
1512 }
1513
TEST(GeckoProfiler,GetProfile)1514 TEST(GeckoProfiler, GetProfile)
1515 {
1516 uint32_t features = ProfilerFeature::StackWalk;
1517 const char* filters[] = {"GeckoMain"};
1518
1519 ASSERT_TRUE(!profiler_get_profile());
1520
1521 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1522 filters, MOZ_ARRAY_LENGTH(filters), 0);
1523
1524 UniquePtr<char[]> profile = profiler_get_profile();
1525 ASSERT_TRUE(profile && profile[0] == '{');
1526
1527 profiler_stop();
1528
1529 ASSERT_TRUE(!profiler_get_profile());
1530 }
1531
JSONOutputCheck(const char * aOutput)1532 static void JSONOutputCheck(const char* aOutput) {
1533 // Check that various expected strings are in the JSON.
1534
1535 ASSERT_TRUE(aOutput);
1536 ASSERT_TRUE(aOutput[0] == '{');
1537
1538 ASSERT_TRUE(strstr(aOutput, "\"libs\""));
1539
1540 ASSERT_TRUE(strstr(aOutput, "\"meta\""));
1541 ASSERT_TRUE(strstr(aOutput, "\"version\""));
1542 ASSERT_TRUE(strstr(aOutput, "\"startTime\""));
1543
1544 ASSERT_TRUE(strstr(aOutput, "\"threads\""));
1545 ASSERT_TRUE(strstr(aOutput, "\"GeckoMain\""));
1546 ASSERT_TRUE(strstr(aOutput, "\"samples\""));
1547 ASSERT_TRUE(strstr(aOutput, "\"markers\""));
1548 ASSERT_TRUE(strstr(aOutput, "\"stackTable\""));
1549 ASSERT_TRUE(strstr(aOutput, "\"frameTable\""));
1550 ASSERT_TRUE(strstr(aOutput, "\"stringTable\""));
1551 }
1552
TEST(GeckoProfiler,StreamJSONForThisProcess)1553 TEST(GeckoProfiler, StreamJSONForThisProcess)
1554 {
1555 uint32_t features = ProfilerFeature::StackWalk;
1556 const char* filters[] = {"GeckoMain"};
1557
1558 SpliceableChunkedJSONWriter w;
1559 ASSERT_TRUE(!profiler_stream_json_for_this_process(w));
1560
1561 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1562 filters, MOZ_ARRAY_LENGTH(filters), 0);
1563
1564 w.Start();
1565 ASSERT_TRUE(profiler_stream_json_for_this_process(w));
1566 w.End();
1567
1568 UniquePtr<char[]> profile = w.WriteFunc()->CopyData();
1569
1570 JSONOutputCheck(profile.get());
1571
1572 profiler_stop();
1573
1574 ASSERT_TRUE(!profiler_stream_json_for_this_process(w));
1575 }
1576
TEST(GeckoProfiler,StreamJSONForThisProcessThreaded)1577 TEST(GeckoProfiler, StreamJSONForThisProcessThreaded)
1578 {
1579 // Same as the previous test, but calling some things on background threads.
1580 nsCOMPtr<nsIThread> thread;
1581 nsresult rv = NS_NewNamedThread("GeckoProfGTest", getter_AddRefs(thread));
1582 ASSERT_TRUE(NS_SUCCEEDED(rv));
1583
1584 uint32_t features = ProfilerFeature::StackWalk;
1585 const char* filters[] = {"GeckoMain"};
1586
1587 SpliceableChunkedJSONWriter w;
1588 ASSERT_TRUE(!profiler_stream_json_for_this_process(w));
1589
1590 // Start the profiler on the main thread.
1591 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1592 filters, MOZ_ARRAY_LENGTH(filters), 0);
1593
1594 // Call profiler_stream_json_for_this_process on a background thread.
1595 thread->Dispatch(
1596 NS_NewRunnableFunction(
1597 "GeckoProfiler_StreamJSONForThisProcessThreaded_Test::TestBody",
1598 [&]() {
1599 w.Start();
1600 ASSERT_TRUE(profiler_stream_json_for_this_process(w));
1601 w.End();
1602 }),
1603 NS_DISPATCH_SYNC);
1604
1605 UniquePtr<char[]> profile = w.WriteFunc()->CopyData();
1606
1607 JSONOutputCheck(profile.get());
1608
1609 // Stop the profiler and call profiler_stream_json_for_this_process on a
1610 // background thread.
1611 thread->Dispatch(
1612 NS_NewRunnableFunction(
1613 "GeckoProfiler_StreamJSONForThisProcessThreaded_Test::TestBody",
1614 [&]() {
1615 profiler_stop();
1616 ASSERT_TRUE(!profiler_stream_json_for_this_process(w));
1617 }),
1618 NS_DISPATCH_SYNC);
1619 thread->Shutdown();
1620
1621 // Call profiler_stream_json_for_this_process on the main thread.
1622 ASSERT_TRUE(!profiler_stream_json_for_this_process(w));
1623 }
1624
TEST(GeckoProfiler,ProfilingStack)1625 TEST(GeckoProfiler, ProfilingStack)
1626 {
1627 uint32_t features = ProfilerFeature::StackWalk;
1628 const char* filters[] = {"GeckoMain"};
1629
1630 AUTO_PROFILER_LABEL("A::B", OTHER);
1631
1632 UniqueFreePtr<char> dynamic(strdup("dynamic"));
1633 {
1634 AUTO_PROFILER_LABEL_DYNAMIC_CSTR("A::C", JS, dynamic.get());
1635 AUTO_PROFILER_LABEL_DYNAMIC_NSCSTRING("A::C2", JS,
1636 nsDependentCString(dynamic.get()));
1637 AUTO_PROFILER_LABEL_DYNAMIC_LOSSY_NSSTRING(
1638 "A::C3", JS, NS_ConvertUTF8toUTF16(dynamic.get()));
1639
1640 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
1641 features, filters, MOZ_ARRAY_LENGTH(filters), 0);
1642
1643 ASSERT_TRUE(profiler_get_backtrace());
1644 }
1645
1646 AutoProfilerLabel label1("A", nullptr, JS::ProfilingCategoryPair::DOM);
1647 AutoProfilerLabel label2("A", dynamic.get(),
1648 JS::ProfilingCategoryPair::NETWORK);
1649 ASSERT_TRUE(profiler_get_backtrace());
1650
1651 profiler_stop();
1652
1653 ASSERT_TRUE(!profiler_get_profile());
1654 }
1655
TEST(GeckoProfiler,Bug1355807)1656 TEST(GeckoProfiler, Bug1355807)
1657 {
1658 uint32_t features = ProfilerFeature::JS;
1659 const char* manyThreadsFilter[] = {""};
1660 const char* fewThreadsFilter[] = {"GeckoMain"};
1661
1662 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1663 manyThreadsFilter, MOZ_ARRAY_LENGTH(manyThreadsFilter), 0);
1664
1665 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1666 fewThreadsFilter, MOZ_ARRAY_LENGTH(fewThreadsFilter), 0);
1667
1668 // In bug 1355807 this caused an assertion failure in StopJSSampling().
1669 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1670 fewThreadsFilter, MOZ_ARRAY_LENGTH(fewThreadsFilter), 0);
1671
1672 profiler_stop();
1673 }
1674
1675 class GTestStackCollector final : public ProfilerStackCollector {
1676 public:
GTestStackCollector()1677 GTestStackCollector() : mSetIsMainThread(0), mFrames(0) {}
1678
SetIsMainThread()1679 virtual void SetIsMainThread() { mSetIsMainThread++; }
1680
CollectNativeLeafAddr(void * aAddr)1681 virtual void CollectNativeLeafAddr(void* aAddr) { mFrames++; }
CollectJitReturnAddr(void * aAddr)1682 virtual void CollectJitReturnAddr(void* aAddr) { mFrames++; }
CollectWasmFrame(const char * aLabel)1683 virtual void CollectWasmFrame(const char* aLabel) { mFrames++; }
CollectProfilingStackFrame(const js::ProfilingStackFrame & aFrame)1684 virtual void CollectProfilingStackFrame(
1685 const js::ProfilingStackFrame& aFrame) {
1686 mFrames++;
1687 }
1688
1689 int mSetIsMainThread;
1690 int mFrames;
1691 };
1692
DoSuspendAndSample(int aTid,nsIThread * aThread)1693 void DoSuspendAndSample(int aTid, nsIThread* aThread) {
1694 aThread->Dispatch(
1695 NS_NewRunnableFunction("GeckoProfiler_SuspendAndSample_Test::TestBody",
1696 [&]() {
1697 uint32_t features = ProfilerFeature::Leaf;
1698 GTestStackCollector collector;
1699 profiler_suspend_and_sample_thread(
1700 aTid, features, collector,
1701 /* sampleNative = */ true);
1702
1703 ASSERT_TRUE(collector.mSetIsMainThread == 1);
1704 ASSERT_TRUE(collector.mFrames > 0);
1705 }),
1706 NS_DISPATCH_SYNC);
1707 }
1708
TEST(GeckoProfiler,SuspendAndSample)1709 TEST(GeckoProfiler, SuspendAndSample)
1710 {
1711 nsCOMPtr<nsIThread> thread;
1712 nsresult rv = NS_NewNamedThread("GeckoProfGTest", getter_AddRefs(thread));
1713 ASSERT_TRUE(NS_SUCCEEDED(rv));
1714
1715 int tid = profiler_current_thread_id();
1716
1717 ASSERT_TRUE(!profiler_is_active());
1718
1719 // Suspend and sample while the profiler is inactive.
1720 DoSuspendAndSample(tid, thread);
1721
1722 uint32_t features = ProfilerFeature::JS | ProfilerFeature::Threads;
1723 const char* filters[] = {"GeckoMain", "Compositor"};
1724
1725 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features,
1726 filters, MOZ_ARRAY_LENGTH(filters), 0);
1727
1728 ASSERT_TRUE(profiler_is_active());
1729
1730 // Suspend and sample while the profiler is active.
1731 DoSuspendAndSample(tid, thread);
1732
1733 profiler_stop();
1734
1735 ASSERT_TRUE(!profiler_is_active());
1736 }
1737
1738 // Returns `static_cast<SamplingState>(-1)` if callback could not be installed.
WaitForSamplingState()1739 static SamplingState WaitForSamplingState() {
1740 Atomic<int> samplingState{-1};
1741
1742 if (!profiler_callback_after_sampling([&](SamplingState aSamplingState) {
1743 samplingState = static_cast<int>(aSamplingState);
1744 })) {
1745 return static_cast<SamplingState>(-1);
1746 }
1747
1748 while (samplingState == -1) {
1749 }
1750
1751 return static_cast<SamplingState>(static_cast<int>(samplingState));
1752 }
1753
TEST(GeckoProfiler,PostSamplingCallback)1754 TEST(GeckoProfiler, PostSamplingCallback)
1755 {
1756 const char* filters[] = {"GeckoMain"};
1757
1758 ASSERT_TRUE(!profiler_is_active());
1759 ASSERT_TRUE(!profiler_callback_after_sampling(
1760 [&](SamplingState) { ASSERT_TRUE(false); }));
1761
1762 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
1763 ProfilerFeature::StackWalk, filters, MOZ_ARRAY_LENGTH(filters),
1764 0);
1765 {
1766 // Stack sampling -> This label should appear at least once.
1767 AUTO_PROFILER_LABEL("PostSamplingCallback completed", OTHER);
1768 ASSERT_EQ(WaitForSamplingState(), SamplingState::SamplingCompleted);
1769 }
1770 UniquePtr<char[]> profileCompleted = profiler_get_profile();
1771 ASSERT_TRUE(profileCompleted);
1772 ASSERT_TRUE(profileCompleted[0] == '{');
1773 ASSERT_TRUE(strstr(profileCompleted.get(), "PostSamplingCallback completed"));
1774
1775 profiler_pause();
1776 {
1777 // Paused -> This label should not appear.
1778 AUTO_PROFILER_LABEL("PostSamplingCallback paused", OTHER);
1779 ASSERT_EQ(WaitForSamplingState(), SamplingState::SamplingPaused);
1780 }
1781 UniquePtr<char[]> profilePaused = profiler_get_profile();
1782 ASSERT_TRUE(profilePaused);
1783 ASSERT_TRUE(profilePaused[0] == '{');
1784 ASSERT_FALSE(strstr(profilePaused.get(), "PostSamplingCallback paused"));
1785
1786 profiler_resume();
1787 {
1788 // Stack sampling -> This label should appear at least once.
1789 AUTO_PROFILER_LABEL("PostSamplingCallback resumed", OTHER);
1790 ASSERT_EQ(WaitForSamplingState(), SamplingState::SamplingCompleted);
1791 }
1792 UniquePtr<char[]> profileResumed = profiler_get_profile();
1793 ASSERT_TRUE(profileResumed);
1794 ASSERT_TRUE(profileResumed[0] == '{');
1795 ASSERT_TRUE(strstr(profileResumed.get(), "PostSamplingCallback resumed"));
1796
1797 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
1798 ProfilerFeature::StackWalk | ProfilerFeature::NoStackSampling,
1799 filters, MOZ_ARRAY_LENGTH(filters), 0);
1800 {
1801 // No stack sampling -> This label should not appear.
1802 AUTO_PROFILER_LABEL("PostSamplingCallback completed (no stacks)", OTHER);
1803 ASSERT_EQ(WaitForSamplingState(), SamplingState::NoStackSamplingCompleted);
1804 }
1805 UniquePtr<char[]> profileNoStacks = profiler_get_profile();
1806 ASSERT_TRUE(profileNoStacks);
1807 ASSERT_TRUE(profileNoStacks[0] == '{');
1808 ASSERT_FALSE(strstr(profileNoStacks.get(),
1809 "PostSamplingCallback completed (no stacks)"));
1810
1811 // Note: There is no non-racy way to test for SamplingState::JustStopped, as
1812 // it would require coordination between `profiler_stop()` and another thread
1813 // doing `profiler_callback_after_sampling()` at just the right moment.
1814
1815 profiler_stop();
1816 ASSERT_TRUE(!profiler_is_active());
1817 ASSERT_TRUE(!profiler_callback_after_sampling(
1818 [&](SamplingState) { ASSERT_TRUE(false); }));
1819 }
1820
TEST(GeckoProfiler,BaseProfilerHandOff)1821 TEST(GeckoProfiler, BaseProfilerHandOff)
1822 {
1823 const char* filters[] = {"GeckoMain"};
1824
1825 ASSERT_TRUE(!baseprofiler::profiler_is_active());
1826 ASSERT_TRUE(!profiler_is_active());
1827
1828 // Start the Base Profiler.
1829 baseprofiler::profiler_start(
1830 PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
1831 ProfilerFeature::StackWalk, filters, MOZ_ARRAY_LENGTH(filters));
1832
1833 ASSERT_TRUE(baseprofiler::profiler_is_active());
1834 ASSERT_TRUE(!profiler_is_active());
1835
1836 // Add at least a marker, which should go straight into the buffer.
1837 Maybe<baseprofiler::ProfilerBufferInfo> info0 =
1838 baseprofiler::profiler_get_buffer_info();
1839 BASE_PROFILER_ADD_MARKER("Marker from base profiler", OTHER);
1840 Maybe<baseprofiler::ProfilerBufferInfo> info1 =
1841 baseprofiler::profiler_get_buffer_info();
1842 ASSERT_GT(info1->mRangeEnd, info0->mRangeEnd);
1843
1844 // Start the Gecko Profiler, which should grab the Base Profiler profile and
1845 // stop it.
1846 profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL,
1847 ProfilerFeature::StackWalk, filters, MOZ_ARRAY_LENGTH(filters),
1848 0);
1849
1850 ASSERT_TRUE(!baseprofiler::profiler_is_active());
1851 ASSERT_TRUE(profiler_is_active());
1852
1853 // Write some Gecko Profiler samples.
1854 ASSERT_EQ(WaitForSamplingState(), SamplingState::SamplingCompleted);
1855
1856 // Check that the Gecko Profiler profile contains at least the Base Profiler
1857 // main thread samples.
1858 UniquePtr<char[]> profile = profiler_get_profile();
1859 ASSERT_TRUE(profile);
1860 ASSERT_TRUE(profile[0] == '{');
1861 ASSERT_TRUE(strstr(profile.get(), "GeckoMain (pre-xul)"));
1862 ASSERT_TRUE(strstr(profile.get(), "Marker from base profiler"));
1863
1864 profiler_stop();
1865 ASSERT_TRUE(!profiler_is_active());
1866 }
1867