From 12fc9a0fbbcd9b741ce494bcf802769da68979af Mon Sep 17 00:00:00 2001
From: Christian Helmuth <christian.helmuth@genode-labs.com>
Date: Wed, 12 Jul 2023 08:04:53 +0200
Subject: [PATCH] trace_logger: log priority of trace subject

Optionally log thread priority with

  <config priority="yes" ...> ... </config>

The commit also applies a cleanup of format calculations.
---
 .../os/recipes/pkg/test-trace_logger/runtime  |  2 +-
 repos/os/src/app/trace_logger/README          |  5 ++
 repos/os/src/app/trace_logger/main.cc         | 20 +++++---
 repos/os/src/app/trace_logger/monitor.cc      | 50 +++++++++++++------
 repos/os/src/app/trace_logger/monitor.h       |  4 +-
 5 files changed, 54 insertions(+), 27 deletions(-)

diff --git a/repos/os/recipes/pkg/test-trace_logger/runtime b/repos/os/recipes/pkg/test-trace_logger/runtime
index d01899729f..51dbf17007 100644
--- a/repos/os/recipes/pkg/test-trace_logger/runtime
+++ b/repos/os/recipes/pkg/test-trace_logger/runtime
@@ -47,7 +47,7 @@
 
 		<start name="trace_logger">
 			<resource name="RAM" quantum="80M"/>
-			<config verbose="yes" session_ram="10M" session_parent_levels="1" session_arg_buffer="64K" period_sec="3" default_policy="null" default_buffer="1K">
+			<config verbose="yes" priority="no" sc_time="no" session_ram="10M" session_parent_levels="1" session_arg_buffer="64K" period_sec="3" default_policy="null" default_buffer="1K">
 
 				<policy label_prefix="init -> dynamic -> test-trace_logger -> cpu_burner" thread="ep"/>
 
diff --git a/repos/os/src/app/trace_logger/README b/repos/os/src/app/trace_logger/README
index 3074091fa1..1b1be7475b 100644
--- a/repos/os/src/app/trace_logger/README
+++ b/repos/os/src/app/trace_logger/README
@@ -14,6 +14,8 @@ the default value for each attribute except the policy.thread and
 policy.label:
 
 ! <config verbose="no"
+!         priority="no"
+!         sc_time="no"
 !         session_ram="10M"
 !         session_arg_buffer="4K"
 !         session_parent_levels="0"
@@ -36,6 +38,9 @@ This is a short description of the tags and attributes:
   Optional. Toggles whether the trace_logger shall log debugging information.
   If enabled, even inactive trace subjects appear in the log.
 
+:config.priority:
+  Optionally log thread priority.
+
 :config.sc_time:
   Optionally log scheduling-context execution time in addition to the
   thread-context. This may be relevant on kernel platforms that do not
diff --git a/repos/os/src/app/trace_logger/main.cc b/repos/os/src/app/trace_logger/main.cc
index 57cefc1c3c..2815ced0e8 100644
--- a/repos/os/src/app/trace_logger/main.cc
+++ b/repos/os/src/app/trace_logger/main.cc
@@ -45,6 +45,7 @@ class Main
 			size_t       session_arg_buffer;
 			unsigned     session_parent_levels;
 			bool         verbose;
+			bool         prio;
 			bool         sc_time;
 			Microseconds period_us;
 			size_t       default_buf_sz;
@@ -210,6 +211,7 @@ class Main
 			log("\nReport ", _report_id++, "\n");
 			Monitor::Level_of_detail const detail { .state       =  _config.verbose,
 			                                        .active_only = !_config.verbose,
+			                                        .prio        =  _config.prio,
 			                                        .sc_time     =  _config.sc_time };
 			_print_monitors(_heap, monitors, detail);
 		}
@@ -235,6 +237,7 @@ Main::Config Main::Config::from_xml(Xml_node const &config)
 		                                                Number_of_bytes(1024*4)),
 		.session_parent_levels = config.attribute_value("session_parent_levels", 0u),
 		.verbose               = config.attribute_value("verbose",  false),
+		.prio                  = config.attribute_value("priority", false),
 		.sc_time               = config.attribute_value("sc_time",  false),
 		.period_us             = Microseconds(config.attribute_value("period_sec", 5)
 		                                     * 1'000'000),
