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

trace_logger: make output format more concise

Browse Source 
This patch changes the output format of the trace logger to become
better suitable for human consumption. For example, when instrumenting
the VFS server in Sculpt using the GENODE_TRACE_TSC utility, the
trace logger now generates tabular output as follows.

  Report 4

  PD "init -> runtime -> arch_vbox6 -> vbox -> " ----------------
   Thread "vCPU"           at (0,0)  total:12909024 recent:989229
   Thread "vCPU"           at (1,0)  total:5643234  recent:786437

  PD "init -> runtime -> ahci-0.fs" -----------------------------
   Thread "ahci-0.fs"      at (0,0)  total:910497   recent:6335
   Thread "ep"             at (0,0)  total:0        recent:0
    71919692932: TSC process_packets: 8005M (4998 calls, last 4932K)
    71921558516: TSC process_packets: 8006M (4999 calls, last 1596K)
    71922760220: TSC process_packets: 8007M (5000 calls, last 1006K)
    71929853586: TSC process_packets: 8009M (5001 calls, last 1840K)
    71931315246: TSC process_packets: 8011M (5002 calls, last 1253K)
    72127999920: TSC process_packets: 8016M (5003 calls, last 5606K)
    72129568198: TSC process_packets: 8018M (5004 calls, last 1345K)
    77161908178: TSC process_packets: 8029M (5005 calls, last 11349K)
    77643225736: TSC process_packets: 8029M (5006 calls, last 217K)
    89422100594: TSC process_packets: 8035M (5007 calls, last 5656K)
    89422123632: TSC process_packets: 8035M (5008 calls, last 1342)
   Thread "signal handler" at (0,0)  total:36329    recent:3001
   Thread "signal_proxy"   at (0,0)  total:51838    recent:13099
   Thread "pdaemon"        at (0,0)  total:97184    recent:332
   Thread "vdrain"         at (0,0)  total:1266     recent:286
   Thread "vrele"          at (0,0)  total:1904     recent:516

  PD "init -> runtime -> nic_drv" -------------------------------
   Thread "nic_drv"        at (0,0)  total:34044    recent:897
   Thread "signal handler" at (0,0)  total:369      recent:142

  ...

Subjects that belong to the same PD are grouped together. The formerly
optional affinity and activity options have been removed. Those
information are now unconditionally displayed. The trace entries
belonging to a thread appear as slightly indented.

The patch also updates the coding style, avoiding excessively long
lines.

Issue #4448
This commit is contained in:
Norman Feske 2022-03-11 17:50:01 +01:00 committed by Christian Helmuth
parent f7270c44cb
commit 3394f97f86
6 changed files with 288 additions and 146 deletions
Show Stats Download Patch File Download Diff File Expand all files Collapse all files

36
repos/os/recipes/pkg/test-trace_logger/runtime
View File

