trace: support more facets of execution time

- execution time per thread context
- execution time per scheduling context
- quantum and priority

Issue #3192

repos/base-fiasco/src/core/include/platform_thread.h

@@ -17,6 +17,7 @@
 /* Genode includes */
 #include <base/native_capability.h>
 #include <base/thread_state.h>
+#include <base/trace/types.h>
 
 /* core includes */
 #include <pager.h>
@@ -178,7 +179,7 @@ namespace Genode {
 			/**
 			 * Return execution time consumed by the thread
 			 */
-			unsigned long long execution_time() const { return 0; }
+			Trace::Execution_time execution_time() const { return { 0, 0 }; }
 
 
 			/*******************************

repos/base-foc/src/core/include/platform_thread.h

@@ -18,6 +18,7 @@
 /* Genode includes */
 #include <base/native_capability.h>
 #include <base/thread_state.h>
+#include <base/trace/types.h>
 
 /* core includes */
 #include <pager.h>
@@ -193,7 +194,7 @@ namespace Genode {
 			/**
 			 * Return execution time consumed by the thread
 			 */
-			unsigned long long execution_time() const;
+			Trace::Execution_time execution_time() const;
 
 
 			/*******************************

repos/base-foc/src/core/platform_thread.cc

@@ -35,11 +35,11 @@ namespace Fiasco {
 using namespace Genode;
 using namespace Fiasco;
 
-unsigned long long Platform_thread::execution_time() const
+Trace::Execution_time Platform_thread::execution_time() const
 {
 	Fiasco::l4_kernel_clock_t us = 0;
 	l4_thread_stats_time(_thread.local.data()->kcap(), &us);
-	return (unsigned long long)us;
+	return { us, 0, 10000 /* quantum readable ?*/, _prio };
 }
 
 

repos/base-hw/src/core/platform_thread.cc

@@ -51,8 +51,11 @@ Platform_thread::~Platform_thread()
 }
 
 
-void Platform_thread::quota(size_t const quota) {
-	Kernel::thread_quota(_kobj.kernel_object(), quota); }
+void Platform_thread::quota(size_t const quota)
+{
+	_quota = quota;
+	Kernel::thread_quota(_kobj.kernel_object(), quota);
+}
 
 
 Platform_thread::Platform_thread(Label const &label, Native_utcb &utcb)
