Merge pull request #15506 from ethereum/profiler-probe

Generalize optimizer step profiler

libsolutil/CMakeLists.txt

@@ -27,6 +27,8 @@ set(sources
 	Numeric.cpp
 	Numeric.h
 	picosha2.h
+	Profiler.cpp
+	Profiler.h
 	Result.h
 	SetOnce.h
 	StackTooDeepString.h

libsolutil/Profiler.cpp

@@ -0,0 +1,98 @@
+/*
+	This file is part of solidity.
+
+	solidity is free software: you can redistribute it and/or modify
+	it under the terms of the GNU General Public License as published by
+	the Free Software Foundation, either version 3 of the License, or
+	(at your option) any later version.
+
+	solidity is distributed in the hope that it will be useful,
+	but WITHOUT ANY WARRANTY; without even the implied warranty of
+	MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+	GNU General Public License for more details.
+
+	You should have received a copy of the GNU General Public License
+	along with solidity.  If not, see <http://www.gnu.org/licenses/>.
+*/
+// SPDX-License-Identifier: GPL-3.0
+
+#include <libsolutil/Profiler.h>
+
+#include <fmt/format.h>
+
+#include <algorithm>
+#include <iostream>
+#include <vector>
+
+using namespace std::chrono;
+using namespace solidity;
+
+#ifdef PROFILE_OPTIMIZER_STEPS
+
+util::Profiler::Probe::Probe(std::string _scopeName):
+	m_scopeName(std::move(_scopeName)),
+	m_startTime(steady_clock::now())
+{
+}
+
+util::Profiler::Probe::~Probe()
+{
+	steady_clock::time_point endTime = steady_clock::now();
+
+	auto [metricsIt, inserted] = Profiler::singleton().m_metrics.try_emplace(m_scopeName, Metrics{0us, 0});
+	metricsIt->second.durationInMicroseconds += duration_cast<microseconds>(endTime - m_startTime);
+	++metricsIt->second.callCount;
+}
+
+util::Profiler::~Profiler()
+{
+	outputPerformanceMetrics();
+}
+
+util::Profiler& util::Profiler::singleton()
+{
+	static Profiler profiler;
+	return profiler;
+}
+
+void util::Profiler::outputPerformanceMetrics()
+{
+	std::vector<std::pair<std::string, Metrics>> sortedMetrics(m_metrics.begin(), m_metrics.end());
+	std::sort(
+		sortedMetrics.begin(),
+		sortedMetrics.end(),
+		[](std::pair<std::string, Metrics> const& _lhs, std::pair<std::string, Metrics> const& _rhs) -> bool
+		{
+			return _lhs.second.durationInMicroseconds < _rhs.second.durationInMicroseconds;
+		}
+	);
+
+	std::chrono::microseconds totalDurationInMicroseconds = 0us;
+	size_t totalCallCount = 0;
+	for (auto&& [scopeName, scopeMetrics]: sortedMetrics)
+	{
+		totalDurationInMicroseconds += scopeMetrics.durationInMicroseconds;
+		totalCallCount += scopeMetrics.callCount;
+	}
+
+	std::cerr << "PERFORMANCE METRICS FOR PROFILED SCOPES\n\n";
+	std::cerr << "| Time % | Time       | Calls   | Scope                          |\n";
+	std::cerr << "|-------:|-----------:|--------:|--------------------------------|\n";
+
+	double totalDurationInSeconds = duration_cast<duration<double>>(totalDurationInMicroseconds).count();
+	for (auto&& [scopeName, scopeMetrics]: sortedMetrics)
+	{
+		double durationInSeconds = duration_cast<duration<double>>(scopeMetrics.durationInMicroseconds).count();
+		double percentage = 100.0 * durationInSeconds / totalDurationInSeconds;
+		std::cerr << fmt::format(
+			"| {:5.1f}% | {:8.3f} s | {:7} | {:30} |\n",
+			percentage,
+			durationInSeconds,
+			scopeMetrics.callCount,
+			scopeName
+		);
+	}
+	std::cerr << fmt::format("| {:5.1f}% | {:8.3f} s | {:7} | {:30} |\n", 100.0, totalDurationInSeconds, totalCallCount, "**TOTAL**");
+}
+
+#endif

libsolutil/Profiler.h

@@ -0,0 +1,81 @@
+/*
+	This file is part of solidity.
+
+	solidity is free software: you can redistribute it and/or modify
+	it under the terms of the GNU General Public License as published by
+	the Free Software Foundation, either version 3 of the License, or
+	(at your option) any later version.
+
+	solidity is distributed in the hope that it will be useful,
+	but WITHOUT ANY WARRANTY; without even the implied warranty of
+	MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+	GNU General Public License for more details.
+
+	You should have received a copy of the GNU General Public License
+	along with solidity.  If not, see <http://www.gnu.org/licenses/>.
+*/
+// SPDX-License-Identifier: GPL-3.0
+
+#pragma once
+
+#include <chrono>
+#include <map>
+#include <optional>
+#include <string>
+
+#ifdef PROFILE_OPTIMIZER_STEPS
+#define PROFILER_PROBE(_scopeName, _variable) solidity::util::Profiler::Probe _variable(_scopeName);
+#else
+#define PROFILER_PROBE(_scopeName, _variable) void(0);
+#endif
+
+namespace solidity::util
+{
+
+#ifdef PROFILE_OPTIMIZER_STEPS
+
+/// Simpler profiler class that gathers metrics during program execution and prints them out on exit.
+///
+/// To gather metrics, create a Probe instance and let it live until the end of the scope.
+/// The probe will register its creation and destruction time and store the results in the profiler
+/// singleton.
+///
+/// Use the PROFILER_PROBE macro to create probes conditionally, in a way that will not affect performance
+/// unless profiling is enabled at compilation time via PROFILE_OPTIMIZER_STEPS CMake option.
+///
+/// Scopes are identified by the name supplied to the probe. Using the same name multiple times
+/// will result in metrics for those scopes being aggregated together as if they were the same scope.
+class Profiler
+{
+public:
+	class Probe
+	{
+	public:
+		Probe(std::string _scopeName);
+		~Probe();
+
+	private:
+		std::string m_scopeName;
+		std::chrono::steady_clock::time_point m_startTime;
+	};
+
+	static Profiler& singleton();
+
+private:
+	~Profiler();
+
+	struct Metrics
+	{
+		std::chrono::microseconds durationInMicroseconds;
+		size_t callCount;
+	};
+
+	/// Summarizes gathered metric and prints a report to standard error output.
+	void outputPerformanceMetrics();
+
+	std::map<std::string, Metrics> m_metrics;
+};
+
+#endif
+
+}

libyul/optimiser/Suite.cpp

@@ -72,6 +72,7 @@
 #include <libyul/backends/evm/NoOutputAssembly.h>
 
 #include <libsolutil/CommonData.h>
+#include <libsolutil/Profiler.h>
 
 #include <libyul/CompilabilityChecker.h>
 
@@ -83,56 +84,10 @@
 #include <limits>
 #include <tuple>
 
-#ifdef PROFILE_OPTIMIZER_STEPS
-#include <chrono>
-#include <fmt/format.h>
-#endif
-
 using namespace solidity;
 using namespace solidity::yul;
-#ifdef PROFILE_OPTIMIZER_STEPS
-using namespace std::chrono;
-#endif
 using namespace std::string_literals;
 
-namespace
-{
-
-#ifdef PROFILE_OPTIMIZER_STEPS
-void outputPerformanceMetrics(std::map<std::string, int64_t> const& _metrics)
-{
-	std::vector<std::pair<std::string, int64_t>> durations(_metrics.begin(), _metrics.end());
-	sort(
-		durations.begin(),
-		durations.end(),
-		[](std::pair<std::string, int64_t> const& _lhs, std::pair<std::string, int64_t> const& _rhs) -> bool
-		{
-			return _lhs.second < _rhs.second;
-		}
-	);
-
-	int64_t totalDurationInMicroseconds = 0;
-	for (auto&& [step, durationInMicroseconds]: durations)
-		totalDurationInMicroseconds += durationInMicroseconds;
-
-	std::cerr << "Performance metrics of optimizer steps" << std::endl;
-	std::cerr << "======================================" << std::endl;
-	constexpr double microsecondsInSecond = 1000000;
-	for (auto&& [step, durationInMicroseconds]: durations)
-	{
-		double percentage = 100.0 * static_cast<double>(durationInMicroseconds) / static_cast<double>(totalDurationInMicroseconds);
-		double sec = static_cast<double>(durationInMicroseconds) / microsecondsInSecond;
-		std::cerr << fmt::format("{:>7.3f}% ({} s): {}", percentage, sec, step) << std::endl;
-	}
-	double totalDurationInSeconds = static_cast<double>(totalDurationInMicroseconds) / microsecondsInSecond;
-	std::cerr << "--------------------------------------" << std::endl;
-	std::cerr << fmt::format("{:>7}% ({:.3f} s)", 100, totalDurationInSeconds) << std::endl;
-}
-#endif
-
-}
-
-
 void OptimiserSuite::run(
 	Dialect const& _dialect,
 	GasMeter const* _meter,
@@ -226,10 +181,6 @@ void OptimiserSuite::run(
 	NameSimplifier::run(suite.m_context, astRoot);
 	VarNameCleaner::run(suite.m_context, astRoot);
 
-#ifdef PROFILE_OPTIMIZER_STEPS
-	outputPerformanceMetrics(suite.m_durationPerStepInMicroseconds);
-#endif
-
 	_object.setCode(std::make_shared<AST>(std::move(astRoot)));
 	_object.analysisInfo = std::make_shared<AsmAnalysisInfo>(AsmAnalyzer::analyzeStrictAssertCorrect(_dialect, _object));
 }
@@ -504,14 +455,12 @@ void OptimiserSuite::runSequence(std::vector<std::string> const& _steps, Block&
 	{
 		if (m_debug == Debug::PrintStep)
 			std::cout << "Running " << step << std::endl;
-#ifdef PROFILE_OPTIMIZER_STEPS
-		steady_clock::time_point startTime = steady_clock::now();
-#endif
-		allSteps().at(step)->run(m_context, _ast);
-#ifdef PROFILE_OPTIMIZER_STEPS
-		steady_clock::time_point endTime = steady_clock::now();
-		m_durationPerStepInMicroseconds[step] += duration_cast<microseconds>(endTime - startTime).count();
-#endif
+
+		{
+			PROFILER_PROBE(step, probe);
+			allSteps().at(step)->run(m_context, _ast);
+		}
+
 		if (m_debug == Debug::PrintChanges)
 		{
 			// TODO should add switch to also compare variable names!

libyul/optimiser/Suite.h

@@ -91,9 +91,6 @@ class OptimiserSuite
 private:
 	OptimiserStepContext& m_context;
 	Debug m_debug;
-#ifdef PROFILE_OPTIMIZER_STEPS
-	std::map<std::string, int64_t> m_durationPerStepInMicroseconds;
-#endif
 };
 
 }