ExternalVendorCode/genode
1
0
Fork 0
mirror of https://github.com/genodelabs/genode.git synced 2025-01-18 02:40:08 +00:00
Code Issues Actions Packages Projects Releases Wiki Activity

trace_logger: log scheduling-context execution time

Browse Source 
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

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

Fixes #4805
This commit is contained in:
Christian Helmuth 2023-04-05 14:33:40 +02:00
parent 1041ed8773
commit 684388e737
8 changed files with 50 additions and 90 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

8
repos/os/src/app/trace_logger/README
View File

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

3
repos/os/src/app/trace_logger/config.xsd
View File

@ -37,8 +37,7 @@
</xs:choice>
<xs:attribute name="verbose" type="Boolean" />
<xs:attribute name="activity" type="Boolean" />
<xs:attribute name="affinity" type="Boolean" />
<xs:attribute name="sc_time" type="Boolean" />
<xs:attribute name="session_arg_buffer" type="Number_of_bytes" />
<xs:attribute name="session_ram" type="Number_of_bytes" />
<xs:attribute name="session_parent_levels" type="xs:nonNegativeInteger" />

30
repos/os/src/app/trace_logger/main.cc
View File

@ -12,11 +12,6 @@
* under the terms of the GNU Affero General Public License version 3.
*/
/* local includes */
#include <policy.h>
#include <monitor.h>
#include <xml_node.h>
/* Genode includes */
#include <base/component.h>
#include <base/attached_rom_dataspace.h>
@ -26,6 +21,11 @@
#include <timer_session/connection.h>
#include <util/construct_at.h>
#include <util/formatted_output.h>
#include <util/xml_node.h>
/* local includes */
#include <policy.h>
#include <monitor.h>
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);

29
repos/os/src/app/trace_logger/monitor.cc
View File

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

10
repos/os/src/app/trace_logger/monitor.h
View File

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

2
repos/os/src/app/trace_logger/target.mk
View File

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

29
repos/os/src/app/trace_logger/xml_node.cc
View File

@ -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 <xml_node.h>
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);
}

29
repos/os/src/app/trace_logger/xml_node.h
View File

@ -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 <util/xml_node.h>
#include <base/duration.h>
namespace Genode {
Microseconds read_sec_attr(Xml_node const node,
char const *name,
uint64_t const default_sec);
}
#endif /* _XML_NODE_H_ */