@ -5,30 +5,16 @@
<events>
<timeout meaning="failed" sec="20" />
<log meaning="succeeded">
[init -> trace_logger] --- Report * (4/* subjects) ---*
[init -> trace_logger] &lt;subject label="init -> dynamic -> test-trace_logger -> cpu_burner.*" thread="ep" id="*" state="TRACED">
[init -> trace_logger] &lt;activity total="*" recent="*">
[init -> trace_logger] &lt;affinity xpos="0" ypos="0">
[init -> trace_logger] &lt;buffer />
[init -> trace_logger] &lt;/subject>*
[init -> trace_logger] &lt;subject label="init -> dynamic -> test-trace_logger -> cpu_burner.*" thread="ep" id="*" state="TRACED">
[init -> trace_logger] &lt;activity total="*" recent="*">
[init -> trace_logger] &lt;affinity xpos="0" ypos="0">
[init -> trace_logger] &lt;buffer />
[init -> trace_logger] &lt;/subject>*
[init -> trace_logger] &lt;subject label="init -> dynamic -> test-trace_logger -> dynamic_rom" thread="ep" id="*" state="TRACED">
[init -> trace_logger] &lt;activity total="*" recent="*">
[init -> trace_logger] &lt;affinity xpos="0" ypos="0">
[init -> trace_logger] &lt;buffer>*
[init -> trace_logger] cpu_burner*.config: change*
[init -> trace_logger] &lt;/subject>*
[init -> trace_logger] &lt;subject label="init -> dynamic -> test-trace_logger -> test-trace_logger" thread="ep" id="*" state="TRACED">
[init -> trace_logger] &lt;activity total="*" recent="*">
[init -> trace_logger] &lt;affinity xpos="0" ypos="0">
[init -> trace_logger] &lt;buffer>*
[init -> trace_logger] 100 *
[init -> trace_logger] trigger_once
[init -> trace_logger] trigger_once
[init -> trace_logger] Report *
[init -> trace_logger] PD "init -> dynamic -> test-trace_logger -> cpu_burner.*"*
[init -> trace_logger] Thread "ep" at (0,0) TRACED total:* recent:*
[init -> trace_logger] PD "init -> dynamic -> test-trace_logger -> dynamic_rom"*
[init -> trace_logger] Thread "ep" at (0,0) TRACED total:* recent:*
[init -> trace_logger] PD "init -> dynamic -> test-trace_logger -> test-trace_logger"*
[init -> trace_logger] Thread "ep" at (0,0) TRACED total:* recent:*
[init -> trace_logger] 100 *
[init -> trace_logger] trigger_once
[init -> trace_logger] trigger_once
</log>
</events>
@ -68,8 +54,6 @@
session_parent_levels="1"
session_arg_buffer="64K"
period_sec="3"
activity="yes"
affinity="yes"
default_policy="null"
default_buffer="1K">

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

@ -18,8 +18,6 @@ policy.label:
! session_arg_buffer="4K"
! session_parent_levels="0"
! period_sec="5"
! activity="no"
! affinity="no"
! default_policy="null"
! default_buffer="4K">
!
@ -50,16 +48,10 @@ This is a short description of the tags and attributes:
:config.period_sec:
Optional. Length of processing/export interval in seconds.
:config.activity:
Optional. Wether to export thread-activity information.
:config.affinity:
Optional. Wether to export thread-affinity information.
:config.default_policy:
Optional. Name of tracing policy for subjects without individual config.
:config.default_policy:
:config.default_buffer:
Optional. Size of tracing buffer for subjects without individual config.
:config.policy:
@ -96,4 +88,4 @@ Examples
~~~~~~~~
An Example of how to use the trace_logger component can be found in the test
script 'os/run/trace_logger.run'.
package at 'os/recipes/pkg/test-trace_logger/'.

2
repos/os/src/app/trace_logger/avl_tree.h
View File

@ -50,6 +50,8 @@ struct Local::Avl_tree : Genode::Avl_tree<NT>
{
using Base = Genode::Avl_tree<NT>;
using Genode::Avl_tree<NT>::for_each;
template <typename FUNC>
void for_each(FUNC && functor) {
if (Base::first()) Base::first()->for_each(functor); }

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

@ -1,6 +1,7 @@
/*
* \brief Log information about trace subjects
* \author Martin Stein
* \author Norman Feske
* \date 2018-01-15
*/
@ -20,9 +21,11 @@
#include <base/component.h>
#include <base/attached_rom_dataspace.h>
#include <base/heap.h>
#include <base/registry.h>
#include <os/session_policy.h>
#include <timer_session/connection.h>
#include <util/construct_at.h>
#include <util/formatted_output.h>
using namespace Genode;
using Thread_name = String<40>;
@ -32,40 +35,46 @@ class Main
{
private:
enum { MAX_SUBJECTS = 512 };
enum { DEFAULT_PERIOD_SEC = 5 };
enum { DEFAULT_BUFFER = 1024 * 4 };
enum { DEFAULT_SESSION_ARG_BUFFER = 1024 * 4 };
enum { DEFAULT_SESSION_RAM = 1024 * 1024 };
enum { DEFAULT_SESSION_PARENT_LEVELS = 0 };
Env &_env;
Env &_env;
Timer::Connection _timer { _env };
Attached_rom_dataspace _config_rom { _env, "config" };
Xml_node const _config { _config_rom.xml() };
Trace::Connection _trace { _env,
_config.attribute_value("session_ram", Number_of_bytes(DEFAULT_SESSION_RAM)),
_config.attribute_value("session_arg_buffer", Number_of_bytes(DEFAULT_SESSION_ARG_BUFFER)),
_config.attribute_value("session_parent_levels", (unsigned)DEFAULT_SESSION_PARENT_LEVELS) };
bool const _affinity { _config.attribute_value("affinity", false) };
bool const _activity { _config.attribute_value("activity", false) };
bool const _verbose { _config.attribute_value("verbose", false) };
Microseconds const _period_us { read_sec_attr(_config, "period_sec", DEFAULT_PERIOD_SEC) };
Number_of_bytes const _default_buf_sz { _config.attribute_value("default_buffer", Number_of_bytes(DEFAULT_BUFFER)) };
Timer::Periodic_timeout<Main> _period { _timer, *this, &Main::_handle_period, _period_us };
Heap _heap { _env.ram(), _env.rm() };
Monitor_tree _monitors_0 { };
Monitor_tree _monitors_1 { };
bool _monitors_switch { false };
Policy_tree _policies { };
Policy_name _default_policy_name { _config.attribute_value("default_policy", Policy_name("null")) };
Policy _default_policy { _env, _trace, _default_policy_name };
unsigned long _report_id { 0 };
unsigned long _num_subjects { 0 };
unsigned long _num_monitors { 0 };
Trace::Subject_id _subjects[MAX_SUBJECTS];
Attached_rom_dataspace _config_rom { _env, "config" };
void _handle_period(Duration)
struct Config
{
size_t session_ram;
size_t session_arg_buffer;
unsigned session_parent_levels;
bool verbose;
Microseconds period_us;
size_t default_buf_sz;
Policy_name default_policy_name;
static Config from_xml(Xml_node const &);
} const _config { Config::from_xml(_config_rom.xml()) };
Trace::Connection _trace { _env,
_config.session_ram,
_config.session_arg_buffer,
_config.session_parent_levels };
Timer::Connection _timer { _env };
Timer::Periodic_timeout<Main> _period {
_timer, *this, &Main::_handle_period, _config.period_us };
Heap _heap { _env.ram(), _env.rm() };
Monitor_tree _monitors_0 { };
Monitor_tree _monitors_1 { };
bool _monitors_switch { false };
Policy_tree _policies { };
Policy _default_policy { _env, _trace, _config.default_policy_name };
unsigned long _report_id { 0 };
static void _print_monitors(Allocator &alloc, Monitor_tree const &,
Monitor::Level_of_detail);
void _update_monitors()
{
/*
* Update monitors
@ -98,7 +107,7 @@ class Main
if (info.state() == Trace::Subject_info::DEAD)
return;
with_matching_policy(info.session_label(), _config,
with_matching_policy(info.session_label(), _config_rom.xml(),
[&] (Xml_node const &policy) {
@ -115,7 +124,7 @@ class Main
/* create monitors for new subject IDs */
for_each_captured_subject([&] (Trace::Subject_id const id,
Trace::Subject_info const &info,
Trace::Subject_info const &,
Xml_node const &policy) {
try {
Monitor &monitor = old_monitors.find_by_subject_id(id);
@ -127,7 +136,7 @@ class Main
catch (Monitor_tree::No_match) {
/* create monitor for subject in the new tree */
_new_monitor(new_monitors, id, info, policy);
_new_monitor(new_monitors, id, policy);
}
});
@ -145,63 +154,171 @@ class Main
error("unexpectedly failed to look up monitor for subject ", id.id);
}
});
/* dump information of each monitor in the new tree */
log("");
log("--- Report ", _report_id++, " (", _num_monitors, "/", _num_subjects, " subjects) ---");
new_monitors.for_each([&] (Monitor &monitor) {
monitor.print(Monitor::Level_of_detail { .activity = _activity,
.affinity = _affinity,
.active_only = !_verbose });
});
}
void _destroy_monitor(Monitor_tree &monitors, Monitor &monitor)
{
if (_verbose)
if (_config.verbose)
log("destroy monitor: subject ", monitor.subject_id().id);
try { _trace.free(monitor.subject_id()); }
catch (Trace::Nonexistent_subject) { }
monitors.remove(&monitor);
destroy(_heap, &monitor);
_num_monitors--;
}
void _new_monitor(Monitor_tree &monitors,
Trace::Subject_id const id,
Trace::Subject_info const &info,
Xml_node const &session_policy)
void _new_monitor(Monitor_tree &monitors,
Trace::Subject_id const id,
Xml_node const &session_policy)
{
auto warn_msg = [] (auto reason) {
warning("Cannot activate tracing: ", reason); };
try {
Number_of_bytes const buffer_sz = session_policy.attribute_value("buffer", _default_buf_sz);
Policy_name const policy_name = session_policy.attribute_value("policy", _default_policy_name);
Number_of_bytes const buffer_sz =
session_policy.attribute_value("buffer", _config.default_buf_sz);
Policy_name const policy_name =
session_policy.attribute_value("policy", _config.default_policy_name);
try {
_trace.trace(id.id, _policies.find_by_name(policy_name).id(), buffer_sz);
} catch (Policy_tree::No_match) {
}
catch (Policy_tree::No_match) {
Policy &policy = *new (_heap) Policy(_env, _trace, policy_name);
_policies.insert(policy);
_trace.trace(id.id, policy.id(), buffer_sz);
}
monitors.insert(new (_heap) Monitor(_trace, _env.rm(), id, info));
monitors.insert(new (_heap) Monitor(_trace, _env.rm(), id));
}
catch (Trace::Already_traced ) { warning("Cannot activate tracing: Already_traced" ); return; }
catch (Trace::Source_is_dead ) { warning("Cannot activate tracing: Source_is_dead" ); return; }
catch (Trace::Nonexistent_policy ) { warning("Cannot activate tracing: Nonexistent_policy" ); return; }
catch (Trace::Traced_by_other_session) { warning("Cannot activate tracing: Traced_by_other_session"); return; }
catch (Trace::Nonexistent_subject ) { warning("Cannot activate tracing: Nonexistent_subject" ); return; }
catch (Region_map::Invalid_dataspace ) { warning("Cannot activate tracing: Loading policy failed" ); return; }
catch (Trace::Already_traced ) { warn_msg("Already_traced" ); return; }
catch (Trace::Source_is_dead ) { warn_msg("Source_is_dead" ); return; }
catch (Trace::Nonexistent_policy ) { warn_msg("Nonexistent_policy" ); return; }
catch (Trace::Traced_by_other_session) { warn_msg("Traced_by_other_session"); return; }
catch (Trace::Nonexistent_subject ) { warn_msg("Nonexistent_subject" ); return; }
catch (Region_map::Invalid_dataspace ) { warn_msg("Loading policy failed" ); return; }
}
void _handle_period(Duration)
{
_update_monitors();
_num_monitors++;
if (_verbose)
log("new monitor: subject ", id.id);
Monitor_tree &monitors = _monitors_switch ? _monitors_1 : _monitors_0;
log("\nReport ", _report_id++, "\n");
Monitor::Level_of_detail const detail { .state = _config.verbose,
.active_only = !_config.verbose };
_print_monitors(_heap, monitors, detail);
}
public:
Main(Env &env) : _env(env) { _policies.insert(_default_policy); }
Main(Env &env) : _env(env)
{
_policies.insert(_default_policy);
_update_monitors();
}
};
Main::Config Main::Config::from_xml(Xml_node const &config)
{
return {
.session_ram = config.attribute_value("session_ram",
Number_of_bytes(1024*1024)),
.session_arg_buffer = config.attribute_value("session_arg_buffer",
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),
.default_buf_sz = config.attribute_value("default_buffer",
Number_of_bytes(4*1024)),
.default_policy_name = config.attribute_value("default_policy",
Policy_name("null"))
};
}
void Main::_print_monitors(Allocator &alloc, Monitor_tree const &monitors,
Monitor::Level_of_detail detail)
{
struct Thread : Noncopyable, Interface
{
Monitor const &monitor;
Thread(Monitor const &monitor) : monitor(monitor) { }
};
struct Pd : Noncopyable, Interface
{
Session_label const label;
Registry<Registered<Thread> > threads { };
Pd(Session_label const &label) : label(label) { }
bool recently_active() const
{
bool result = false;
threads.for_each([&] (Thread const &thread) {
if (thread.monitor.recently_active())
result = true; });
return result;
}
};
Registry<Registered<Pd> > pds { };
auto with_pd = [&] (Session_label const &label, auto const &fn)
{
Pd *pd_ptr = nullptr;
pds.for_each([&] (Pd &pd) {
if (!pd_ptr && (pd.label == label))
pd_ptr = &pd; });
if (!pd_ptr)
pd_ptr = new (alloc) Registered<Pd>(pds, label);
fn(*pd_ptr);
};
monitors.for_each([&] (Monitor const &monitor) {
with_pd(monitor.info().session_label(), [&] (Pd &pd) {
new (alloc) Registered<Thread>(pd.threads, monitor); }); });
/* determine formatting */
Monitor::Formatting fmt { };
pds.for_each([&] (Pd const &pd) {
if (!detail.active_only || pd.recently_active())
pd.threads.for_each([&] (Thread const &thread) {
thread.monitor.apply_formatting(fmt); }); });
pds.for_each([&] (Pd const &pd) {
unsigned const state_width = detail.state ? fmt.state + 1 : 0;
unsigned const table_width = fmt.thread_name
+ fmt.affinity
+ state_width
+ fmt.total_cpu
+ fmt.recent_cpu
+ 26;
unsigned const pd_width = (unsigned)pd.label.length() + 6;
unsigned const excess_width = table_width - min(table_width, pd_width);
if (detail.active_only && !pd.recently_active())
return;
log("PD \"", pd.label, "\" ", Repeated(excess_width, Char('-')));
pd.threads.for_each([&] (Thread const &thread) {
const_cast<Monitor &>(thread.monitor).print(fmt, detail); });
log("");
});
pds.for_each([&] (Registered<Pd> &pd) {
pd.threads.for_each([&] (Registered<Thread> &thread) {
destroy(alloc, &thread); });
destroy(alloc, &pd);
});
}
void Component::construct(Env &env) { static Main main(env); }

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

