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.
This commit is contained in:
Christian Helmuth 2023-07-12 08:04:53 +02:00
parent 484bde4b4b
commit 12fc9a0fbb
5 changed files with 54 additions and 27 deletions

View File

@ -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"/>

View File

@ -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

View File

@ -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;

View File

@ -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) {

View File

@ -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);