fix #478, record resource usage info in provenance

Author: bhaller

VERSIONS

@@ -147,6 +147,7 @@ development head (in the master branch):
 		fix #488, non-UTF-8 encoding causes poor error
 		fix #476, external editing causes SLiMgui to get confused
 		fix #479, CLI progress bar would be a nice option; this is now -p[rogress]
+		fix #478, record resource usage information in the tree sequence provenance; now we also print user/sys CPU usage for -t[ime], since we now have the information
 
 
 version 4.3 (Eidos version 3.3):

core/main.cpp

@@ -554,7 +554,6 @@ int main(int argc, char *argv[])	// FIXME: clang-tidy flags this with bugprone-e
 
 	// keep time (we do this whether or not the -time flag was passed)
 	std::clock_t begin_cpu = std::clock();
-	std::chrono::steady_clock::time_point begin_wall = std::chrono::steady_clock::now();
 
 	// keep memory usage information, if asked to
 	size_t *mem_record = nullptr;
@@ -826,15 +825,20 @@ int main(int argc, char *argv[])	// FIXME: clang-tidy flags this with bugprone-e
 	}
 
 	// end timing and print elapsed time
-	std::clock_t end_cpu = std::clock();
-	std::chrono::steady_clock::time_point end_wall = std::chrono::steady_clock::now();
-	double cpu_time_secs = static_cast<double>(end_cpu - begin_cpu) / CLOCKS_PER_SEC;
-	double wall_time_secs = std::chrono::duration<double>(end_wall - begin_wall).count();
-	
 	if (keep_time)
 	{
+		std::clock_t end_cpu = std::clock();
+		double cpu_time_secs = static_cast<double>(end_cpu - begin_cpu) / CLOCKS_PER_SEC;
+		double user_time, sys_time;
+		
+		Eidos_GetUserSysTime(&user_time, &sys_time);
+		
 		SLIM_ERRSTREAM << "// ********** CPU time used: " << cpu_time_secs << std::endl;
-		SLIM_ERRSTREAM << "// ********** Wall time used: " << wall_time_secs << std::endl;
+		if (user_time > 0.0)
+			SLIM_ERRSTREAM << "// ********** User CPU time: " << user_time << std::endl;
+		if (sys_time > 0.0)
+			SLIM_ERRSTREAM << "// ********** System CPU time: " << sys_time << std::endl;
+		SLIM_ERRSTREAM << "// ********** Wall time used: " << Eidos_WallTimeSeconds() << std::endl;
 	}
 
 	if (gEidosBenchmarkType != EidosBenchmarkType::kNone)

core/species.cpp

