MirrorHub/construct
0
0
Fork 0
mirror of https://github.com/matrix-construct/construct synced 2024-06-02 10:08:56 +02:00
Code Issues Releases Wiki Activity

ircd::ios: Profile the latency of handler execution.

Browse source
This commit is contained in:
Jason Volk 2019-09-22 14:43:14 -07:00
parent 2be2d7ca8c
commit a20659b1d8
3 changed files with 58 additions and 27 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

6
include/ircd/ios.h
View file

@ -137,6 +137,8 @@ struct ircd::ios::descriptor::stats
uint64_t free_bytes{0};
uint64_t slice_total {0};
uint64_t slice_last {0};
uint64_t latency_total {0};
uint64_t latency_last {0};
stats &operator+=(const stats &) &;
@ -157,7 +159,7 @@ struct ircd::ios::handler
static bool fault(handler *const &) noexcept;
ios::descriptor *descriptor {nullptr};
uint64_t slice_start {0};
uint64_t ts {0}; // last tsc sample; for profiling each phase
};
template<class function>
@ -191,7 +193,7 @@ namespace ircd::ios
template<class function>
ircd::ios::handle<function>::handle(ios::descriptor &d,
function f)
:handler{&d}
:handler{&d, prof::cycles()}
,f{std::move(f)}
{
assert(d.stats);

34
ircd/ios.cc
View file

@ -155,6 +155,8 @@ ircd::ios::descriptor::stats::operator+=(const stats &o)
free_bytes += o.free_bytes;
slice_total += o.slice_total;
slice_last += o.slice_last;
latency_total += o.latency_total;
latency_last += o.latency_last;
return *this;
}
@ -187,7 +189,7 @@ noexcept
// needs to be tied off here instead.
if(!ret)
{
stats.slice_last = cycles() - handler->slice_start;
stats.slice_last = cycles() - handler->ts;
stats.slice_total += stats.slice_last;
assert(handler::current == handler);
@ -202,21 +204,21 @@ void
ircd::ios::handler::leave(handler *const &handler)
noexcept
{
const auto slice_stop
{
cycles()
};
assert(handler && handler->descriptor);
auto &descriptor(*handler->descriptor);
assert(descriptor.stats);
auto &stats(*descriptor.stats);
const auto slice_stop
{
cycles()
};
// NOTE: will fail without constant_tsc;
// NOTE: may fail without nonstop_tsc after OS suspend mode
assert(slice_stop >= handler->slice_start);
stats.slice_last = slice_stop - handler->slice_start;
assert(slice_stop >= handler->ts);
stats.slice_last = slice_stop - handler->ts;
stats.slice_total += stats.slice_last;
assert(handler::current == handler);
@ -228,16 +230,24 @@ void
ircd::ios::handler::enter(handler *const &handler)
noexcept
{
assert(!handler::current);
assert(handler && handler->descriptor);
auto &descriptor(*handler->descriptor);
assert(descriptor.stats);
auto &stats(*descriptor.stats);
++stats.calls;
++handler::epoch;
assert(!handler::current);
handler::current = handler;
handler->slice_start = cycles();
++handler::epoch;
++stats.calls;
const auto last_ts
{
std::exchange(handler->ts, cycles())
};
stats.latency_last = handler->ts - last_ts;
stats.latency_total += stats.latency_last;
}
[[gnu::hot]]

45
modules/console.cc
View file

@ -1315,14 +1315,16 @@ console_cmd__ios(opt &out, const string_view &line)
{
out << std::left << std::setw(3) << "ID"
<< " " << std::left << std::setw(48) << "NAME"
<< " " << std::right << std::setw(6) << "QUEUED"
<< " " << std::right << std::setw(13) << "LAST LATENCY"
<< " " << std::right << std::setw(13) << "AVG LATENCY"
<< " " << std::right << std::setw(13) << "AVG CYCLES"
<< " " << std::right << std::setw(13) << "LAST CYCLES"
<< " " << std::right << std::setw(10) << "CALLS"
<< " " << std::right << std::setw(15) << "TOTAL CYCLES"
<< " " << std::right << std::setw(15) << "LAST CYCLES"
<< " " << std::right << std::setw(10) << "ALLOCS"
<< " " << std::right << std::setw(10) << "FREES"
<< " " << std::right << std::setw(26) << "ALLOCATED"
<< " " << std::right << std::setw(26) << "FREED"
<< " " << std::right << std::setw(8) << "QUEUED"
<< " " << std::right << std::setw(8) << "FAULTS"
<< std::endl
;
@ -1331,16 +1333,33 @@ console_cmd__ios(opt &out, const string_view &line)
(const auto &s)
{
thread_local char pbuf[64];
out << " " << std::right << std::setw(10) << s.calls
<< " " << std::right << std::setw(15) << s.slice_total
<< " " << std::right << std::setw(15) << s.slice_last
<< " " << std::right << std::setw(10) << s.allocs
<< " " << std::right << std::setw(10) << s.frees
<< " " << std::right << std::setw(26) << pretty(iec(s.alloc_bytes))
<< " " << std::right << std::setw(26) << pretty(iec(s.free_bytes))
<< " " << std::right << std::setw(8) << s.queued
<< " " << std::right << std::setw(8) << s.faults
;
const auto latency_avg
{
s.calls?
(long double)s.latency_total / (long double)s.calls:
0.0L
};
const auto cycles_avg
{
s.calls?
(long double)s.slice_total / (long double)s.calls:
0.0L
};
out
<< " " << std::right << std::setw(6) << s.queued
<< " " << std::right << std::setw(13) << pretty(pbuf, si(ulong(s.latency_last)), 2)
<< " " << std::right << std::setw(13) << pretty(pbuf, si(ulong(latency_avg)), 2)
<< " " << std::right << std::setw(13) << pretty(pbuf, si(ulong(cycles_avg)), 2)
<< " " << std::right << std::setw(13) << pretty(pbuf, si(s.slice_last), 2)
<< " " << std::right << std::setw(10) << s.calls
<< " " << std::right << std::setw(10) << s.allocs
<< " " << std::right << std::setw(10) << s.frees
<< " " << std::right << std::setw(26) << pretty(pbuf, iec(s.alloc_bytes))
<< " " << std::right << std::setw(26) << pretty(pbuf, iec(s.free_bytes))
<< " " << std::right << std::setw(8) << s.faults
;
}};
struct ios::descriptor::stats total;