diff --git a/src/hook_manager.cc b/src/hook_manager.cc index 1dda5043..81a00730 100644 --- a/src/hook_manager.cc +++ b/src/hook_manager.cc @@ -7,6 +7,8 @@ #include "face_registry.hh" #include "regex.hh" +#include + namespace Kakoune { @@ -49,7 +51,12 @@ void HookManager::run_hook(StringView hook_name, if (hook_list_it == m_hook.end()) return; - const bool trace = context.options()["debug"].get() & DebugFlags::Hooks; + using Clock = std::chrono::steady_clock; + using TimePoint = Clock::time_point; + + const DebugFlags debug_flags = context.options()["debug"].get(); + const bool profile = debug_flags & DebugFlags::Profile; + auto start_time = profile ? Clock::now() : TimePoint{}; auto& disabled_hooks = context.options()["disabled_hooks"].get(); bool hook_error = false; @@ -61,7 +68,7 @@ void HookManager::run_hook(StringView hook_name, try { - if (trace) + if (debug_flags & DebugFlags::Hooks) write_to_debug_buffer(format("hook {}/{}", hook_name, hook.key)); hook.value(param, context); @@ -78,6 +85,13 @@ void HookManager::run_hook(StringView hook_name, context.print_status({ format("Error running hooks for '{}' '{}', see *debug* buffer", hook_name, param), get_face("Error") }); + + if (profile) + { + auto end_time = Clock::now(); + auto full = std::chrono::duration_cast(end_time - start_time); + write_to_debug_buffer(format("hook '{}({})' took {} ms", hook_name, param, (size_t)full.count())); + } } } diff --git a/src/option_types.hh b/src/option_types.hh index f95c61f0..5f702f9d 100644 --- a/src/option_types.hh +++ b/src/option_types.hh @@ -198,16 +198,18 @@ enum class DebugFlags None = 0, Hooks = 1 << 0, Shell = 1 << 1, + Profile = 1 << 2, }; template<> struct WithBitOps : std::true_type {}; -constexpr Array, 2> enum_desc(DebugFlags) +constexpr Array, 3> enum_desc(DebugFlags) { return { { { DebugFlags::Hooks, "hooks" }, - { DebugFlags::Shell, "shell" } + { DebugFlags::Shell, "shell" }, + { DebugFlags::Profile, "profile" } } }; } diff --git a/src/shell_manager.cc b/src/shell_manager.cc index f23725a1..861b9a63 100644 --- a/src/shell_manager.cc +++ b/src/shell_manager.cc @@ -5,6 +5,8 @@ #include "event_manager.hh" #include "file.hh" +#include + #include #include #include @@ -87,9 +89,16 @@ std::pair ShellManager::eval( { static const Regex re(R"(\bkak_(\w+)\b)"); - if (context.options()["debug"].get() & DebugFlags::Shell) + using Clock = std::chrono::steady_clock; + using TimePoint = Clock::time_point; + + const DebugFlags debug_flags = context.options()["debug"].get(); + const bool profile = debug_flags & DebugFlags::Profile; + if (debug_flags & DebugFlags::Shell) write_to_debug_buffer(format("shell:\n{}\n----\n", cmdline)); + auto start_time = profile ? Clock::now() : TimePoint{}; + Vector kak_env; for (RegexIterator it{cmdline.begin(), cmdline.end(), re}, end; it != end; ++it) @@ -113,6 +122,8 @@ std::pair ShellManager::eval( } catch (runtime_error&) {} } + auto spawn_time = profile ? Clock::now() : TimePoint{}; + Pipe child_stdin, child_stdout, child_stderr; pid_t pid = spawn_process(cmdline, shell_context.params, kak_env, child_stdin, child_stdout, child_stderr); @@ -124,6 +135,8 @@ std::pair ShellManager::eval( write(child_stdin.write_fd(), input.data(), (int)input.length()); child_stdin.close_write_fd(); + auto wait_time = profile ? Clock::now() : TimePoint{}; + struct PipeReader : FDWatcher { PipeReader(Pipe& pipe, String& contents) @@ -170,6 +183,16 @@ std::pair ShellManager::eval( if (not stderr_contents.empty()) write_to_debug_buffer(format("shell stderr: <<<\n{}>>>", stderr_contents)); + if (profile) + { + TimePoint end_time = Clock::now(); + auto full = std::chrono::duration_cast(end_time - start_time); + auto spawn = std::chrono::duration_cast(wait_time - spawn_time); + auto wait = std::chrono::duration_cast(end_time - wait_time); + write_to_debug_buffer(format("shell execution took {} ms (spawn: {}, wait: {})", + (size_t)full.count(), (size_t)spawn.count(), (size_t)wait.count())); + } + return { stdout_contents, WIFEXITED(status) ? WEXITSTATUS(status) : -1 }; }