@@ -86,8 +89,10 @@ Platform_thread::Platform_thread(size_t             const  quota,
 	_pd(nullptr),
 	_pager(nullptr),
 	_utcb_pd_addr((Native_utcb *)utcb),
+	_priority(_scale_priority(virt_prio)),
+	_quota(quota),
 	_main_thread(false),
-	_kobj(true, _priority(virt_prio), quota, _label.string())
+	_kobj(true, _priority, _quota, _label.string())
 {
 	try {
 		_utcb = core_env().pd_session()->alloc(sizeof(Native_utcb), CACHED);

repos/base-hw/src/core/platform_thread.h

@@ -18,6 +18,7 @@
 /* Genode includes */
 #include <base/ram_allocator.h>
 #include <base/thread.h>
+#include <base/trace/types.h>
 
 /* base-internal includes */
 #include <base/internal/native_utcb.h>
@@ -58,6 +59,8 @@ namespace Genode {
 		Native_utcb *            _utcb_core_addr { }; /* UTCB addr in core */
 		Native_utcb *            _utcb_pd_addr;       /* UTCB addr in pd   */
 		Ram_dataspace_capability _utcb           { }; /* UTCB dataspace    */
+		unsigned                 _priority       {0};
+		unsigned                 _quota          {0};
 
 		/*
 		 * Wether this thread is the main thread of a program.
@@ -83,7 +86,7 @@ namespace Genode {
 		 */
 		bool _attaches_utcb_by_itself();
 
-		unsigned _priority(unsigned virt_prio)
+		unsigned _scale_priority(unsigned virt_prio)
 		{
 			return Cpu_session::scale_priority(Kernel::Cpu_priority::MAX,
 			                                   virt_prio);
@@ -205,7 +208,8 @@ namespace Genode {
 			/**
 			 * Return execution time consumed by the thread
 			 */
-			unsigned long long execution_time() const { return 0; }
+			Trace::Execution_time execution_time() const {
+				return { 0, 0, _quota, _priority }; }
 
 
 			/***************

repos/base-linux/src/core/include/platform_thread.h

@@ -18,8 +18,9 @@
 
 /* Genode includes */
 #include <base/thread_state.h>
-#include <cpu_session/cpu_session.h>
+#include <base/trace/types.h>
 #include <base/weak_ptr.h>
+#include <cpu_session/cpu_session.h>
 
 /* base-internal includes */
 #include <base/internal/server_socket_pair.h>
@@ -175,7 +176,7 @@ namespace Genode {
 			/**
 			 * Return execution time consumed by the thread
 			 */
-			unsigned long long execution_time() const { return 0; }
+			Trace::Execution_time execution_time() const { return { 0, 0 }; }
 
 			unsigned long pager_object_badge() const { return 0; }
 	};

repos/base-nova/src/core/include/platform_thread.h

@@ -19,6 +19,7 @@
 #include <base/thread_state.h>
 #include <base/thread.h>
 #include <nova_native_cpu/nova_native_cpu.h>
+#include <base/trace/types.h>
 
 /* base-internal includes */
 #include <base/internal/stack.h>
@@ -210,7 +211,7 @@ namespace Genode {
 			/**
 			 * Return execution time consumed by the thread
 			 */
-			unsigned long long execution_time() const;
+			Trace::Execution_time execution_time() const;
 	};
 }
 

repos/base-nova/src/core/platform.cc

@@ -857,7 +857,7 @@ Platform::Platform()
 				            ", res=", res);
 
 				return { Session_label("kernel"), Trace::Thread_name(name),
-				         Trace::Execution_time(sc_time), affinity };
+				         Trace::Execution_time(sc_time, sc_time), affinity };
 			}
 
 			Trace_source(Trace::Source_registry &registry,
@@ -909,7 +909,7 @@ Platform::Platform()
 			}
 
 			return { Session_label("core"), name,
-			         Trace::Execution_time(sc_time), location };
+			         Trace::Execution_time(sc_time, sc_time), location };
 		}
 
 		Core_trace_source(Trace::Source_registry &registry,

repos/base-nova/src/core/platform_thread.cc

@@ -297,19 +297,19 @@ const char * Platform_thread::pd_name() const {
 	return _pd ? _pd->name() : "unknown"; }
 
 
-unsigned long long Platform_thread::execution_time() const
+Trace::Execution_time Platform_thread::execution_time() const
 {
 	unsigned long long time = 0;
 
 	/* for ECs without a SC we simply return 0 */
 	if (!sc_created())
-		return time;
+		return { time, time, Nova::Qpd::DEFAULT_QUANTUM, _priority };
 
 	uint8_t res = Nova::sc_ctrl(_sel_sc(), time);
 	if (res != Nova::NOVA_OK)
 		warning("sc_ctrl failed res=", res);
 
-	return time;
+	return { time, time, Nova::Qpd::DEFAULT_QUANTUM, _priority };
 }
 
 

repos/base-nova/src/core/thread_start.cc

@@ -135,7 +135,7 @@ void Thread::start()
 			uint64_t sc_time = 0;
 
 			return { Session_label("core"), thread.name(),
-			         Trace::Execution_time(sc_time), thread._affinity };
+			         Trace::Execution_time(sc_time, sc_time), thread._affinity };
 		}
 
 		Core_trace_source(Trace::Source_registry &registry, Thread &t)

repos/base-okl4/src/core/include/platform_thread.h

@@ -16,6 +16,7 @@
 
 /* Genode includes */
 #include <base/thread_state.h>
+#include <base/trace/types.h>
 
 /* core includes */
 #include <pager.h>
