From 684388e737df9f4510afa9fb4f9ccf947d5de3d9 Mon Sep 17 00:00:00 2001 From: Christian Helmuth Date: Wed, 5 Apr 2023 14:33:40 +0200 Subject: [PATCH] trace_logger: log scheduling-context execution time Optionally log scheduling-context execution time in addition to the thread-context. This may be relevant on kernel platforms that do not schedule threads on their own CPU share only but implement some kind of donation scheme, for example, NOVA. Usage ... Fixes #4805 --- repos/os/src/app/trace_logger/README | 8 +++++- repos/os/src/app/trace_logger/config.xsd | 3 +-- repos/os/src/app/trace_logger/main.cc | 30 +++++++++++++++-------- repos/os/src/app/trace_logger/monitor.cc | 29 +++++++++++----------- repos/os/src/app/trace_logger/monitor.h | 10 +++++--- repos/os/src/app/trace_logger/target.mk | 2 +- repos/os/src/app/trace_logger/xml_node.cc | 29 ---------------------- repos/os/src/app/trace_logger/xml_node.h | 29 ---------------------- 8 files changed, 50 insertions(+), 90 deletions(-) delete mode 100644 repos/os/src/app/trace_logger/xml_node.cc delete mode 100644 repos/os/src/app/trace_logger/xml_node.h diff --git a/repos/os/src/app/trace_logger/README b/repos/os/src/app/trace_logger/README index fac5e4341b..3074091fa1 100644 --- a/repos/os/src/app/trace_logger/README +++ b/repos/os/src/app/trace_logger/README @@ -33,9 +33,15 @@ policy.label: This is a short description of the tags and attributes: :config.verbose: - Optional. Toggles wether the trace_logger shall log debugging information. + Optional. Toggles whether the trace_logger shall log debugging information. If enabled, even inactive trace subjects appear in the log. +: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 + schedule threads on their own CPU share only but implement some kind of + donation scheme, for example, NOVA. + :config.session_ram: Optional. Amount of RAM donated to the trace session. diff --git a/repos/os/src/app/trace_logger/config.xsd b/repos/os/src/app/trace_logger/config.xsd index c854de69d5..5f37b62c59 100644 --- a/repos/os/src/app/trace_logger/config.xsd +++ b/repos/os/src/app/trace_logger/config.xsd @@ -37,8 +37,7 @@ - - + diff --git a/repos/os/src/app/trace_logger/main.cc b/repos/os/src/app/trace_logger/main.cc index fbb0abdb67..57cefc1c3c 100644 --- a/repos/os/src/app/trace_logger/main.cc +++ b/repos/os/src/app/trace_logger/main.cc @@ -12,11 +12,6 @@ * under the terms of the GNU Affero General Public License version 3. */ -/* local includes */ -#include -#include -#include - /* Genode includes */ #include #include @@ -26,6 +21,11 @@ #include #include #include +#include + +/* local includes */ +#include +#include using namespace Genode; using Thread_name = String<40>; @@ -45,6 +45,7 @@ class Main size_t session_arg_buffer; unsigned session_parent_levels; bool verbose; + bool sc_time; Microseconds period_us; size_t default_buf_sz; Policy_name default_policy_name; @@ -208,7 +209,8 @@ class Main log("\nReport ", _report_id++, "\n"); Monitor::Level_of_detail const detail { .state = _config.verbose, - .active_only = !_config.verbose }; + .active_only = !_config.verbose, + .sc_time = _config.sc_time }; _print_monitors(_heap, monitors, detail); } @@ -216,7 +218,10 @@ class Main Main(Env &env) : _env(env) { - _update_monitors(); + /* + * We skip the initial monitor update as the periodic timeout triggers + * the update immediately for the first time. + */ } }; @@ -230,7 +235,9 @@ 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), - .period_us = read_sec_attr(config, "period_sec", 5), + .sc_time = config.attribute_value("sc_time", false), + .period_us = Microseconds(config.attribute_value("period_sec", 5) + * 1'000'000), .default_buf_sz = config.attribute_value("default_buffer", Number_of_bytes(4*1024)), .default_policy_name = config.attribute_value("default_policy", @@ -293,11 +300,14 @@ 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; unsigned const table_width = fmt.thread_name + fmt.affinity + state_width - + fmt.total_cpu - + fmt.recent_cpu + + 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); diff --git a/repos/os/src/app/trace_logger/monitor.cc b/repos/os/src/app/trace_logger/monitor.cc index b762525c3e..7828141a03 100644 --- a/repos/os/src/app/trace_logger/monitor.cc +++ b/repos/os/src/app/trace_logger/monitor.cc @@ -112,17 +112,12 @@ Monitor::Monitor(Trace::Connection &trace, void Monitor::update_info(Trace::Subject_info const &info) { - try { - uint64_t const last_execution_time = - _info.execution_time().thread_context; + _recent_exec_time = { + info.execution_time().thread_context - _info.execution_time().thread_context, + info.execution_time().scheduling_context - _info.execution_time().scheduling_context + }; - _info = info; - - _recent_exec_time = - _info.execution_time().thread_context - last_execution_time; - } - catch (Trace::Nonexistent_subject) { - warning("Cannot update subject info: Nonexistent_subject"); } + _info = info; } @@ -138,8 +133,10 @@ void Monitor::apply_formatting(Formatting &formatting) const expand(formatting.thread_name, Quoted_name{_info.thread_name()}); expand(formatting.affinity, Formatted_affinity{_info.affinity()}); expand(formatting.state, Subject_info::state_name(_info.state())); - expand(formatting.total_cpu, _info.execution_time().thread_context); - expand(formatting.recent_cpu, _recent_exec_time); + 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); } @@ -152,12 +149,16 @@ void Monitor::print(Formatting fmt, Level_of_detail detail) /* print general subject information */ 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_cpu, _info.execution_time().thread_context), " " - "recent:", _recent_exec_time); + "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))); /* 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 3f7a6bab96..411d1092b0 100644 --- a/repos/os/src/app/trace_logger/monitor.h +++ b/repos/os/src/app/trace_logger/monitor.h @@ -57,14 +57,14 @@ class Monitor : public Monitor_base, Trace_buffer _buffer; unsigned long _report_id { 0 }; Genode::Trace::Subject_info _info { }; - unsigned long long _recent_exec_time { 0 }; + Genode::Trace::Execution_time _recent_exec_time { }; char _curr_entry_data[MAX_ENTRY_LENGTH]; public: struct Formatting { - unsigned thread_name, affinity, state, total_cpu, recent_cpu; + unsigned thread_name, affinity, 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; }; + struct Level_of_detail { bool state, active_only, sc_time; }; void print(Formatting, Level_of_detail); @@ -101,7 +101,9 @@ class Monitor : public Monitor_base, bool recently_active() const { - return (_recent_exec_time != 0) || !_buffer.empty(); + return _recent_exec_time.thread_context + || _recent_exec_time.scheduling_context + || !_buffer.empty(); } }; diff --git a/repos/os/src/app/trace_logger/target.mk b/repos/os/src/app/trace_logger/target.mk index 788e2a360c..7a2595dcfc 100644 --- a/repos/os/src/app/trace_logger/target.mk +++ b/repos/os/src/app/trace_logger/target.mk @@ -1,5 +1,5 @@ TARGET = trace_logger INC_DIR += $(PRG_DIR) -SRC_CC = main.cc monitor.cc policy.cc xml_node.cc +SRC_CC = main.cc monitor.cc policy.cc CONFIG_XSD = config.xsd LIBS += base diff --git a/repos/os/src/app/trace_logger/xml_node.cc b/repos/os/src/app/trace_logger/xml_node.cc deleted file mode 100644 index b2dbee1552..0000000000 --- a/repos/os/src/app/trace_logger/xml_node.cc +++ /dev/null @@ -1,29 +0,0 @@ -/* - * \brief Genode XML nodes plus local utilities - * \author Martin Stein - * \date 2016-08-19 - */ - -/* - * Copyright (C) 2016-2017 Genode Labs GmbH - * - * This file is part of the Genode OS framework, which is distributed - * under the terms of the GNU Affero General Public License version 3. - */ - -/* local includes */ -#include - -using namespace Genode; - - -Microseconds Genode::read_sec_attr(Xml_node const node, - char const *name, - uint64_t const default_sec) -{ - uint64_t sec = node.attribute_value(name, (uint64_t)0); - if (!sec) { - sec = default_sec; - } - return Microseconds(sec * 1000 * 1000); -} diff --git a/repos/os/src/app/trace_logger/xml_node.h b/repos/os/src/app/trace_logger/xml_node.h deleted file mode 100644 index 33cf34647c..0000000000 --- a/repos/os/src/app/trace_logger/xml_node.h +++ /dev/null @@ -1,29 +0,0 @@ -/* - * \brief Genode XML nodes plus local utilities - * \author Martin Stein - * \date 2016-08-19 - */ - -/* - * Copyright (C) 2016-2017 Genode Labs GmbH - * - * This file is part of the Genode OS framework, which is distributed - * under the terms of the GNU Affero General Public License version 3. - */ - -#ifndef _XML_NODE_H_ -#define _XML_NODE_H_ - -/* Genode includes */ -#include -#include - - -namespace Genode { - - Microseconds read_sec_attr(Xml_node const node, - char const *name, - uint64_t const default_sec); -} - -#endif /* _XML_NODE_H_ */