17595: Enables profiling from the command line without preprocessor m…

…acros (#15)

src/Amalgam/AmalgamMain.cpp

@@ -32,28 +32,34 @@ PLATFORM_MAIN_CONSOLE
 			<< "Concurrency type: " << GetConcurrencyTypeString() << std::endl
 			<< "Must specify an input file.  Flags:" << std::endl
 			<< "-l [filename]: specify a debug log file." << std::endl
-		#if defined(INTERPRETER_PROFILE_OPCODES) || defined(INTERPRETER_PROFILE_LABELS_CALLED)
-			<< "-p: display engine performance counters upon completion" << std::endl
-		#endif
 			<< "-s [random number seed]: specify a particular random number seed -- can be any alphanumeric string." << std::endl
 			<< "-t [filename]: specify a code-based transaction log file." << std::endl
 		#if defined(MULTITHREAD_SUPPORT) || defined(_OPENMP)
 			<< "--numthreads [number]: maximum number of threads to use (if unspecified or set to zero, may use unlimited)." << std::endl
 		#endif
+			<< "--p-opcodes: display engine profiling information for opcodes upon completion (one profiling type allowed at a time); when used with --debug-sources, reports line numbers" << std::endl
+			<< "--p-labels: display engine profiling information for labels upon completion (one profiling type allowed at a time)" << std::endl
+			<< "--p-count [number]: when used with --p-opcodes or --p-labels, specifies the count of the top profile information elements to display; "
+				<< "the default is 20 for command line, all when --p - file is specified" << std::endl
+			<< "--p-file [filename]: when used with --p-opcodes or --p-labels, writes the profile information to a file" << std::endl
 			<< "--debug: when specified, begins in debugging mode." << std::endl
 			<< "--debug-minimal: when specified, begins in debugging mode with minimal output while stepping." << std::endl
 			<< "--debug-sources: when specified, prepends all node comments with the source of the node when applicable." << std::endl
 			<< "--nosbfds: disables the sbfds acceleration, which is generally preferred in the heuristics." << std::endl
 			<< "--trace: uses commands via stdio to act as if it were being called as a library." << std::endl
-			<< "--tracefile [file]: like trace, but pulls the data from the file specified." << std::endl
+			<< "--tracefile [filename]: like trace, but pulls the data from the file specified." << std::endl
 			<< "--version: prints the current version." << std::endl;
 		return 0;
 	}
-
+	
 	//run options
 	bool debug_state = false;
 	bool debug_minimal = false;
 	bool debug_sources = false;
+	bool profile_opcodes = false;
+	bool profile_labels = false;
+	size_t profile_count = 0;
+	std::string profile_out_file;
 	bool run_trace = false;
 	bool run_tracefile = false;
 	std::string tracefile;
@@ -82,10 +88,14 @@ PLATFORM_MAIN_CONSOLE
 		{
 			print_log_filename = args[++i];
 		}
-	#if defined(INTERPRETER_PROFILE_OPCODES) || defined(INTERPRETER_PROFILE_LABELS_CALLED)
-		else if(args[i] == "-p")
-			PerformanceProfiler::EnableProfiling();
-	#endif
+		else if(args[i] == "--p-opcodes")
+			profile_opcodes = true;
+		else if(args[i] == "--p-labels")
+			profile_labels = true;
+		else if(args[i] == "--p-count" && i + 1 < args.size())
+			profile_count = static_cast<size_t>(std::max(std::atoi(args[++i].data()), 0));
+		else if(args[i] == "--p-file" && i + 1 < args.size())
+			profile_out_file = args[++i];
 		else if(args[i] == "-q")
 			print_to_stdio = false;
 		else if(args[i] == "-s" && i + 1 < args.size())
@@ -144,6 +154,12 @@ PLATFORM_MAIN_CONSOLE
 	if(debug_minimal)
 		asset_manager.debugMinimal = true;
 
