Add a ProfileScope helper class to replace most profiling uses

This commit is contained in:
Maxime Coste 2023-08-12 13:06:53 +10:00
parent e605ad8582
commit e090131b87
6 changed files with 60 additions and 43 deletions

View File

@ -8,6 +8,7 @@
#include "file.hh" #include "file.hh"
#include "optional.hh" #include "optional.hh"
#include "option_types.hh" #include "option_types.hh"
#include "profile.hh"
#include "ranges.hh" #include "ranges.hh"
#include "regex.hh" #include "regex.hh"
#include "register_manager.hh" #include "register_manager.hh"
@ -525,12 +526,9 @@ void CommandManager::execute_single_command(CommandParameters params,
if (debug_flags & DebugFlags::Commands) if (debug_flags & DebugFlags::Commands)
write_to_debug_buffer(format("command {}", join(params, ' '))); write_to_debug_buffer(format("command {}", join(params, ' ')));
auto profile = on_scope_end([&, start = (debug_flags & DebugFlags::Profile) ? Clock::now() : Clock::time_point{}] { ProfileScope profile{debug_flags, [&](std::chrono::microseconds duration) {
if (not (debug_flags & DebugFlags::Profile)) write_to_debug_buffer(format("command {} took {} us", params[0], duration.count()));
return; }};
auto full = std::chrono::duration_cast<std::chrono::microseconds>(Clock::now() - start);
write_to_debug_buffer(format("command {} took {} us", params[0], full.count()));
});
command_it->value.func({{params.begin()+1, params.end()}, command_it->value.param_desc}, command_it->value.func({{params.begin()+1, params.end()}, command_it->value.param_desc},
context, shell_context); context, shell_context);

View File

@ -20,6 +20,7 @@
#include "option_manager.hh" #include "option_manager.hh"
#include "option_types.hh" #include "option_types.hh"
#include "parameters_parser.hh" #include "parameters_parser.hh"
#include "profile.hh"
#include "ranges.hh" #include "ranges.hh"
#include "ranked_match.hh" #include "ranked_match.hh"
#include "regex.hh" #include "regex.hh"
@ -1639,9 +1640,9 @@ const CommandDesc source_cmd = {
filename_completer<true>, filename_completer<true>,
[](const ParametersParser& parser, Context& context, const ShellContext&) [](const ParametersParser& parser, Context& context, const ShellContext&)
{ {
const DebugFlags debug_flags = context.options()["debug"].get<DebugFlags>(); ProfileScope profile{context, [&](std::chrono::microseconds duration) {
const bool profile = debug_flags & DebugFlags::Profile; write_to_debug_buffer(format("sourcing '{}' took {} us", parser[0], (size_t)duration.count()));
auto start_time = profile ? Clock::now() : Clock::time_point{}; }};
String path = real_path(parse_filename(parser[0])); String path = real_path(parse_filename(parser[0]));
MappedFile file_content{path}; MappedFile file_content{path};
@ -1656,11 +1657,6 @@ const CommandDesc source_cmd = {
write_to_debug_buffer(format("{}:{}", parser[0], err.what())); write_to_debug_buffer(format("{}:{}", parser[0], err.what()));
throw; throw;
} }
using namespace std::chrono;
if (profile)
write_to_debug_buffer(format("sourcing '{}' took {} us", parser[0],
(size_t)duration_cast<microseconds>(Clock::now() - start_time).count()));
} }
}; };

View File

@ -8,6 +8,7 @@
#include "face_registry.hh" #include "face_registry.hh"
#include "option.hh" #include "option.hh"
#include "option_types.hh" #include "option_types.hh"
#include "profile.hh"
#include "ranges.hh" #include "ranges.hh"
#include "regex.hh" #include "regex.hh"
@ -138,9 +139,9 @@ void HookManager::run_hook(Hook hook, StringView param, Context& context)
m_hooks_trash.clear(); m_hooks_trash.clear();
}); });
const DebugFlags debug_flags = context.options()["debug"].get<DebugFlags>(); ProfileScope profile{context, [&](std::chrono::microseconds duration) {
const bool profile = debug_flags & DebugFlags::Profile; write_to_debug_buffer(format("hook '{}({})' took {} us", hook_name, param, (size_t)duration.count()));
auto start_time = profile ? Clock::now() : TimePoint{}; }};
bool hook_error = false; bool hook_error = false;
for (auto& to_run : hooks_to_run) for (auto& to_run : hooks_to_run)
@ -171,13 +172,6 @@ void HookManager::run_hook(Hook hook, StringView param, Context& context)
context.print_status({ context.print_status({
format("Error running hooks for '{}' '{}', see *debug* buffer", format("Error running hooks for '{}' '{}', see *debug* buffer",
hook_name, param), context.faces()["Error"] }); hook_name, param), context.faces()["Error"] });
if (profile)
{
auto end_time = Clock::now();
auto full = std::chrono::duration_cast<std::chrono::microseconds>(end_time - start_time);
write_to_debug_buffer(format("hook '{}({})' took {} us", hook_name, param, (size_t)full.count()));
}
} }
} }

