From 6b4dfc2df9271b2e9e0b9e0e0a78f715ddebf36e Mon Sep 17 00:00:00 2001 From: Derek Lamberti Date: Wed, 7 Aug 2019 17:01:57 +0100 Subject: IVGCVSW-3603 *Json printer prints full profiling hierarchy Change-Id: Ide5acbf993c2bcff5265b72fc979caa6f183bb22 Signed-off-by: Derek Lamberti --- src/armnn/JsonPrinter.cpp | 70 +++++++++++-- src/armnn/JsonPrinter.hpp | 33 +++++- src/armnn/Profiling.cpp | 110 +++++++++---------- src/armnn/Profiling.hpp | 8 +- src/armnn/test/ProfilerTests.cpp | 106 ++++++++++++++++++- .../backendsCommon/test/JsonPrinterTestImpl.cpp | 116 ++------------------- 6 files changed, 258 insertions(+), 185 deletions(-) diff --git a/src/armnn/JsonPrinter.cpp b/src/armnn/JsonPrinter.cpp index 97cd5f2b4b..9dc648c538 100644 --- a/src/armnn/JsonPrinter.cpp +++ b/src/armnn/JsonPrinter.cpp @@ -7,25 +7,41 @@ #include #include +#include namespace armnn { -void JsonPrinter::PrintJsonChildObject(const JsonChildObject& object) +void JsonPrinter::PrintJsonChildObject(const JsonChildObject& object, size_t& id) { - PrintLabel(object.m_Label); - PrintMeasurementsList(object.m_Measurements); - PrintSeparator(); - PrintNewLine(); - PrintUnit(object.m_Unit); + if (object.GetType() == JsonObjectType::Event) + { + // Increase the Id for new events. This ensures a new event has a unique ID and any measurements belonging + // to the event have the same id. This id is appended to the name during the call to PrintLabel() below. + id++; + } - if (!object.m_Children.empty()) + PrintLabel(object.m_Label, id); + PrintType(object.m_Type); + + if (!object.m_Measurements.empty() || !object.m_Children.empty()) { PrintSeparator(); PrintNewLine(); + } + + if (object.GetType() == JsonObjectType::Measurement) + { + PrintMeasurementsList(object.m_Measurements); + PrintSeparator(); + PrintNewLine(); + PrintUnit(object.m_Unit); + } + if (!object.m_Children.empty()) + { for (unsigned int childIndex = 0; childIndex < object.m_Children.size(); ++childIndex) { - PrintJsonChildObject(object.m_Children[childIndex]); + PrintJsonChildObject(object.m_Children[childIndex], id); // Only print separator and new line if current child is not the last element. if (&object.m_Children[childIndex] != &object.m_Children.back()) { @@ -51,10 +67,17 @@ void JsonPrinter::PrintArmNNHeader() IncrementNumberOfTabs(); } -void JsonPrinter::PrintLabel(const std::string& label) +std::string JsonPrinter::MakeKey(const std::string& label, size_t id) +{ + std::stringstream ss; + ss << label << std::string("_#") << id; + return ss.str(); +} + +void JsonPrinter::PrintLabel(const std::string& label, size_t id) { PrintTabs(); - m_OutputStream << R"(")" << label << R"(": {)" << std::endl; + m_OutputStream << R"(")" << MakeKey(label, id) << R"(": {)" << std::endl; IncrementNumberOfTabs(); } @@ -66,6 +89,33 @@ void JsonPrinter::PrintUnit(armnn::Measurement::Unit unit) m_OutputStream << R"(")"; } +void JsonPrinter::PrintType(armnn::JsonObjectType type) +{ + auto ToString = [](armnn::JsonObjectType type) + { + switch (type) + { + case JsonObjectType::Measurement: + { + return "Measurement"; + } + case JsonObjectType::Event: + { + return "Event"; + } + default: + { + return "Unknown"; + } + } + }; + PrintTabs(); + m_OutputStream << R"("type": ")"; + m_OutputStream << ToString(type); + m_OutputStream << R"(")"; +} + + void JsonPrinter::PrintMeasurementsList(const std::vector& measurementsVector) { if (measurementsVector.empty()) diff --git a/src/armnn/JsonPrinter.hpp b/src/armnn/JsonPrinter.hpp index 12a0891a97..04f56b0134 100644 --- a/src/armnn/JsonPrinter.hpp +++ b/src/armnn/JsonPrinter.hpp @@ -8,16 +8,23 @@ #include #include #include +#include #include "Instrument.hpp" namespace armnn { +enum class JsonObjectType +{ + Measurement, + Event +}; + struct JsonChildObject { JsonChildObject(const std::string& label) - : m_Label(label), m_Unit(Measurement::Unit::TIME_MS) + : m_Label(label), m_Unit(Measurement::Unit::TIME_MS), m_Type(JsonObjectType::Event) {} JsonChildObject(const JsonChildObject&) = default; @@ -31,7 +38,7 @@ struct JsonChildObject m_Children.push_back(childObject); } - JsonChildObject GetChild(const unsigned int index) + JsonChildObject& GetChild(const unsigned int index) { return m_Children[index]; } @@ -41,10 +48,26 @@ struct JsonChildObject m_Unit = unit; } + size_t NumChildren() const + { + return m_Children.size(); + } + + void SetType(JsonObjectType type) + { + m_Type = type; + } + + JsonObjectType GetType() const + { + return m_Type; + } + ~JsonChildObject() = default; std::string m_Label; Measurement::Unit m_Unit; + JsonObjectType m_Type; std::vector m_Measurements; std::vector m_Children; @@ -55,14 +78,15 @@ private: class JsonPrinter { public: - void PrintJsonChildObject(const JsonChildObject& object); + void PrintJsonChildObject(const JsonChildObject& object, size_t& id); void PrintHeader(); void PrintArmNNHeader(); void PrintFooter(); void PrintSeparator(); void PrintNewLine(); - void PrintLabel(const std::string& label); + void PrintLabel(const std::string& label, size_t id); void PrintUnit(armnn::Measurement::Unit unit); + void PrintType(armnn::JsonObjectType type); void PrintMeasurementsList(const std::vector& measurementsVector); public: @@ -71,6 +95,7 @@ public: {} private: + std::string MakeKey(const std::string& label, size_t id); void PrintTabs(); void DecrementNumberOfTabs(); void IncrementNumberOfTabs(); diff --git a/src/armnn/Profiling.cpp b/src/armnn/Profiling.cpp index d30a64fedb..1cd21ab63c 100644 --- a/src/armnn/Profiling.cpp +++ b/src/armnn/Profiling.cpp @@ -280,6 +280,53 @@ void Profiler::PopulateDescendants(std::map> descendantsMap) +{ + BOOST_ASSERT(parentEvent); + std::vector instrumentMeasurements = parentEvent->GetMeasurements(); + unsigned int childIdx=0; + for(size_t measurementIndex = 0; measurementIndex < instrumentMeasurements.size(); ++measurementIndex, ++childIdx) + { + if (inferenceIndex == 0) + { + // Only add kernel measurement once, in case of multiple inferences + JsonChildObject measurementObject{instrumentMeasurements[measurementIndex].m_Name}; + measurementObject.SetUnit(instrumentMeasurements[measurementIndex].m_Unit); + measurementObject.SetType(JsonObjectType::Measurement); + + BOOST_ASSERT(parentObject.NumChildren() == childIdx); + parentObject.AddChild(measurementObject); + } + + parentObject.GetChild(childIdx).AddMeasurement(instrumentMeasurements[measurementIndex].m_Value); + } + + + auto childEventsIt = descendantsMap.find(parentEvent); + if (childEventsIt != descendantsMap.end()) + { + for (auto childEvent : childEventsIt->second) + { + if (inferenceIndex == 0) + { + // Only add second level once, in case of multiple inferences + JsonChildObject childObject{childEvent->GetName()}; + childObject.SetType(JsonObjectType::Event); + parentObject.AddChild(childObject); + } + + // Recursively process children. In reality this won't be very deep recursion. ~4-6 levels deep. + ExtractJsonObjects(inferenceIndex, childEvent, parentObject.GetChild(childIdx), descendantsMap); + + childIdx++; + } + } +} + void Profiler::Print(std::ostream& outStream) const { // Makes sure timestamps are output with 6 decimals, and save old settings. @@ -306,72 +353,15 @@ void Profiler::Print(std::ostream& outStream) const for (unsigned int inferenceIndex = 0; inferenceIndex < inferences.size(); ++inferenceIndex) { auto inference = inferences[inferenceIndex]; - Measurement measurement = FindMeasurement(WallClockTimer::WALL_CLOCK_TIME, inference); - inferenceObject.SetUnit(measurement.m_Unit); - inferenceObject.AddMeasurement(measurement.m_Value); - - auto layerEventsIt = descendantsMap.find(inference); - - // Assuming 1 Execute per inference - if (layerEventsIt != descendantsMap.end()) - { - auto layerEvent = layerEventsIt->second[0]; - Measurement measurement = FindMeasurement(WallClockTimer::WALL_CLOCK_TIME, layerEvent); - layerObject.SetUnit(measurement.m_Unit); - layerObject.AddMeasurement(measurement.m_Value); - - // Get Descendant Events for Execute - auto workloadEventsIt = descendantsMap.find(layerEvent); - for(unsigned int workloadIndex = 0; workloadIndex < workloadEventsIt->second.size(); ++workloadIndex) - { - auto workloadEvent = workloadEventsIt->second[workloadIndex]; - Measurement measurement = FindMeasurement(WallClockTimer::WALL_CLOCK_TIME, workloadEvent); - std::vector kernelMeasurements = FindKernelMeasurements(workloadEvent); - if (inferenceIndex == 0) - { - // Only add second level once, in case of multiple inferences - JsonChildObject workloadObject{workloadEvent->GetName()}; - workloadObject.SetUnit(measurement.m_Unit); - workloadObjects.push_back(workloadObject); - } - workloadObjects[workloadIndex].AddMeasurement(measurement.m_Value); - - for(unsigned int kernelIndex = 0; kernelIndex < kernelMeasurements.size(); ++kernelIndex) - { - if (inferenceIndex == 0) - { - // Only add kernel measurement once, in case of multiple inferences - JsonChildObject kernelObject{kernelMeasurements[kernelIndex].m_Name}; - kernelObject.SetUnit(kernelMeasurements[kernelIndex].m_Unit); - workloadToKernelObjects[workloadIndex].push_back(kernelObject); - - } - workloadToKernelObjects[workloadIndex][kernelIndex]. - AddMeasurement(kernelMeasurements[kernelIndex].m_Value); - } - } - } - } - - for (auto workloadToKernelPair : workloadToKernelObjects) - { - for (auto kernelObject : workloadToKernelPair.second) - { - workloadObjects[workloadToKernelPair.first].AddChild(kernelObject); - } - } - - for (auto workloadObject : workloadObjects) - { - layerObject.AddChild(workloadObject); + ExtractJsonObjects(inferenceIndex, inference, inferenceObject, descendantsMap); } - inferenceObject.AddChild(layerObject); printer.PrintHeader(); printer.PrintArmNNHeader(); // print inference object, also prints child layer and kernel measurements - printer.PrintJsonChildObject(inferenceObject); + size_t id=0; + printer.PrintJsonChildObject(inferenceObject, id); // end of ArmNN printer.PrintNewLine(); diff --git a/src/armnn/Profiling.hpp b/src/armnn/Profiling.hpp index 0b2e46d46d..d52bbb0aec 100644 --- a/src/armnn/Profiling.hpp +++ b/src/armnn/Profiling.hpp @@ -158,9 +158,15 @@ private: } // namespace armnn + +#include + +#define ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS_UNIQUE_LOC(backendId, /*name,*/ ...) \ + armnn::ScopedProfilingEvent BOOST_PP_CAT(e_,__LINE__)(backendId, /*name,*/ __VA_ARGS__); + // The event name must be known at compile time #define ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS(backendId, /*name,*/ ...) \ - armnn::ScopedProfilingEvent e_##__FILE__##__LINE__(backendId, /*name,*/ __VA_ARGS__); + ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS_UNIQUE_LOC(backendId, /*name,*/ __VA_ARGS__); #define ARMNN_SCOPED_PROFILING_EVENT(backendId, name) \ ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS(backendId, name, armnn::WallClockTimer()) diff --git a/src/armnn/test/ProfilerTests.cpp b/src/armnn/test/ProfilerTests.cpp index f6688eafc9..90f6d8b133 100644 --- a/src/armnn/test/ProfilerTests.cpp +++ b/src/armnn/test/ProfilerTests.cpp @@ -9,6 +9,7 @@ #include #include +#include #include #include @@ -240,4 +241,107 @@ BOOST_AUTO_TEST_CASE(WriteEventResults) profiler->EnableProfiling(false); } -BOOST_AUTO_TEST_SUITE_END() +BOOST_AUTO_TEST_CASE(ProfilerJsonPrinter) +{ + class TestInstrument : public armnn::Instrument + { + public: + virtual ~TestInstrument() {} + void Start() override {} + void Stop() override {} + + std::vector GetMeasurements() const override + { + std::vector measurements; + measurements.emplace_back(armnn::Measurement("Measurement1", + 1.0, + armnn::Measurement::Unit::TIME_MS)); + measurements.emplace_back(armnn::Measurement("Measurement2", + 2.0, + armnn::Measurement::Unit::TIME_US)); + return measurements; + } + + const char* GetName() const override + { + return "TestInstrument"; + } + }; + + // Get a reference to the profiler manager. + armnn::ProfilerManager& profilerManager = armnn::ProfilerManager::GetInstance(); + + // Create and register a profiler for this thread. + std::unique_ptr profiler = std::make_unique(); + profilerManager.RegisterProfiler(profiler.get()); + + profiler->EnableProfiling(true); + + { + // Test scoped macro. + ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS(armnn::Compute::CpuAcc, "EnqueueWorkload", TestInstrument()) + ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS(armnn::Compute::CpuAcc, "Level 0", TestInstrument()) + { + { + ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS(armnn::Compute::CpuAcc, "Level 1A", TestInstrument()) + } + + { + ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS(armnn::Compute::CpuAcc, "Level 1B", TestInstrument()) + + { + ARMNN_SCOPED_PROFILING_EVENT_WITH_INSTRUMENTS(armnn::Compute::CpuAcc, "Level 2A", TestInstrument()) + } + } + } + } + + std::stringbuf buffer; + std::ostream json(&buffer); + profiler->Print(json); + + std::string output = buffer.str(); + boost::ignore_unused(output); + + // Disable profiling here to not print out anything on stdout. + profiler->EnableProfiling(false); + + // blessed output validated by a human eyeballing the output to make sure it's ok and then copying it here. + // validation also included running the blessed output through an online json validation site + std::string blessedOutput("{\n\t\"ArmNN\": {\n\t\t\"inference_measurements_#1\": {\n\t\t\t\"type\": \"" + "Event\",\n\t\t\t\"Measurement1_#1\": {\n\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\"raw\": [\n\t\t\t\t\t1.000000\n\t\t\t\t],\n\t\t\t\t\"" + "unit\": \"ms\"\n\t\t\t},\n\t\t\t\"Measurement2_#1\": {\n\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\"raw\": [\n\t\t\t\t\t2.000000\n\t\t\t\t],\n\t\t\t\t\"" + "unit\": \"us\"\n\t\t\t},\n\t\t\t\"Level 0_#2\": {\n\t\t\t\t\"type\": \"" + "Event\",\n\t\t\t\t\"Measurement1_#2\": {\n\t\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t1.000000\n\t\t\t\t\t],\n\t\t\t\t\t\"" + "unit\": \"ms\"\n\t\t\t\t},\n\t\t\t\t\"Measurement2_#2\": {\n\t\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t2.000000\n\t\t\t\t\t],\n\t\t\t\t\t\"" + "unit\": \"us\"\n\t\t\t\t},\n\t\t\t\t\"Level 1A_#3\": {\n\t\t\t\t\t\"type\": \"" + "Event\",\n\t\t\t\t\t\"Measurement1_#3\": {\n\t\t\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t\t" + "1.000000\n\t\t\t\t\t\t],\n\t\t\t\t\t\t\"" + "unit\": \"ms\"\n\t\t\t\t\t},\n\t\t\t\t\t\"Measurement2_#3\": {\n\t\t\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t\t" + "2.000000\n\t\t\t\t\t\t],\n\t\t\t\t\t\t\"" + "unit\": \"us\"\n\t\t\t\t\t}\n\t\t\t\t},\n\t\t\t\t\"Level 1B_#4\": {\n\t\t\t\t\t\"" + "type\": \"Event\",\n\t\t\t\t\t\"Measurement1_#4\": {\n\t\t\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t\t" + "1.000000\n\t\t\t\t\t\t],\n\t\t\t\t\t\t\"" + "unit\": \"ms\"\n\t\t\t\t\t},\n\t\t\t\t\t\"Measurement2_#4\": {\n\t\t\t\t\t\t\"" + "type\": \"Measurement\",\n\t\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t\t" + "2.000000\n\t\t\t\t\t\t],\n\t\t\t\t\t\t\"" + "unit\": \"us\"\n\t\t\t\t\t},\n\t\t\t\t\t\"Level 2A_#5\": {\n\t\t\t\t\t\t\"" + "type\": \"Event\",\n\t\t\t\t\t\t\"Measurement1_#5\": {\n\t\t\t\t\t\t\t\"type\": \"" + "Measurement\",\n\t\t\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t\t\t" + "1.000000\n\t\t\t\t\t\t\t],\n\t\t\t\t\t\t\t\"" + "unit\": \"ms\"\n\t\t\t\t\t\t},\n\t\t\t\t\t\t\"Measurement2_#5\": {\n\t\t\t\t\t\t\t\"" + "type\": \"Measurement\",\n\t\t\t\t\t\t\t\"raw\": [\n\t\t\t\t\t\t\t\t" + "2.000000\n\t\t\t\t\t\t\t],\n\t\t\t\t\t\t\t\"" + "unit\": \"us\"\n\t\t\t\t\t\t}\n\t\t\t\t\t}\n\t\t\t\t}\n\t\t\t}\n\t\t}\n\t}\n}\n"); + + BOOST_CHECK(output == blessedOutput); +} + +BOOST_AUTO_TEST_SUITE_END(); diff --git a/src/backends/backendsCommon/test/JsonPrinterTestImpl.cpp b/src/backends/backendsCommon/test/JsonPrinterTestImpl.cpp index c7870d9672..9273a7910f 100644 --- a/src/backends/backendsCommon/test/JsonPrinterTestImpl.cpp +++ b/src/backends/backendsCommon/test/JsonPrinterTestImpl.cpp @@ -199,7 +199,7 @@ std::string GetSoftmaxProfilerJson(const std::vector& backends return ss.str(); } -inline void ValidateProfilerJson(std::string& result, const std::string& testData) +inline void ValidateProfilerJson(std::string& result) { // ensure all measurements are greater than zero std::vector measurementsVector = ExtractMeasurements(result); @@ -237,8 +237,6 @@ inline void ValidateProfilerJson(std::string& result, const std::string& testDat BOOST_CHECK(boost::contains(result, "ArmNN")); BOOST_CHECK(boost::contains(result, "inference_measurements")); - BOOST_CHECK(boost::contains(result, "layer_measurements")); - BOOST_CHECK_EQUAL(result, testData); // ensure no spare parenthesis present in print output BOOST_CHECK(AreParenthesesMatching(result)); @@ -249,118 +247,18 @@ void RunSoftmaxProfilerJsonPrinterTest(const std::vector& back // setup the test fixture and obtain JSON Printer result std::string result = GetSoftmaxProfilerJson(backends); - std::string backend = "Ref"; - std::string testName = "SoftmaxWorkload_Execute"; - std::string changeLine31 = "\n},\n\"CopyMemGeneric_Execute\": {"; - std::string changeLine39 = "us\""; - std::string changeLine40; - std::string changeLine45; + // validate the JSON Printer result + ValidateProfilerJson(result); const armnn::BackendId& firstBackend = backends.at(0); if (firstBackend == armnn::Compute::GpuAcc) { - backend = "Cl"; - testName = "SoftmaxUintWorkload_Execute"; - changeLine31 = ",\n\"OpenClKernelTimer/: softmax_layer_max_shift_exp_sum_quantized_serial GWS[,,]\": {"; - changeLine39 = R"(us" -}, -"OpenClKernelTimer/: softmax_layer_norm_quantized GWS[,,]": { -"raw": [ -, -, - -], -"unit": "us")"; - - changeLine40 = R"( -}, -"CopyMemGeneric_Execute": { -"raw": [ -, -, - -], -"unit": "us")"; - changeLine45 = "}\n"; + BOOST_CHECK(boost::contains(result, + "OpenClKernelTimer/: softmax_layer_max_shift_exp_sum_quantized_serial GWS[,,]")); } else if (firstBackend == armnn::Compute::CpuAcc) { - backend = "Neon"; - testName = "SoftmaxUintWorkload_Execute"; - changeLine31 = ",\n\"NeonKernelTimer/: NEFillBorderKernel\": {"; - changeLine39 = R"(us" -}, -"NeonKernelTimer/: NELogitsDMaxKernel": { -"raw": [ -, -, - -], -"unit": "us" -}, -"NeonKernelTimer/: NELogitsDSoftmaxKernel": { -"raw": [ -, -, - -], -"unit": "us")"; - changeLine40 = R"( -}, -"CopyMemGeneric_Execute": { -"raw": [ -, -, - -], -"unit": "us")"; - changeLine45 = "}\n"; + BOOST_CHECK(boost::contains(result, + "NeonKernelTimer/: NEFillBorderKernel")); } - - std::string testData = R"({ -"ArmNN": { -"inference_measurements": { -"raw": [ -, -, - -], -"unit": "us", -"layer_measurements": { -"raw": [ -, -, - -], -"unit": "us", -"CopyMemGeneric_Execute": { -"raw": [ -, -, - -], -"unit": "us" -}, -")" + backend + testName + R"(": { -"raw": [ -, -, - -], -"unit": "us")" + changeLine31 + R"( -"raw": [ -, -, - -], -"unit": ")" + changeLine39 + R"( -})" + changeLine40 + R"( -} -} -} -} -)" + changeLine45 + R"()"; - - // validate the JSON Printer result - ValidateProfilerJson(result, testData); } -- cgit v1.2.1