@@ -175,7 +176,7 @@ namespace Genode {
 			/**
 			 * Return execution time consumed by the thread
 			 */
-			unsigned long long execution_time() const { return 0; }
+			Trace::Execution_time execution_time() const { return { 0, 0 }; }
 
 
 			/*****************************

repos/base-pistachio/src/core/include/platform_thread.h

@@ -17,6 +17,7 @@
 /* Genode includes */
 #include <base/native_capability.h>
 #include <base/thread_state.h>
+#include <base/trace/types.h>
 
 /* core includes */
 #include <pager.h>
@@ -188,7 +189,7 @@ namespace Genode {
 			/**
 			 * Return execution time consumed by the thread
 			 */
-			unsigned long long execution_time() const { return 0; }
+			Trace::Execution_time execution_time() const { return { 0, 0 }; }
 
 
 			/**********************************

repos/base-sel4/src/core/include/platform_thread.h

@@ -17,6 +17,7 @@
 /* Genode includes */
 #include <base/thread_state.h>
 #include <util/string.h>
+#include <base/trace/types.h>
 
 /* core includes */
 #include <pager.h>
@@ -140,7 +141,7 @@ class Genode::Platform_thread : public List<Platform_thread>::Element
 		/**
 		 * Return execution time consumed by the thread
 		 */
-		unsigned long long execution_time() const;
+		Trace::Execution_time execution_time() const;
 
 
 		/************************

repos/base-sel4/src/core/platform.cc

@@ -586,9 +586,10 @@ Platform::Platform()
 
 				seL4_BenchmarkGetThreadUtilisation(tcb_sel.value());
 				uint64_t execution_time = buf[BENCHMARK_IDLE_TCBCPU_UTILISATION];
+				uint64_t sc_time = 0; /* not supported */
 
 				return { Session_label("kernel"), Trace::Thread_name("idle"),
-				         Trace::Execution_time(execution_time), affinity };
+				         Trace::Execution_time(execution_time, sc_time), affinity };
 			}
 
 			Idle_trace_source(Trace::Source_registry &registry,

repos/base-sel4/src/core/platform_thread.cc

@@ -258,11 +258,11 @@ Platform_thread::~Platform_thread()
 	platform_specific().core_sel_alloc().free(_pager_obj_sel);
 }
 
-unsigned long long Platform_thread::execution_time() const
+Trace::Execution_time Platform_thread::execution_time() const
 {
 	if (!Thread::myself() || !Thread::myself()->utcb()) {
 		error("don't know myself");
-		return 0;
+		return { 0, 0, 10000, _priority };
 	}
 	Thread &myself = *Thread::myself();
 
@@ -272,8 +272,9 @@ unsigned long long Platform_thread::execution_time() const
 	/* kernel puts execution time on ipc buffer of calling thread */
 	seL4_BenchmarkGetThreadUtilisation(_info.tcb_sel.value());
 
-	uint64_t const execution_time = values[BENCHMARK_TCB_UTILISATION];
-	return execution_time;
+	uint64_t const ec_time = values[BENCHMARK_TCB_UTILISATION];
+	uint64_t const sc_time = 0; /* not supported */
+	return { ec_time, sc_time, 10000, _priority};
 }
 
 void Platform_thread::setup_vcpu(Cap_sel ept, Cap_sel notification)

repos/base-sel4/src/core/thread_start.cc

@@ -125,7 +125,7 @@ void Thread::start()
 			uint64_t const thread_time = buf[BENCHMARK_TCB_UTILISATION];
 
 			return { Session_label("core"), _thread.name(),
-			         Trace::Execution_time(thread_time), _thread._affinity };
+			         Trace::Execution_time(thread_time, 0), _thread._affinity };
 		}
 
 

repos/base/include/base/trace/types.h

@@ -17,6 +17,8 @@
 /* Genode includes */
 #include <util/string.h>
 #include <base/affinity.h>