View File

@ -16,6 +16,7 @@
#include "terminal_ui.hh" #include "terminal_ui.hh"
#include "option_types.hh" #include "option_types.hh"
#include "parameters_parser.hh" #include "parameters_parser.hh"
#include "profile.hh"
#include "ranges.hh" #include "ranges.hh"
#include "regex.hh" #include "regex.hh"
#include "register_manager.hh" #include "register_manager.hh"
@ -806,14 +807,11 @@ int run_server(StringView session, StringView server_init,
write_to_debug_buffer("*** This is the debug buffer, where debug info will be written ***"); write_to_debug_buffer("*** This is the debug buffer, where debug info will be written ***");
#ifdef KAK_DEBUG #ifdef KAK_DEBUG
const auto start_time = Clock::now();
UnitTest::run_all_tests();
if (debug_flags & DebugFlags::Profile)
{ {
using namespace std::chrono; ProfileScope profile{debug_flags, [&](std::chrono::microseconds duration) {
write_to_debug_buffer(format("running the unit tests took {} ms", write_to_debug_buffer(format("running the unit tests took {} ms", duration.count()));
duration_cast<milliseconds>(Clock::now() - start_time).count())); }};
UnitTest::run_all_tests();
} }
#endif #endif

38
src/profile.hh Normal file
View File

@ -0,0 +1,38 @@
#ifndef profile_hh_INCLUDED
#define profile_hh_INCLUDED
#include "option.hh"
#include "clock.hh"
namespace Kakoune
{
template<typename Callback>
class ProfileScope
{
public:
ProfileScope(const DebugFlags debug_flags, Callback&& callback, bool active = true)
: m_active{active and debug_flags & DebugFlags::Profile},
m_start_time(m_active ? Clock::now() : Clock::time_point{}),
m_callback{std::move(callback)}
{}
ProfileScope(const Context& context, Callback&& callback, bool active = true)
: ProfileScope{context.options()["debug"].get<DebugFlags>(), std::move(callback), active}
{}
~ProfileScope()
{
if (m_active)
m_callback(std::chrono::duration_cast<std::chrono::microseconds>(Clock::now() - m_start_time));
}
private:
bool m_active;
Clock::time_point m_start_time;
Callback m_callback;
};
}
#endif // profile_hh_INCLUDED

View File

@ -10,6 +10,7 @@
#include "buffer_utils.hh" #include "buffer_utils.hh"
#include "option.hh" #include "option.hh"
#include "option_types.hh" #include "option_types.hh"
#include "profile.hh"
#include <algorithm> #include <algorithm>
@ -119,10 +120,10 @@ bool Window::needs_redraw(const Context& context) const
const DisplayBuffer& Window::update_display_buffer(const Context& context) const DisplayBuffer& Window::update_display_buffer(const Context& context)
{ {
const bool profile = context.options()["debug"].get<DebugFlags>() & ProfileScope profile{context, [&](std::chrono::microseconds duration) {
DebugFlags::Profile; write_to_debug_buffer(format("window display update for '{}' took {} us",
buffer().display_name(), (size_t)duration.count()));
auto start_time = profile ? Clock::now() : Clock::time_point{}; }, not (buffer().flags() & Buffer::Flags::Debug)};
if (m_display_buffer.timestamp() != -1) if (m_display_buffer.timestamp() != -1)
{ {
@ -168,14 +169,6 @@ const DisplayBuffer& Window::update_display_buffer(const Context& context)
set_position({setup.first_line, setup.first_column}); set_position({setup.first_line, setup.first_column});
m_last_setup = build_setup(context); m_last_setup = build_setup(context);
if (profile and not (buffer().flags() & Buffer::Flags::Debug))
{
using namespace std::chrono;
auto duration = duration_cast<microseconds>(Clock::now() - start_time);
write_to_debug_buffer(format("window display update for '{}' took {} us",
buffer().display_name(), (size_t)duration.count()));
}
return m_display_buffer; return m_display_buffer;
} }