Add a profiling debug flag to get timings for hooks/shell eval

src/hook_manager.cc

@@ -7,6 +7,8 @@
 #include "face_registry.hh"
 #include "regex.hh"
 
+#include <chrono>
+
 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>() & DebugFlags::Hooks;
+    using Clock = std::chrono::steady_clock;
+    using TimePoint = Clock::time_point;
+
+    const DebugFlags debug_flags = context.options()["debug"].get<DebugFlags>();
+    const bool profile = debug_flags & DebugFlags::Profile;
+    auto start_time = profile ? Clock::now() : TimePoint{};
 
     auto& disabled_hooks = context.options()["disabled_hooks"].get<Regex>();
     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<std::chrono::milliseconds>(end_time - start_time);
+        write_to_debug_buffer(format("hook '{}({})' took {} ms", hook_name, param, (size_t)full.count()));
+    }
 }
 
 }

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<DebugFlags> : std::true_type {};
 
-constexpr Array<EnumDesc<DebugFlags>, 2> enum_desc(DebugFlags)
+constexpr Array<EnumDesc<DebugFlags>, 3> enum_desc(DebugFlags)
 {
     return { {
         { DebugFlags::Hooks, "hooks" },
-        { DebugFlags::Shell, "shell" }
+        { DebugFlags::Shell, "shell" },
+        { DebugFlags::Profile, "profile" }
     } };
 }
 

src/shell_manager.cc

@@ -5,6 +5,8 @@
 #include "event_manager.hh"
 #include "file.hh"
 
+#include <chrono>
+
 #include <cstring>
 #include <sys/types.h>
 #include <sys/wait.h>
@@ -87,9 +89,16 @@ std::pair<String, int> ShellManager::eval(
 {
     static const Regex re(R"(\bkak_(\w+)\b)");
 
-    if (context.options()["debug"].get<DebugFlags>() & DebugFlags::Shell)
+    using Clock = std::chrono::steady_clock;
+    using TimePoint = Clock::time_point;
+
+    const DebugFlags debug_flags = context.options()["debug"].get<DebugFlags>();
+    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<String> kak_env;
     for (RegexIterator<const char*> it{cmdline.begin(), cmdline.end(), re}, end;
          it != end; ++it)
@@ -113,6 +122,8 @@ std::pair<String, int> 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<String, int> 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<String, int> 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<std::chrono::milliseconds>(end_time - start_time);
+        auto spawn = std::chrono::duration_cast<std::chrono::milliseconds>(wait_time - spawn_time);
+        auto wait = std::chrono::duration_cast<std::chrono::milliseconds>(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 };
 }