@@ -6636,7 +6636,9 @@ void Species::WriteProvenanceTable(tsk_table_collection_t *p_tables, bool p_use_
 	try {
 		nlohmann::json j;
 
-		j["schema_version"] = "1.0.0";
+		// BCH 3/10/2024: Moving from schema version 1.0.0 to 1.1.0, which I believe shipped in tskit 0.5.9.
+		// This adds the optional `resources` key.  See https://github.com/MesserLab/SLiM/issues/478.
+		j["schema_version"] = "1.1.0";
 
 		struct utsname name;
 		ret = uname(&name);
@@ -6740,6 +6742,23 @@ void Species::WriteProvenanceTable(tsk_table_collection_t *p_tables, bool p_use_
 		j["metadata"]["individuals"]["flags"]["18"]["name"] = "SLIM_TSK_INDIVIDUAL_RETAINED";
 		j["metadata"]["individuals"]["flags"]["18"]["description"] = "the individual was requested by the user to be retained only if its nodes continue to exist in the tree sequence";
 
+		// We save this information out only for runs at the command line.  This data might not be available on
+		// all platforms; when it is unavailable, the key will be omitted.  We always have elapsed wall time.
+#ifndef SLIMGUI
+		double user_time, sys_time;
+		size_t peak_RSS = Eidos_GetPeakRSS();
+		
+		Eidos_GetUserSysTime(&user_time, &sys_time);
+		
+		j["resources"]["elapsed_time"] = Eidos_WallTimeSeconds();
+		if (user_time > 0.0)
+			j["resources"]["user_time"] = user_time;
+		if (sys_time > 0.0)
+			j["resources"]["sys_time"] = sys_time;
+		if (peak_RSS > 0)
+			j["resources"]["max_memory"] = peak_RSS;
+#endif
+		
 		if (p_use_newlines)
 			provenance_str = j.dump(4);
 		else

eidos/eidos_functions_other.cpp

@@ -143,8 +143,6 @@ EidosValue_SP Eidos_ExecuteFunction_citation(__attribute__((unused)) const std::
 }
 
 //	(float$)clock([string$ type = "cpu"])
-static std::chrono::steady_clock::time_point timebase = std::chrono::steady_clock::now();	// start at launch
-
 EidosValue_SP Eidos_ExecuteFunction_clock(__attribute__((unused)) const std::vector<EidosValue_SP> &p_arguments, __attribute__((unused)) EidosInterpreter &p_interpreter)
 {
 	// Note that this function ignores matrix/array attributes, and always returns a vector, by design
@@ -163,9 +161,7 @@ EidosValue_SP Eidos_ExecuteFunction_clock(__attribute__((unused)) const std::vec
 	else if (type_name == "mono")
 	{
 		// monotonic clock time; this is best for measured user-perceived elapsed times
-		std::chrono::steady_clock::time_point ts = std::chrono::steady_clock::now();
-		std::chrono::steady_clock::duration clock_duration = ts - timebase;
-		double seconds = std::chrono::duration<double>(clock_duration).count();
+		double seconds = Eidos_WallTimeSeconds();
 
 		return EidosValue_SP(new (gEidosValuePool->AllocateChunk()) EidosValue_Float(seconds));
 	}

eidos/eidos_globals.cpp

@@ -109,6 +109,9 @@ int gEidosFloatOutputPrecision = 6;
 int gEidosDebugIndent = 0;
 #endif
 
+// start our wall clock duration timer at launch; this is for Eidos_WallTimeSeconds().
+std::chrono::steady_clock::time_point gEidos_WallTimeBegin = std::chrono::steady_clock::now();
+
 
 #pragma mark -
 #pragma mark Profiling support
@@ -1929,7 +1932,7 @@ void CheckLongTermBoundary()
 
 
 #pragma mark -
-#pragma mark Memory usage monitoring
+#pragma mark Memory usage and runtime monitoring
 #pragma mark -
 
 //
@@ -2228,6 +2231,45 @@ void Eidos_CheckRSSAgainstMax(const std::string &p_message1, const std::string &
 	}
 }
 
+double Eidos_WallTimeSeconds(void)
+{
+	std::chrono::steady_clock::time_point end_wall = std::chrono::steady_clock::now();
+	std::chrono::steady_clock::duration wall_duration = end_wall - gEidos_WallTimeBegin;
+	double wall_time_secs = std::chrono::duration<double>(wall_duration).count();
+	
+	return wall_time_secs;
+}
+
+void Eidos_GetUserSysTime(double *p_user_time, double *p_sys_time)
+{
+	double user_time, sys_time;
+	
+#if defined(__unix__) || defined(__unix) || defined(unix) || (defined(__APPLE__) && defined(__MACH__))
+	/* BSD, Linux, and OSX -------------------------------------- */
+	struct rusage rusage;
+	getrusage( RUSAGE_SELF, &rusage );
+	
+	user_time = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec / 1000000.0;
+	sys_time = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec / 1000000.0;	
+#elif defined(_WIN32)
+	/* Windows might be the same?  Let's find out! -------------- */
+	struct rusage rusage;
+	getrusage( RUSAGE_SELF, &rusage );
+	
+	user_time = rusage.ru_utime.tv_sec + rusage.ru_utime.tv_usec / 1000000.0;
+	sys_time = rusage.ru_stime.tv_sec + rusage.ru_stime.tv_usec / 1000000.0;	
+#else
+	/* Unknown OS ----------------------------------------------- */
+	user_time = 0.0;			/* Unsupported. */
+	sys_time = 0.0;				/* Unsupported. */
+#endif
+	
+	if (p_user_time)
+		*p_user_time = user_time;
+	if (p_sys_time)
+		*p_sys_time = sys_time;
+}
+
 
 #pragma mark -
 #pragma mark File I/O

eidos/eidos_globals.h

@@ -244,10 +244,10 @@ void CheckLongTermBoundary();
 
 // *******************************************************************************************************************
 //
-//	Memory usage monitoring
+//	Memory usage and runtime monitoring
 //
 #pragma mark -
-#pragma mark Memory usage monitoring
+#pragma mark Memory usage and runtime monitoring
 #pragma mark -
 
 // Memory-monitoring calls.  See the .cpp for comments.  These return a size in bytes.
@@ -263,6 +263,12 @@ size_t Eidos_GetMaxRSS(void);
 // It is a good idea to check eidos_do_memory_checks before calling this, to save calling overhead.
 void Eidos_CheckRSSAgainstMax(const std::string &p_message1, const std::string &p_message2);
 
+// This provides the elapsed wall clock time, in seconds, since process startup.
+double Eidos_WallTimeSeconds(void);
+
+// This provides total process time usage in terms of user CPU time and system CPU time, not wall clock time.
+void Eidos_GetUserSysTime(double *p_user_time, double *p_sys_time);
+
 
 // *******************************************************************************************************************
 //

eidostool/main.cpp

@@ -170,7 +170,6 @@ int main(int argc, const char * argv[])
 
 	// keep time (we do this whether or not the -time flag was passed)
 	std::clock_t begin_cpu = std::clock();
-	std::chrono::steady_clock::time_point begin_wall = std::chrono::steady_clock::now();
 
 	// keep memory usage information, if asked to
 	size_t initial_mem_usage = 0;
@@ -254,15 +253,20 @@ int main(int argc, const char * argv[])
 	Eidos_FlushFiles();
 
 	// end timing and print elapsed time
-	std::clock_t end_cpu = std::clock();
-	std::chrono::steady_clock::time_point end_wall = std::chrono::steady_clock::now();
-	double cpu_time_secs = static_cast<double>(end_cpu - begin_cpu) / CLOCKS_PER_SEC;
-	double wall_time_secs = std::chrono::duration<double>(end_wall - begin_wall).count();
-	
 	if (keep_time)
 	{
+		std::clock_t end_cpu = std::clock();
+		double cpu_time_secs = static_cast<double>(end_cpu - begin_cpu) / CLOCKS_PER_SEC;
+		double user_time, sys_time;
+		
+		Eidos_GetUserSysTime(&user_time, &sys_time);
+		
 		std::cout << "// ********** CPU time used: " << cpu_time_secs << std::endl;
-		std::cout << "// ********** Wall time used: " << wall_time_secs << std::endl;
+		if (user_time > 0.0)
+			std::cout << "// ********** User CPU time: " << user_time << std::endl;
+		if (sys_time > 0.0)
+			std::cout << "// ********** System CPU time: " << sys_time << std::endl;
+		std::cout << "// ********** Wall time used: " << Eidos_WallTimeSeconds() << std::endl;
 	}
 
 	// print memory usage stats