+#include <base/exception.h>
+#include <base/fixed_stdint.h>
 #include <base/session_label.h>
 
 namespace Genode { namespace Trace {
@@ -77,10 +79,19 @@ struct Genode::Trace::Subject_id
  */
 struct Genode::Trace::Execution_time
 {
-	unsigned long long value;
+	uint64_t thread_context;
+	addr_t   scheduling_context;
+	uint16_t quantum { 0 };
+	uint16_t priority { 0 };
 
-	Execution_time() : value(0) { }
-	Execution_time(unsigned long long value) : value(value) { }
+	Execution_time() : thread_context(0), scheduling_context(0) { }
+	Execution_time(uint64_t thread_context, uint64_t scheduling_context)
+	: thread_context(thread_context), scheduling_context(scheduling_context) { }
+
+	Execution_time(uint64_t thread_context, uint64_t scheduling_context,
+	               unsigned quantum, unsigned priority)
+	: thread_context(thread_context), scheduling_context(scheduling_context),
+	  quantum(quantum), priority(priority) { }
 };
 
 
@@ -112,7 +123,7 @@ class Genode::Trace::Subject_info
 		Thread_name        _thread_name    { };
 		State              _state          { INVALID };
 		Policy_id          _policy_id      { 0 };
-		Execution_time     _execution_time { 0 };
+		Execution_time     _execution_time { 0, 0 };
 		Affinity::Location _affinity       { };
 
 	public:

repos/os/src/app/top/main.cc

@@ -40,11 +40,11 @@ struct Trace_subject_registry
 
 			void update(Genode::Trace::Subject_info const &new_info)
 			{
-				if (new_info.execution_time().value < info.execution_time().value)
+				if (new_info.execution_time().thread_context < info.execution_time().thread_context)
 					recent_execution_time = 0;
 				else
-					recent_execution_time = new_info.execution_time().value -
-				                            info.execution_time().value;
+					recent_execution_time = new_info.execution_time().thread_context -
+				                            info.execution_time().thread_context;
 
 				info = new_info;
 			}

repos/os/src/app/trace_logger/monitor.cc

@@ -75,12 +75,12 @@ void Monitor::_update_info()
 		Trace::Subject_info const &info =
 			_trace.subject_info(_subject_id);
 
-		unsigned long long const last_execution_time =
-			_info.execution_time().value;
+		uint64_t const last_execution_time =
+			_info.execution_time().thread_context;
 
 		_info = info;
 		_recent_exec_time =
-			_info.execution_time().value - last_execution_time;
+			_info.execution_time().thread_context - last_execution_time;
 	}
 	catch (Trace::Nonexistent_subject) { warning("Cannot update subject info: Nonexistent_subject"); }
 }
@@ -101,7 +101,7 @@ void Monitor::print(bool activity, bool affinity)
 
 	/* print subjects activity if desired */
 	if (activity)
-		log("   <activity total=\"",  _info.execution_time().value,
+		log("   <activity total=\"",  _info.execution_time().thread_context,
 		              "\" recent=\"", _recent_exec_time,
 		              "\">");
 

repos/os/src/app/trace_subject_reporter/main.cc

@@ -41,9 +41,9 @@ struct Trace_subject_registry
 
 			void update(Genode::Trace::Subject_info const &new_info)
 			{
-				unsigned long long const last_execution_time = info.execution_time().value;
+				unsigned long long const last_execution_time = info.execution_time().thread_context;
 				info = new_info;
-				recent_execution_time = info.execution_time().value - last_execution_time;
+				recent_execution_time = info.execution_time().thread_context - last_execution_time;
 			}
 		};
 
@@ -134,7 +134,7 @@ struct Trace_subject_registry
 
 					if (report_activity)
 						xml.node("activity", [&] () {
-							xml.attribute("total", e->info.execution_time().value);
+							xml.attribute("total", e->info.execution_time().thread_context);
 							xml.attribute("recent", e->recent_execution_time);
 						});
 

repos/os/src/test/trace/main.cc

@@ -273,7 +273,10 @@ struct Test_tracing
 			    "name:\"",  info.thread_name(),     "\" "
 			    "state:",   state_name(info.state()), " "
 			    "policy:",  info.policy_id().id,      " "
-			    "time:",    info.execution_time().value);
+			    "thread context time:", info.execution_time().thread_context, " "
+			    "scheduling context time:", info.execution_time().scheduling_context, " ",
+			    "priority:", info.execution_time().priority, " ",
+			    "quantum:", info.execution_time().quantum);
 		};
 
 		for_each_subject(subjects, num_subjects, print_info);