+	if(profile_opcodes)
+		Interpreter::SetOpcodeProfilingState(true);
+
+	if(profile_labels)
+		Interpreter::SetLabelProfilingState(true);
+
 	if(run_trace)
 	{
 		return RunAmalgamTrace(&std::cin, &std::cout, random_seed);
@@ -154,8 +170,8 @@ PLATFORM_MAIN_CONSOLE
 		int ret = RunAmalgamTrace(trace_stream, &std::cout, random_seed);
 		delete trace_stream;
 
-		if(PerformanceProfiler::IsProfilingEnabled())
-			PerformanceProfiler::PrintProfilingInformation();
+		if(profile_opcodes || profile_labels)
+			PerformanceProfiler::PrintProfilingInformation(profile_out_file, profile_count);
 
 		return ret;
 	}
@@ -227,8 +243,8 @@ PLATFORM_MAIN_CONSOLE
 			}
 		}
 
-		if(PerformanceProfiler::IsProfilingEnabled())
-			PerformanceProfiler::PrintProfilingInformation();
+		if(profile_opcodes || profile_labels)
+			PerformanceProfiler::PrintProfilingInformation(profile_out_file, profile_count);
 
 		if(Platform_IsDebuggerPresent())
 		{

src/Amalgam/PerformanceProfiler.cpp

@@ -3,7 +3,7 @@
 #include "Concurrency.h"
 
 //if true, then will record profiling data
-bool _profiler_enabled;
+bool PerformanceProfiler::_profiler_enabled;
 
 #if defined(MULTITHREAD_SUPPORT) || defined(MULTITHREAD_INTERFACE)
 Concurrency::SingleMutex performance_profiler_mutex;
@@ -28,29 +28,13 @@ inline double GetCurTime()
 	return cur_time / 1000.0 / 1000.0 / 1000.0;
 }
 
-void PerformanceProfiler::EnableProfiling(bool enable)
-{
-	_profiler_enabled = enable;
-}
-
-bool PerformanceProfiler::IsProfilingEnabled()
-{
-	return _profiler_enabled;
-}
-
 void PerformanceProfiler::StartOperation(const std::string &t, int64_t memory_use)
-{
-	if(!_profiler_enabled)
-		return;
-
+{	
 	instructionStackTypeAndStartTimeAndMemUse.push_back(std::make_pair(t, std::make_pair(GetCurTime(), memory_use)));
 }
 
 void PerformanceProfiler::EndOperation(int64_t memory_use = 0)
 {
-	if(!_profiler_enabled)
-		return;
-
 	//get and remove data from call stack
 	auto type_and_time_and_mem = instructionStackTypeAndStartTimeAndMemUse.back();
 	auto inst_type = type_and_time_and_mem.first;
@@ -88,67 +72,88 @@ void PerformanceProfiler::EndOperation(int64_t memory_use = 0)
 	}
 }
 
