add compilation times and execution-time

meetesh06 · meetesh06 · commit fdd8254b4df5 · 2021-06-17T20:12:23.000+05:30
diff --git a/.gitignore b/.gitignore
@@ -36,4 +36,5 @@ benchmarks/
 *.DS_Store
 external/*
 !external/custom-r
-.history
+.history
+profile
diff --git a/.vscode/settings.json b/.vscode/settings.json
@@ -112,6 +112,8 @@
     "cfenv": "cpp",
     "csignal": "cpp",
     "__functional_base_03": "cpp",
-    "__memory": "cpp"
+    "__memory": "cpp",
+    "typeindex": "cpp",
+    "variant": "cpp"
   }
 }
diff --git a/rir/src/api.cpp b/rir/src/api.cpp
@@ -23,6 +23,9 @@
 #include <memory>
 #include <string>
 
+#include <chrono>
+#include <ctime>
+
 using namespace rir;
 
 extern "C" Rboolean R_Visible;
@@ -304,14 +307,22 @@ SEXP pirCompile(SEXP what, const Context& assumptions, const std::string& name,
     logger.title("Compiling " + name);
     pir::Compiler cmp(m, logger);
     pir::Backend backend(logger, name);
+	auto start = std::chrono::system_clock::now();
+	std::chrono::duration<double> duration;
+
     cmp.compileClosure(what, name, assumptions, true,
                        [&](pir::ClosureVersion* c) {
                            logger.flush();
                            cmp.optimizeModule();
 
                            auto fun = backend.getOrCompile(c);
+							// Some computation here
+							auto end = std::chrono::system_clock::now();
+
+							duration = end - start;
 
-                            ContextualProfiling::countSuccessfulCompilation(what,assumptions);
+
+                            ContextualProfiling::countSuccessfulCompilation(what,assumptions,duration);
 
                            // Install
                            if (dryRun)
@@ -321,7 +332,10 @@ SEXP pirCompile(SEXP what, const Context& assumptions, const std::string& name,
                            DispatchTable::unpack(BODY(what))->insert(fun);
                        },
                        [&]() {
-                            ContextualProfiling::countFailedCompilation(what,assumptions);
+							auto end = std::chrono::system_clock::now();
+
+							duration = end - start;
+                            ContextualProfiling::countFailedCompilation(what,assumptions,duration);
                             if (debug.includes(pir::DebugFlag::ShowWarnings))
                                std::cerr << "Compilation failed\n";
                        },
diff --git a/rir/src/interpreter/interp.cpp b/rir/src/interpreter/interp.cpp
@@ -1071,7 +1071,7 @@ RIR_INLINE SEXP rirCall(CallContext& call, InterpreterInstance* ctx) {
     Context lContext = call.givenContext;
     // For Logger -- END
 
-    if (!isDeoptimizing() && RecompileHeuristic(table, fun)) {
+    if (ContextualProfiling::compileFlag(lMethodId, lContext) && !isDeoptimizing() && RecompileHeuristic(table, fun)) {
         Context given = call.givenContext;
         // addDynamicAssumptionForOneTarget compares arguments with the
         // signature of the current dispatch target. There the number of
@@ -1094,6 +1094,8 @@ RIR_INLINE SEXP rirCall(CallContext& call, InterpreterInstance* ctx) {
         *fun
     );
 
+    auto start = std::chrono::system_clock::now(); // runtime start
+
     bool needsEnv = fun->signature().envCreation ==
                     FunctionSignature::Environment::CallerProvided;
 
@@ -1102,12 +1104,16 @@ RIR_INLINE SEXP rirCall(CallContext& call, InterpreterInstance* ctx) {
         call.depromiseArgs();
     }
 
+
     LazyArglistOnStack lazyPromargs(
         call.callId,
         call.caller ? call.caller->arglistOrderContainer() : nullptr,
         call.suppliedArgs, call.stackArgs, call.ast);
 
+
     SEXP result;
+
+	std::chrono::duration<double> duration;
     if (!needsEnv) {
         // Default fast calling convention for pir, environment is created by
         // the callee
@@ -1129,6 +1135,18 @@ RIR_INLINE SEXP rirCall(CallContext& call, InterpreterInstance* ctx) {
     }
     assert(result);
     assert(!fun->flags.contains(Function::Deopt));
+
+
+    auto end = std::chrono::system_clock::now();
+    duration = end - start;
+
+    ContextualProfiling::addFunctionDispatchRuntime(
+        lMethodId,
+        lContext,
+        *fun,
+        duration
+    );
+
     return result;
 }
 
diff --git a/rir/src/utils/ContextualProfiling.cpp b/rir/src/utils/ContextualProfiling.cpp
@@ -60,10 +60,14 @@ namespace rir {
 			int call_count_in_ctxt = 0;
 			int successful_compilation_count = 0;
 			int failed_compilation_count = 0;
+			double time_spent_in_compilation = 0;
+			double time_wasted_in_compilation = 0;
 			// Count the number of time the version for the context C
 			// has been called in this context in
 			//     version_called_count[C]
 			unordered_map<Context, int> version_called_count;
+			unordered_map<Context, int> version_success_run_count;
+			unordered_map<Context, double> version_runtime;
 		};
 
 		class Entry {
@@ -88,7 +92,7 @@ namespace rir {
 				string runId = runId_ss.str();
 
 				myfile.open("profile/" + runId + ".csv");
-				myfile << "ID,NAME,CONTEXT,N_CALL,CMP_SUCCESS,CMP_FAIL,DISPATCHED FUNCTIONS\n";
+				myfile << "ID,NAME,CONTEXT,N_CALL,TOTAL_RUNTIME,CMP_SUCCESS,SUCCESS_TIME,CMP_FAIL,FAIL_TIME,GOODNESS,DISPATCHED FUNCTIONS\n";
 			}
 
 			static size_t getEntryKey(SEXP callee) {
@@ -186,30 +190,71 @@ namespace rir {
 				ctxt_data.version_called_count[version_context]++;
 			}
 
+			void addFunctionDispatchRuntime(
+				size_t id,
+				Context call_context,
+				Function const & f,
+				std::chrono::duration<double> duration
+			) {
+				Context version_context = f.context();
+
+				// find entry for this function
+				// entry must have been previously created by a call to createEntry
+				auto & entry = entries.at(id);
+
+				// create or get call context data
+				auto & ctxt_data = entry.dispatch_data[call_context];
+
+				// count one call in the context callContextId  to version compiled for funContextId
+
+				ctxt_data.version_success_run_count[version_context]++;
+				ctxt_data.version_runtime[version_context] += duration.count();
+			}
+
 			// For the two functions below: function entry must have been previously
 			// created by createEntry, context entry may not exist yet
 			void countSuccessfulCompilation(
 				SEXP callee,
-				Context call_ctxt
+				Context call_ctxt,
+				std::chrono::duration<double> duration
 			) {
 				size_t entry_key = getEntryKey(callee);
 
 				auto & entry = entries.at(entry_key);
 				auto & dispatch_data = entry.dispatch_data[call_ctxt];
 
 				dispatch_data.successful_compilation_count++;
+
+				dispatch_data.time_spent_in_compilation += duration.count();
+
+			}
+
+			bool compileOnlyOnce(
+				size_t entry_key,
+				Context call_context
+			) {
+				auto & entry = entries.at(entry_key);
+				auto & dispatch_data = entry.dispatch_data[call_context];
+
+				if(dispatch_data.successful_compilation_count > 0 || dispatch_data.failed_compilation_count > 0) {
+					return false;
+				} else {
+					return true;
+				}
 			}
 
 			void countFailedCompilation(
 				SEXP callee,
-				Context call_ctxt
+				Context call_ctxt,
+				std::chrono::duration<double> duration
 			) {
 				size_t entry_key = getEntryKey(callee);
 
 				auto & entry = entries.at(entry_key);
 				auto & dispatch_data = entry.dispatch_data[call_ctxt];
 
 				dispatch_data.failed_compilation_count++;
+				dispatch_data.time_wasted_in_compilation += duration.count();
 			}
 
 
@@ -329,6 +374,7 @@ namespace rir {
 			}
 
 			~FileLogger() {
+				double total_time_in_compilation = 0;
 				for (auto const & ir : entries) {
 					auto fun_id = ir.first;
 					auto & entry = ir.second;
@@ -344,6 +390,12 @@ namespace rir {
 
 						stringstream contextsDispatched;
 
+						double totalRuntimeUnderContext = 0;
+
+						double goodness = false;
+						double baselineAvgRuntime = 0;
+						int otherRuntimeCount = 0;
+						double otherAvgRuntime = 0;
 
 						// iterate over dispatched functions under this context
 						for (auto const & itr1 : dispatch_data.version_called_count) {
@@ -352,7 +404,32 @@ namespace rir {
 							int functionContextCallCount = itr1.second; // current function context __call count
 							string currContextString = getContextString(version_context); // current function context __string
 
-							contextsDispatched << "[" << functionContextCallCount << "]" << currContextString << " ";
+							unordered_map<Context, int> version_success_run_count = dispatch_data.version_success_run_count;
+							unordered_map<Context, double> version_runtime = dispatch_data.version_runtime;
+
+							double success_runs = version_success_run_count[version_context];
+							double success_runtime = version_runtime[version_context];
+							double avg_runtime = 0;
+							totalRuntimeUnderContext += success_runtime;
+
+							if(success_runs > 0) {
+								avg_runtime = success_runtime / success_runs;
+							}
+							bool baseline = version_context.toI() == 0 ? true : false;
+
+							if(baseline) {
+								baselineAvgRuntime = avg_runtime;
+							} else {
+								otherRuntimeCount++;
+								otherAvgRuntime += avg_runtime;
+							}
+
+							contextsDispatched << "[" << functionContextCallCount << "]{" << avg_runtime << "}" << currContextString << " ";
+						}
+						otherAvgRuntime = otherAvgRuntime / otherRuntimeCount;
+						total_time_in_compilation += dispatch_data.time_spent_in_compilation;
+						if(otherAvgRuntime < baselineAvgRuntime) {
+							goodness = true;
 						}
 						// print row
 						myfile
@@ -364,14 +441,33 @@ namespace rir {
 							<< del
 							<< dispatch_data.call_count_in_ctxt // call context count
 							<< del
+							<< totalRuntimeUnderContext // total runtime under context
+							<< del
 							<< dispatch_data.successful_compilation_count // number of successful compilations in this context
 							<< del
+							<< dispatch_data.time_spent_in_compilation // time spent for successful compilation
+							<< del
 							<< dispatch_data.failed_compilation_count // number of failed compilations in this context
 							<< del
+							<< dispatch_data.time_wasted_in_compilation // time wasted trying to compile
+							<< del
+							<< goodness
+							<< del
 							<< contextsDispatched.str() // functions dispatched under this context
 							<< "\n";
 					}
 				}
+				myfile
+					<< del
+					<< del
+					<< del
+					<< del
+					<< del
+					<< total_time_in_compilation // Total time in compilation
+					<< del
+					<< del
+					<< del
+					<< "\n";
 				myfile.close();
 			}
 
@@ -420,21 +516,51 @@ void ContextualProfiling::addFunctionDispatchInfo(
 
 void ContextualProfiling::countSuccessfulCompilation(
 	SEXP callee,
-	Context assumptions
+	Context assumptions,
+	std::chrono::duration<double> duration
 ) {
 	if (fileLogger) {
-		fileLogger->countSuccessfulCompilation(callee, assumptions);
+		fileLogger->countSuccessfulCompilation(callee, assumptions, duration);
 	}
 }
 
 void ContextualProfiling::countFailedCompilation(
 	SEXP callee,
-	Context assumptions
+	Context assumptions,
+	std::chrono::duration<double> duration
 ) {
 	if (fileLogger) {
-		fileLogger->countFailedCompilation(callee, assumptions);
+		fileLogger->countFailedCompilation(callee, assumptions, duration);
 	}
 }
 
+bool ContextualProfiling::compileFlag(
+	size_t id,
+	Context contextCaller
+) {
+	if (getenv("SKIP_ALL_COMPILATION")) {
+		return false;
+	}
+	if (!getenv("COMPILE_ONLY_ONCE")) {
+		return true;
+	}
+	if (fileLogger) {
+		return fileLogger->compileOnlyOnce(id, contextCaller);
+	} else {
+		return true;
+	}
+}
+
+void ContextualProfiling::addFunctionDispatchRuntime(
+	size_t id,
+	Context contextCaller,
+	Function const &f,
+	std::chrono::duration<double> duration
+
+) {
+	if(fileLogger) {
+		return fileLogger->addFunctionDispatchRuntime(id, contextCaller, f, duration);
+	}
+}
 
 } // namespace rir
diff --git a/rir/src/utils/ContextualProfiling.h b/rir/src/utils/ContextualProfiling.h

Original file line number	Diff line number	Diff line change
`@@ -112,6 +112,8 @@`
`112`	`112`	`"cfenv": "cpp",`
`113`	`113`	`"csignal": "cpp",`
`114`	`114`	`"__functional_base_03": "cpp",`
`115`		`- "__memory": "cpp"`
	`115`	`+ "__memory": "cpp",`
	`116`	`+ "typeindex": "cpp",`
	`117`	`+ "variant": "cpp"`
`116`	`118`	`}`
`117`	`119`	`}`