@@ -299,18 +302,19 @@ void Main::_print_monitors(Allocator &alloc, Monitor_tree const &monitors,
 
 	pds.for_each([&] (Pd const &pd) {
 
-		unsigned const state_width  = detail.state ? fmt.state + 1 : 0;
-		unsigned const sc_width     = detail.sc_time
-		                            ? fmt.total_sc + fmt.total_tc + 21 : 0;
+		auto opt = [] (bool cond, unsigned value) { return cond ? value : 0; };
+
 		unsigned const table_width  = fmt.thread_name
 		                            + fmt.affinity
-		                            + state_width
+		                            + 1 /* additional space */
+		                            + opt(detail.state,   fmt.state)
+		                            + opt(detail.prio,    fmt.prio)
 		                            + fmt.total_tc
 		                            + fmt.recent_tc
-		                            + sc_width
-		                            + 26;
-		unsigned const pd_width     = (unsigned)pd.label.length() + 6;
-		unsigned const excess_width = table_width - min(table_width, pd_width);
+		                            + opt(detail.sc_time, fmt.total_sc)
+		                            + opt(detail.sc_time, fmt.recent_sc);
+		unsigned const pd_width     = 4 + (unsigned)(pd.label.length() - 1) + 1;
+		unsigned const excess_width = table_width - min(table_width, pd_width + 1);
 
 		if (detail.active_only && !pd.recently_active())
 			return;
diff --git a/repos/os/src/app/trace_logger/monitor.cc b/repos/os/src/app/trace_logger/monitor.cc
index 7828141a03..050576b7de 100644
--- a/repos/os/src/app/trace_logger/monitor.cc
+++ b/repos/os/src/app/trace_logger/monitor.cc
@@ -31,7 +31,24 @@ struct Formatted_affinity
 
 	void print(Genode::Output &out) const
 	{
-		Genode::print(out, "at (", affinity.xpos(),",", affinity.ypos(), ")");
+		Genode::print(out, " at (", affinity.xpos(),",", affinity.ypos(), ")");
+	}
+};
+
+
+template<typename T>
+struct Formatted
+{
+	char const *type = "";
+
+	T const &value;
+
+	Formatted(T const &value) : value(value) { }
+	Formatted(char const *type, T const &value) : type(type), value(value) { }
+
+	void print(Genode::Output &out) const
+	{
+		Genode::print(out, " ", type, value);
 	}
 };
 
@@ -130,13 +147,14 @@ void Monitor::apply_formatting(Formatting &formatting) const
 
 	typedef Trace::Subject_info Subject_info;
 
-	expand(formatting.thread_name, Quoted_name{_info.thread_name()});
+	expand(formatting.thread_name, Formatted("Thread ", Quoted_name{_info.thread_name()}));
 	expand(formatting.affinity,    Formatted_affinity{_info.affinity()});
-	expand(formatting.state,       Subject_info::state_name(_info.state()));
-	expand(formatting.total_tc,    _info.execution_time().thread_context);
-	expand(formatting.recent_tc,   _recent_exec_time.thread_context);
-	expand(formatting.total_sc,    _info.execution_time().scheduling_context);
-	expand(formatting.recent_sc,   _recent_exec_time.scheduling_context);
+	expand(formatting.state,       Formatted(Subject_info::state_name(_info.state())));
+	expand(formatting.prio,        Formatted("prio:", _info.execution_time().priority));
+	expand(formatting.total_tc,    Formatted("total:", _info.execution_time().thread_context));
+	expand(formatting.recent_tc,   Formatted("recent:", _recent_exec_time.thread_context));
+	expand(formatting.total_sc,    Formatted("total_sc:", _info.execution_time().scheduling_context));
+	expand(formatting.recent_sc,   Formatted("recent_sc:", _recent_exec_time.scheduling_context));
 }
 
 
@@ -150,15 +168,15 @@ void Monitor::print(Formatting fmt, Level_of_detail detail)
 	typedef Trace::Subject_info Subject_info;
 	Subject_info::State const state = _info.state();
 
-	log(" Thread ", Left_aligned(fmt.thread_name, Quoted_name{_info.thread_name()}),
-	    " ",        Left_aligned(fmt.affinity, Formatted_affinity{_info.affinity()}),
-	    "  ",       Conditional(detail.state,
-	                            Left_aligned(fmt.state + 1, Subject_info::state_name(state))),
-	    "total:",   Left_aligned(fmt.total_tc, _info.execution_time().thread_context), " "
-	    "recent:",  Left_aligned(fmt.recent_tc, _recent_exec_time.thread_context),
-	    Conditional(detail.sc_time, String<80>(
-	      " total_sc:",  Left_aligned(fmt.total_sc, _info.execution_time().scheduling_context),
-	      " recent_sc:", _recent_exec_time.scheduling_context)));
+	log(Left_aligned(fmt.thread_name, Formatted("Thread ", Quoted_name{_info.thread_name()})),
+	    Left_aligned(fmt.affinity, Formatted_affinity{_info.affinity()}),
+	    " ",
+	    Conditional(detail.state, Left_aligned(fmt.state, Formatted("", Subject_info::state_name(state)))),
+	    Conditional(detail.prio, Left_aligned(fmt.prio, Formatted("prio:", _info.execution_time().priority))),
+	    Left_aligned(fmt.total_tc,  Formatted("total:",  _info.execution_time().thread_context)),
+	    Left_aligned(fmt.recent_tc, Formatted("recent:", _recent_exec_time.thread_context)),
+	    Conditional(detail.sc_time, Left_aligned(fmt.total_sc,  Formatted("total_sc:",  _info.execution_time().scheduling_context))),
+	    Conditional(detail.sc_time, Left_aligned(fmt.recent_sc, Formatted("recent_sc:", _recent_exec_time.scheduling_context))));
 
 	/* print all buffer entries that we haven't yet printed */
 	_buffer.for_each_new_entry([&] (Trace::Buffer::Entry entry) {
diff --git a/repos/os/src/app/trace_logger/monitor.h b/repos/os/src/app/trace_logger/monitor.h
index 411d1092b0..44110fca15 100644
--- a/repos/os/src/app/trace_logger/monitor.h
+++ b/repos/os/src/app/trace_logger/monitor.h
@@ -64,7 +64,7 @@ class Monitor : public Monitor_base,
 
 		struct Formatting
 		{
-			unsigned thread_name, affinity, state, total_tc, recent_tc, total_sc, recent_sc;
+			unsigned thread_name, affinity, prio, state, total_tc, recent_tc, total_sc, recent_sc;
 		};
 
 		Monitor(Genode::Trace::Connection &trace,
@@ -76,7 +76,7 @@ class Monitor : public Monitor_base,
 		 */
 		void apply_formatting(Formatting &) const;
 
-		struct Level_of_detail { bool state, active_only, sc_time; };
+		struct Level_of_detail { bool state, active_only, prio, sc_time; };
 
 		void print(Formatting, Level_of_detail);