-void PerformanceProfiler::PrintProfilingInformation()
+void PerformanceProfiler::PrintProfilingInformation(std::string outfile_name, size_t max_print_count)
 {
-	size_t max_num_perf_counters_to_display = 20;
-	std::cout << "Operations that took the longest total time (s): " << std::endl;
+	std::ofstream outfile;
+	if(outfile_name != "")
+		outfile.open(outfile_name);
+
+	std::ostream &out_dest = (outfile.is_open() ? outfile : std::cout);
+
+	if(max_print_count == 0)
+	{
+		if(outfile.is_open())
+			max_print_count = std::numeric_limits<size_t>::max();
+		else
+			max_print_count = 20;
+	}
+
+	out_dest << "------------------------------------------------------" << std::endl;
+	out_dest << "Operations that took the longest total time (s): " << std::endl;
 	auto longest_total_time = PerformanceProfiler::GetNumCallsByTotalTime();
-	for(size_t i = 0; i < max_num_perf_counters_to_display && i < longest_total_time.size(); i++)
-		std::cout << longest_total_time[i].first << ": " << longest_total_time[i].second << std::endl;
-	std::cout << std::endl;
+	for(size_t i = 0; i < max_print_count && i < longest_total_time.size(); i++)
+		out_dest << longest_total_time[i].first << ": " << longest_total_time[i].second << std::endl;
+	out_dest << std::endl;
 
-	std::cout << "Operations called the most number of times: " << std::endl;
+	out_dest << "------------------------------------------------------" << std::endl;
+	out_dest << "Operations called the most number of times: " << std::endl;
 	auto most_calls = PerformanceProfiler::GetNumCallsByType();
-	for(size_t i = 0; i < max_num_perf_counters_to_display && i < most_calls.size(); i++)
-		std::cout << most_calls[i].first << ": " << most_calls[i].second << std::endl;
-	std::cout << std::endl;
+	for(size_t i = 0; i < max_print_count && i < most_calls.size(); i++)
+		out_dest << most_calls[i].first << ": " << most_calls[i].second << std::endl;
+	out_dest << std::endl;
 
-	std::cout << "Operations that took the longest average time (s): " << std::endl;
+	out_dest << "------------------------------------------------------" << std::endl;
+	out_dest << "Operations that took the longest average time (s): " << std::endl;
 	auto longest_ave_time = PerformanceProfiler::GetNumCallsByAveTime();
-	for(size_t i = 0; i < max_num_perf_counters_to_display && i < longest_ave_time.size(); i++)
-		std::cout << longest_ave_time[i].first << ": " << longest_ave_time[i].second << std::endl;
-	std::cout << std::endl;
+	for(size_t i = 0; i < max_print_count && i < longest_ave_time.size(); i++)
+		out_dest << longest_ave_time[i].first << ": " << longest_ave_time[i].second << std::endl;
+	out_dest << std::endl;
 
-	std::cout << "Operations that increased the memory usage the most in total (nodes): " << std::endl;
+	out_dest << "------------------------------------------------------" << std::endl;
+	out_dest << "Operations that increased the memory usage the most in total (nodes): " << std::endl;
 	auto most_total_memory = PerformanceProfiler::GetNumCallsByTotalMemoryIncrease();
-	for(size_t i = 0; i < max_num_perf_counters_to_display && i < most_total_memory.size(); i++)
-		std::cout << most_total_memory[i].first << ": " << most_total_memory[i].second << std::endl;
-	std::cout << std::endl;
+	for(size_t i = 0; i < max_print_count && i < most_total_memory.size(); i++)
+		out_dest << most_total_memory[i].first << ": " << most_total_memory[i].second << std::endl;
+	out_dest << std::endl;
 
-	std::cout << "Operations that increased the memory usage the most on average (nodes): " << std::endl;
+	out_dest << "------------------------------------------------------" << std::endl;
+	out_dest << "Operations that increased the memory usage the most on average (nodes): " << std::endl;
 	auto most_ave_memory = PerformanceProfiler::GetNumCallsByAveMemoryIncrease();
-	for(size_t i = 0; i < max_num_perf_counters_to_display && i < most_ave_memory.size(); i++)
-		std::cout << most_ave_memory[i].first << ": " << most_ave_memory[i].second << std::endl;
-	std::cout << std::endl;
+	for(size_t i = 0; i < max_print_count && i < most_ave_memory.size(); i++)
+		out_dest << most_ave_memory[i].first << ": " << most_ave_memory[i].second << std::endl;
+	out_dest << std::endl;
 
-	std::cout << "Operations that decreased the memory usage the most in total (nodes): " << std::endl;
-	for(size_t i = 0; i < max_num_perf_counters_to_display && i < most_total_memory.size(); i++)
+	out_dest << "------------------------------------------------------" << std::endl;
+	out_dest << "Operations that decreased the memory usage the most in total (nodes): " << std::endl;
+	for(size_t i = 0; i < max_print_count && i < most_total_memory.size(); i++)
 	{
 		//only write out those that had a net decrease
 		double mem_delta = most_total_memory[most_total_memory.size() - 1 - i].second;
 		if(mem_delta >= 0)
 			break;
-		std::cout << most_total_memory[i].first << ": " << mem_delta << std::endl;
+		out_dest << most_total_memory[i].first << ": " << mem_delta << std::endl;
 	}
-	std::cout << std::endl;
+	out_dest << std::endl;
 
-	std::cout << "Operations that decreased the memory usage the most on average (nodes): " << std::endl;
-	for(size_t i = 0; i < max_num_perf_counters_to_display && i < most_ave_memory.size(); i++)
+	out_dest << "------------------------------------------------------" << std::endl;
+	out_dest << "Operations that decreased the memory usage the most on average (nodes): " << std::endl;
+	for(size_t i = 0; i < max_print_count && i < most_ave_memory.size(); i++)
 	{
 		//only write out those that had a net decrease
 		double mem_delta = most_ave_memory[most_total_memory.size() - 1 - i].second;
 		if(mem_delta >= 0)
 			break;
-		std::cout << most_total_memory[i].first << ": " << mem_delta << std::endl;
+		out_dest << most_total_memory[i].first << ": " << mem_delta << std::endl;
 	}
-	std::cout << std::endl;
+	out_dest << std::endl;
 
+	out_dest << "------------------------------------------------------" << std::endl;
 	size_t total_call_count = GetTotalNumCalls();
-	std::cout << "Total number of operations: " << total_call_count << std::endl;
+	out_dest << "Total number of operations: " << total_call_count << std::endl;
 
 	auto [total_mem_increase, positive_mem_increase] = PerformanceProfiler::GetTotalAndPositiveMemoryIncreases();
-	std::cout << "Net number of nodes allocated: " << total_mem_increase << std::endl;
-	std::cout << "Total node increases: " << positive_mem_increase << std::endl;
+	out_dest << "Net number of nodes allocated: " << total_mem_increase << std::endl;
+	out_dest << "Total node increases: " << positive_mem_increase << std::endl;
 }
 
 size_t PerformanceProfiler::GetTotalNumCalls()