@ -16,10 +16,53 @@
/* Genode includes */
#include <trace_session/connection.h>
#include <util/formatted_output.h>
using namespace Genode;
/*******************************
** Text-formatting utilities **
*******************************/
struct Formatted_affinity
{
Genode::Affinity::Location affinity;
void print(Genode::Output &out) const
{
Genode::print(out, "at (", affinity.xpos(),",", affinity.ypos(), ")");
}
};
struct Quoted_name
{
Genode::String<100> const name;
void print(Genode::Output &out) const
{
Genode::print(out, "\"", name, "\"");
}
};
template <typename T>
struct Conditional
{
bool const _cond;
T const &_arg;
Conditional(bool cond, T const &arg) : _cond(cond), _arg(arg) { }
void print(Output &out) const
{
if (_cond)
Genode::print(out, _arg);
}
};
/******************
** Monitor_base **
******************/
@ -58,16 +101,13 @@ Monitor &Monitor::find_by_subject_id(Trace::Subject_id const subject_id)
}
Monitor::Monitor(Trace::Connection &trace,
Region_map &rm,
Trace::Subject_id const subject_id,
Trace::Subject_info const &info)
Monitor::Monitor(Trace::Connection &trace,
Region_map &rm,
Trace::Subject_id const subject_id)
:
Monitor_base(trace, rm, subject_id),
_subject_id(subject_id), _buffer(_buffer_raw)
{
update_info(info);
}
{ }
void Monitor::update_info(Trace::Subject_info const &info)
@ -86,36 +126,40 @@ void Monitor::update_info(Trace::Subject_info const &info)
}
void Monitor::print(Level_of_detail detail)
void Monitor::apply_formatting(Formatting &formatting) const
{
auto expand = [] (unsigned &n, auto const &arg)
{
n = max(n, printed_length(arg));
};
typedef Trace::Subject_info Subject_info;
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);
}
void Monitor::print(Formatting fmt, Level_of_detail detail)
{
/* skip output for a subject with no recent activity */
bool const inactive = (_recent_exec_time == 0) && _buffer.empty();
if (detail.active_only && inactive)
if (detail.active_only && !recently_active())
return;
/* print general subject information */
typedef Trace::Subject_info Subject_info;
Subject_info::State const state = _info.state();
log("<subject label=\"", _info.session_label().string(),
"\" thread=\"", _info.thread_name().string(),
"\" id=\"", _subject_id.id,
"\" state=\"", Subject_info::state_name(state),
"\">");
/* print subjects activity if desired */
if (detail.activity)
log(" <activity total=\"", _info.execution_time().thread_context,
"\" recent=\"", _recent_exec_time,
"\">");
/* print subjects affinity if desired */
if (detail.affinity)
log(" <affinity xpos=\"", _info.affinity().xpos(),
"\" ypos=\"", _info.affinity().ypos(),
"\">");
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);
/* print all buffer entries that we haven't yet printed */
bool printed_buf_entries = false;
_buffer.for_each_new_entry([&] (Trace::Buffer::Entry entry) {
/* get readable data length and skip empty entries */
@ -131,21 +175,10 @@ void Monitor::print(Level_of_detail detail)
if (_curr_entry_data[length - 1] == '\n')
_curr_entry_data[length - 1] = '\0';
/* print copied entry data out to log */
if (!printed_buf_entries) {
log(" <buffer>");
printed_buf_entries = true;
}
log(Cstring(_curr_entry_data));
log(" ", Cstring(_curr_entry_data));
return true;
});
/* print end tags */
if (printed_buf_entries)
log(" </buffer>");
else
log(" <buffer/>");
log("</subject>");
}

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

@ -62,14 +62,23 @@ class Monitor : public Monitor_base,
public:
Monitor(Genode::Trace::Connection &trace,
Genode::Region_map &rm,
Genode::Trace::Subject_id subject_id,
Genode::Trace::Subject_info const &info);
struct Formatting
{
unsigned thread_name, affinity, state, total_cpu, recent_cpu;
};
struct Level_of_detail { bool activity, affinity, active_only; };
Monitor(Genode::Trace::Connection &trace,
Genode::Region_map &rm,
Genode::Trace::Subject_id subject_id);
void print(Level_of_detail);
/**
* Expand column formatting according to the monitor's constraints
*/
void apply_formatting(Formatting &) const;
struct Level_of_detail { bool state, active_only; };
void print(Formatting, Level_of_detail);
/**************
@ -89,6 +98,11 @@ class Monitor : public Monitor_base,
Genode::Trace::Subject_info const &info() const { return _info; }
void update_info(Genode::Trace::Subject_info const &);
bool recently_active() const
{
return (_recent_exec_time != 0) || !_buffer.empty();
}
};