From 8c14c7f000ea8be4b7681ec2582e466ad1dabe3f Mon Sep 17 00:00:00 2001 From: Gerald Squelart Date: Tue, 8 Oct 2019 02:16:00 +0000 Subject: [PATCH] Bug 1586132 - Use jsoncpp to test profiler output in Profiler.Markers gtest - r=gregtatum This does not test more markers than before. But instead of searching for strings in the raw json, expected values are checked in the parsed output profile. Also some `ASSERT_...` tests could be changed to `EXPECT_...`, because their failures would not prevent running more of the test. Differential Revision: https://phabricator.services.mozilla.com/D48326 --HG-- extra : moz-landing-system : lando --- tools/profiler/tests/gtest/GeckoProfiler.cpp | 315 ++++++++++++++++--- tools/profiler/tests/gtest/moz.build | 5 + 2 files changed, 277 insertions(+), 43 deletions(-) diff --git a/tools/profiler/tests/gtest/GeckoProfiler.cpp b/tools/profiler/tests/gtest/GeckoProfiler.cpp index 246ba119984d..8715b63afc2e 100644 --- a/tools/profiler/tests/gtest/GeckoProfiler.cpp +++ b/tools/profiler/tests/gtest/GeckoProfiler.cpp @@ -18,6 +18,7 @@ #include "js/Initialization.h" #include "js/Printf.h" #include "jsapi.h" +#include "json/json.h" #include "mozilla/BlocksRingBufferGeckoExtensions.h" #include "mozilla/UniquePtrExtensions.h" #include "nsIThread.h" @@ -25,7 +26,7 @@ #include "gtest/gtest.h" -#include +#include // Note: profiler_init() has already been called in XRE_main(), so we can't // test it here. Likewise for profiler_shutdown(), and AutoProfilerInit @@ -580,15 +581,17 @@ TEST(GeckoProfiler, Markers) profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features, filters, MOZ_ARRAY_LENGTH(filters)); - profiler_tracing("A", "B", JS::ProfilingCategoryPair::OTHER, TRACING_EVENT); - PROFILER_TRACING("A", "C", OTHER, TRACING_INTERVAL_START); - PROFILER_TRACING("A", "C", OTHER, TRACING_INTERVAL_END); + profiler_tracing("A", "tracing event", JS::ProfilingCategoryPair::OTHER, + TRACING_EVENT); + PROFILER_TRACING("A", "tracing start", OTHER, TRACING_INTERVAL_START); + PROFILER_TRACING("A", "tracing end", OTHER, TRACING_INTERVAL_END); UniqueProfilerBacktrace bt = profiler_get_backtrace(); - profiler_tracing("B", "A", JS::ProfilingCategoryPair::OTHER, TRACING_EVENT, + profiler_tracing("B", "tracing event with stack", + JS::ProfilingCategoryPair::OTHER, TRACING_EVENT, std::move(bt)); - { AUTO_PROFILER_TRACING("C", "A", OTHER); } + { AUTO_PROFILER_TRACING("C", "auto tracing", OTHER); } PROFILER_ADD_MARKER("M1", OTHER); PROFILER_ADD_MARKER_WITH_PAYLOAD("M2", OTHER, TracingMarkerPayload, @@ -604,13 +607,13 @@ TEST(GeckoProfiler, Markers) } // The GTestMarkerPayloads should have been created, serialized, and // destroyed. - ASSERT_EQ(GTestMarkerPayload::sNumCreated, 10); - ASSERT_EQ(GTestMarkerPayload::sNumSerialized, 10); - ASSERT_EQ(GTestMarkerPayload::sNumDeserialized, 0); - ASSERT_EQ(GTestMarkerPayload::sNumStreamed, 0); - ASSERT_EQ(GTestMarkerPayload::sNumDestroyed, 10); + EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10); + EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10); + EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0); + EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0); + EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10); - // Create two strings: one that is the maximum allowed length, and one that + // Create three strings: two that are the maximum allowed length, and one that // is one char longer. static const size_t kMax = ProfileBuffer::kMaxFrameKeyLength; UniquePtr okstr1 = MakeUnique(kMax); @@ -624,8 +627,11 @@ TEST(GeckoProfiler, Markers) okstr1[kMax - 1] = '\0'; okstr2[kMax - 1] = '\0'; longstr[kMax] = '\0'; + // Should be output as-is. AUTO_PROFILER_LABEL_DYNAMIC_CSTR("", LAYOUT, okstr1.get()); + // Should be output as label + space + okstr2. AUTO_PROFILER_LABEL_DYNAMIC_CSTR("okstr2", LAYOUT, okstr2.get()); + // Should be output as "(too long)". AUTO_PROFILER_LABEL_DYNAMIC_CSTR("", LAYOUT, longstr.get()); // Sleep briefly to ensure a sample is taken and the pending markers are @@ -633,33 +639,255 @@ TEST(GeckoProfiler, Markers) PR_Sleep(PR_MillisecondsToInterval(500)); SpliceableChunkedJSONWriter w; - ASSERT_TRUE(profiler_stream_json_for_this_process(w)); - - UniquePtr profile = w.WriteFunc()->CopyData(); + w.Start(); + EXPECT_TRUE(profiler_stream_json_for_this_process(w)); + w.End(); // The GTestMarkerPayloads should have been deserialized, streamed, and // destroyed. - ASSERT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10); - ASSERT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10); - ASSERT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10); - for (int i = 0; i < 10; i++) { - char buf[64]; - SprintfLiteral(buf, "\"gtest-%d\"", i); - ASSERT_TRUE(strstr(profile.get(), buf)); + EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10); + EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10); + EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10); + + UniquePtr profile = w.WriteFunc()->CopyData(); + ASSERT_TRUE(!!profile.get()); + + // Expected markers, in order. + enum State { + S_tracing_event, + S_tracing_start, + S_tracing_end, + S_tracing_event_with_stack, + S_tracing_auto_tracing_start, + S_tracing_auto_tracing_end, + S_M1, + S_tracing_M2_C, + S_M3, + S_tracing_M4_C_stack, + S_M5_gtest0, + S_M5_gtest1, + S_M5_gtest2, + S_M5_gtest3, + S_M5_gtest4, + S_M5_gtest5, + S_M5_gtest6, + S_M5_gtest7, + S_M5_gtest8, + S_M5_gtest9, + + S_LAST, + } state = State(0); + + // Extract JSON. + Json::Value parsedRoot; + Json::CharReaderBuilder builder; + const std::unique_ptr reader(builder.newCharReader()); + ASSERT_TRUE(reader->parse(profile.get(), strchr(profile.get(), '\0'), + &parsedRoot, nullptr)); + + // Use const root, we only want to test what's in the profile, not change it. + const Json::Value& root = parsedRoot; + ASSERT_TRUE(root.isObject()); + + // We have a root object. + + // Most common test: Checks that the given value is present, is of the + // expected type, and has the expected value. +#define EXPECT_EQ_JSON(GETTER, TYPE, VALUE) \ + if ((GETTER).isNull()) { \ + EXPECT_FALSE((GETTER).isNull()); \ + } else if (!(GETTER).is##TYPE()) { \ + EXPECT_TRUE((GETTER).is##TYPE()); \ + } else { \ + EXPECT_EQ((GETTER).as##TYPE(), (VALUE)); \ } - // okstr1 should appear as is. - ASSERT_TRUE(strstr(profile.get(), okstr1.get())); + { + const Json::Value& threads = root["threads"]; + ASSERT_TRUE(!threads.isNull()); + ASSERT_TRUE(threads.isArray()); + ASSERT_EQ(threads.size(), 1u); - // okstr2 should appear, slightly truncated with "okstr2 " in front of it. - // (Nb: this only checks the front part of the marker string.) - ASSERT_TRUE(strstr(profile.get(), "okstr2 bbbbbbbbb")); + // root.threads is a 1-element array. - // longstr should be replaced with "(too long)". - ASSERT_TRUE(!strstr(profile.get(), longstr.get())); - ASSERT_TRUE(strstr(profile.get(), "(too long)")); + { + const Json::Value& thread0 = threads[0]; + ASSERT_TRUE(thread0.isObject()); + + // root.threads[0] is an object. + + // Keep a reference to the string table in this block, it will be used + // below. + const Json::Value& stringTable = thread0["stringTable"]; + ASSERT_TRUE(stringTable.isArray()); + + // Test the expected labels in the string table. + bool foundOkstr1 = false; + bool foundOkstr2 = false; + const std::string okstr2Label = std::string("okstr2 ") + okstr2.get(); + bool foundTooLong = false; + for (const auto& s : stringTable) { + ASSERT_TRUE(s.isString()); + std::string sString = s.asString(); + if (sString == okstr1.get()) { + EXPECT_FALSE(foundOkstr1); + foundOkstr1 = true; + } else if (sString == okstr2Label) { + EXPECT_FALSE(foundOkstr2); + foundOkstr2 = true; + } else if (sString == "(too long)") { + EXPECT_FALSE(foundTooLong); + foundTooLong = true; + } else { + EXPECT_NE(sString, longstr.get()); + } + } + EXPECT_TRUE(foundOkstr1); + EXPECT_TRUE(foundOkstr2); + EXPECT_TRUE(foundTooLong); + + { + const Json::Value& markers = thread0["markers"]; + ASSERT_TRUE(markers.isObject()); + + // root.threads[0].markers is an object. + + { + const Json::Value& data = markers["data"]; + ASSERT_TRUE(data.isArray()); + + // root.threads[0].markers.data is an array. + + for (const Json::Value& marker : data) { + ASSERT_TRUE(marker.isArray()); + ASSERT_GE(marker.size(), 3u); + ASSERT_LE(marker.size(), 4u); + + // root.threads[0].markers.data[i] is an array with 3 or 4 elements. + + ASSERT_TRUE(marker[0].isUInt()); // name id + const Json::Value& name = stringTable[marker[0].asUInt()]; + ASSERT_TRUE(name.isString()); + std::string nameString = name.asString(); + + EXPECT_TRUE(marker[1].isNumeric()); // timestamp + + EXPECT_TRUE(marker[2].isUInt()); // category + + if (marker.size() == 3u) { + // root.threads[0].markers.data[i] is an array with 3 elements, + // so there is no payload. + if (nameString == "M1") { + ASSERT_EQ(state, S_M1); + state = State(state + 1); + } else if (nameString == "M3") { + ASSERT_EQ(state, S_M3); + state = State(state + 1); + } + } else { + // root.threads[0].markers.data[i] is an array with 4 elements, + // so there is a payload. + const Json::Value& payload = marker[3]; + ASSERT_TRUE(payload.isObject()); + + // root.threads[0].markers.data[i][3] is an object (payload). + + // It should at least have a "type" string. + const Json::Value& type = payload["type"]; + ASSERT_TRUE(type.isString()); + std::string typeString = type.asString(); + + if (nameString == "tracing event") { + EXPECT_EQ(state, S_tracing_event); + state = State(S_tracing_event + 1); + EXPECT_EQ(typeString, "tracing"); + EXPECT_EQ_JSON(payload["category"], String, "A"); + EXPECT_TRUE(payload["interval"].isNull()); + EXPECT_TRUE(payload["stack"].isNull()); + } else if (nameString == "tracing start") { + EXPECT_EQ(state, S_tracing_start); + state = State(S_tracing_start + 1); + EXPECT_EQ(typeString, "tracing"); + EXPECT_EQ_JSON(payload["category"], String, "A"); + EXPECT_EQ_JSON(payload["interval"], String, "start"); + EXPECT_TRUE(payload["stack"].isNull()); + } else if (nameString == "tracing end") { + EXPECT_EQ(state, S_tracing_end); + state = State(S_tracing_end + 1); + EXPECT_EQ(typeString, "tracing"); + EXPECT_EQ_JSON(payload["category"], String, "A"); + EXPECT_EQ_JSON(payload["interval"], String, "end"); + EXPECT_TRUE(payload["stack"].isNull()); + } else if (nameString == "tracing event with stack") { + EXPECT_EQ(state, S_tracing_event_with_stack); + state = State(S_tracing_event_with_stack + 1); + EXPECT_EQ(typeString, "tracing"); + EXPECT_EQ_JSON(payload["category"], String, "B"); + EXPECT_TRUE(payload["interval"].isNull()); + EXPECT_TRUE(payload["stack"].isObject()); + } else if (nameString == "auto tracing") { + switch (state) { + case S_tracing_auto_tracing_start: + state = State(S_tracing_auto_tracing_start + 1); + EXPECT_EQ_JSON(payload["category"], String, "C"); + EXPECT_EQ_JSON(payload["interval"], String, "start"); + EXPECT_TRUE(payload["stack"].isNull()); + break; + case S_tracing_auto_tracing_end: + state = State(S_tracing_auto_tracing_end + 1); + EXPECT_EQ_JSON(payload["category"], String, "C"); + EXPECT_EQ_JSON(payload["interval"], String, "end"); + ASSERT_TRUE(payload["stack"].isNull()); + break; + default: + EXPECT_TRUE(state == S_tracing_auto_tracing_start || + state == S_tracing_auto_tracing_end); + break; + } + } else if (nameString == "M2") { + EXPECT_EQ(state, S_tracing_M2_C); + state = State(S_tracing_M2_C + 1); + EXPECT_EQ(typeString, "tracing"); + EXPECT_EQ_JSON(payload["category"], String, "C"); + EXPECT_TRUE(payload["interval"].isNull()); + EXPECT_TRUE(payload["stack"].isNull()); + } else if (nameString == "M4") { + EXPECT_EQ(state, S_tracing_M4_C_stack); + state = State(S_tracing_M4_C_stack + 1); + EXPECT_EQ(typeString, "tracing"); + EXPECT_EQ_JSON(payload["category"], String, "C"); + EXPECT_TRUE(payload["interval"].isNull()); + EXPECT_TRUE(payload["stack"].isObject()); + } else if (nameString == "M5") { + EXPECT_EQ(typeString, "gtest"); + // It should only have one more element (apart from "type"). + ASSERT_EQ(payload.size(), 2u); + const auto itEnd = payload.end(); + for (auto it = payload.begin(); it != itEnd; ++it) { + std::string key = it.name(); + if (key != "type") { + const Json::Value& value = *it; + ASSERT_TRUE(value.isInt()); + int valueInt = value.asInt(); + // We expect `"gtest-" : `. + EXPECT_EQ(state, State(S_M5_gtest0 + valueInt)); + state = State(state + 1); + EXPECT_EQ(key, + std::string("gtest-") + std::to_string(valueInt)); + } + } + } + } // marker with payload + } // for (marker:data) + } // markers.data + } // markers + } // thread0 + } // threads + + // We should have read all expected markers. + EXPECT_EQ(state, S_LAST); Maybe info = profiler_get_buffer_info(); MOZ_RELEASE_ASSERT(info.isSome()); @@ -693,12 +921,13 @@ TEST(GeckoProfiler, Markers) profiler_stop(); // Nothing more should have happened to the GTestMarkerPayloads. - ASSERT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10 + 0); + // Try to add markers while the profiler is stopped. for (int i = 0; i < 10; i++) { PROFILER_ADD_MARKER_WITH_PAYLOAD("M5", OTHER, GTestMarkerPayload, (i)); } @@ -707,17 +936,17 @@ TEST(GeckoProfiler, Markers) profiler_start(PROFILER_DEFAULT_ENTRIES, PROFILER_DEFAULT_INTERVAL, features, filters, MOZ_ARRAY_LENGTH(filters)); - ASSERT_TRUE(profiler_stream_json_for_this_process(w)); + EXPECT_TRUE(profiler_stream_json_for_this_process(w)); profiler_stop(); // The second set of GTestMarkerPayloads should not have been serialized or // streamed. - ASSERT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0 + 0 + 10); - ASSERT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0 + 0 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10 + 0 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10 + 0 + 0); - ASSERT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10 + 0 + 10); + EXPECT_EQ(GTestMarkerPayload::sNumCreated, 10 + 0 + 0 + 10); + EXPECT_EQ(GTestMarkerPayload::sNumSerialized, 10 + 0 + 0 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumDeserialized, 0 + 10 + 0 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumStreamed, 0 + 10 + 0 + 0); + EXPECT_EQ(GTestMarkerPayload::sNumDestroyed, 10 + 10 + 0 + 10); } TEST(GeckoProfiler, DurationLimit) diff --git a/tools/profiler/tests/gtest/moz.build b/tools/profiler/tests/gtest/moz.build index 2922bd9a2edc..51718e0e0743 100644 --- a/tools/profiler/tests/gtest/moz.build +++ b/tools/profiler/tests/gtest/moz.build @@ -13,6 +13,7 @@ if (CONFIG['OS_TARGET'] in ('Android', 'Linux') and ] LOCAL_INCLUDES += [ + '/toolkit/components/jsoncpp/include', '/tools/profiler/core', '/tools/profiler/gecko', '/tools/profiler/lul', @@ -24,6 +25,10 @@ if CONFIG['OS_TARGET'] != 'Android': 'ThreadProfileTest.cpp', ] +USE_LIBS += [ + 'jsoncpp', +] + FINAL_LIBRARY = 'xul-gtest' if CONFIG['CC_TYPE'] in ('clang', 'gcc'):