src/Amalgam/PerformanceProfiler.h

@@ -10,9 +10,17 @@
 
 namespace PerformanceProfiler
 {
-	void EnableProfiling(bool enable = true);
+	extern bool _profiler_enabled;
 
-	bool IsProfilingEnabled();
+	inline void SetProfilingState(bool enabled)
+	{
+		_profiler_enabled = enabled;
+	}
+
+	inline bool IsProfilingEnabled()
+	{
+		return _profiler_enabled;
+	}
 
 	//begins performance timers for the specified operation type, specified by the string t
 	// pushes current instruction on the stack, such that it will be cleared when the
@@ -21,7 +29,10 @@ namespace PerformanceProfiler
 
 	void EndOperation(int64_t memory_use);
 
-	void PrintProfilingInformation();
+	//prints profiling information
+	//if outfile_name is empty string, will print to stdout
+	//if max_print_count is 0, will print a default of 20 for stdout, will print all for a file
+	void PrintProfilingInformation(std::string outfile_name = "", size_t max_print_count = 0);
 
 	size_t GetTotalNumCalls();
 

src/Amalgam/evaluablenode/EvaluableNodeManagement.cpp

@@ -1,5 +1,6 @@
 //project headers:
 #include "EvaluableNodeManagement.h"
+#include "PerformanceProfiler.h"
 
 //system headers:
 #include <limits>
@@ -195,6 +196,12 @@ void EvaluableNodeManager::CollectGarbage()
 	if(!RecommendGarbageCollection())
 		return;
 
+	if(PerformanceProfiler::IsProfilingEnabled())
+	{
+		static const std::string collect_garbage_string = ".collect_garbage";
+		PerformanceProfiler::StartOperation(collect_garbage_string, GetNumberOfUsedNodes());
+	}
+
 #ifdef MULTITHREAD_SUPPORT
 
 	//free lock so can attempt to enter write lock to collect garbage
@@ -209,6 +216,10 @@ void EvaluableNodeManager::CollectGarbage()
 		{
 			if(memory_modification_lock != nullptr)
 				memory_modification_lock->lock();
+
+			if(PerformanceProfiler::IsProfilingEnabled())
+				PerformanceProfiler::EndOperation(GetNumberOfUsedNodes());
+
 			return;
 		}
 
@@ -220,6 +231,10 @@ void EvaluableNodeManager::CollectGarbage()
 		write_lock.unlock();
 		if(memory_modification_lock != nullptr)
 			memory_modification_lock->lock();
+
+		if(PerformanceProfiler::IsProfilingEnabled())
+			PerformanceProfiler::EndOperation(GetNumberOfUsedNodes());
+
 		return;
 	}
 #endif
@@ -233,6 +248,9 @@ void EvaluableNodeManager::CollectGarbage()
 	if(memory_modification_lock != nullptr)
 		memory_modification_lock->lock();
 #endif
+
+	if(PerformanceProfiler::IsProfilingEnabled())
+		PerformanceProfiler::EndOperation(GetNumberOfUsedNodes());
 }
 
 void EvaluableNodeManager::FreeAllNodes()