fix(#1961): harden profiling functions (#1986)

lua/nvim-tree/actions/finders/find-file.lua

@@ -28,7 +28,7 @@ function M.fn(fname)
   end
   running[fname_real] = true
 
-  local ps = log.profile_start("find file %s", fname_real)
+  local profile = log.profile_start("find file %s", fname_real)
 
   -- we cannot wait for watchers
   reload.refresh_nodes_for_path(vim.fn.fnamemodify(fname_real, ":h"))
@@ -71,7 +71,7 @@ function M.fn(fname)
 
   running[fname_real] = false
 
-  log.profile_end(ps, "find file %s", fname_real)
+  log.profile_end(profile)
 end
 
 return M

lua/nvim-tree/actions/root/change-dir.lua

@@ -56,9 +56,9 @@ end
 
 local function add_profiling_to(f)
   return function(foldername, should_open_view)
-    local ps = log.profile_start("change dir %s", foldername)
+    local profile = log.profile_start("change dir %s", foldername)
     f(foldername, should_open_view)
-    log.profile_end(ps, "change dir %s", foldername)
+    log.profile_end(profile)
   end
 end
 

lua/nvim-tree/core.lua

@@ -10,8 +10,7 @@ TreeExplorer = nil
 local first_init_done = false
 
 function M.init(foldername)
-  local pn = string.format("core init %s", foldername)
-  local ps = log.profile_start(pn)
+  local profile = log.profile_start("core init %s", foldername)
 
   if TreeExplorer then
     TreeExplorer:destroy()
@@ -21,7 +20,7 @@ function M.init(foldername)
     events._dispatch_ready()
     first_init_done = true
   end
-  log.profile_end(ps, pn)
+  log.profile_end(profile)
 end
 
 function M.get_explorer()

lua/nvim-tree/diagnostics.lua

@@ -90,7 +90,7 @@ function M.update()
     return
   end
   utils.debounce("diagnostics", M.debounce_delay, function()
-    local ps = log.profile_start "diagnostics update"
+    local profile = log.profile_start "diagnostics update"
     log.line("diagnostics", "update")
 
     local buffer_severity
@@ -130,7 +130,7 @@ function M.update()
         end
       end
     end
-    log.profile_end(ps, "diagnostics update")
+    log.profile_end(profile)
   end)
 end
 

lua/nvim-tree/explorer/explore.lua

@@ -26,8 +26,7 @@ local function populate_children(handle, cwd, node, git_status)
 
     local abs = utils.path_join { cwd, name }
 
-    local pn = string.format("explore populate_children %s", abs)
-    local ps = log.profile_start(pn)
+    local profile = log.profile_start("explore populate_children %s", abs)
 
     t = get_type_from(t, abs)
     if
@@ -53,7 +52,7 @@ local function populate_children(handle, cwd, node, git_status)
       end
     end
 
-    log.profile_end(ps, pn)
+    log.profile_end(profile)
   end
 end
 
@@ -64,8 +63,7 @@ function M.explore(node, status)
     return
   end
 
-  local pn = string.format("explore init %s", node.absolute_path)
-  local ps = log.profile_start(pn)
+  local profile = log.profile_start("explore init %s", node.absolute_path)
 
   populate_children(handle, cwd, node, status)
 
@@ -76,14 +74,14 @@ function M.explore(node, status)
     local ns = M.explore(child_folder_only, status)
     node.nodes = ns or {}
 
-    log.profile_end(ps, pn)
+    log.profile_end(profile)
     return ns
   end
 
   sorters.merge_sort(node.nodes, sorters.node_comparator)
   live_filter.apply_filter(node)
 
-  log.profile_end(ps, pn)
+  log.profile_end(profile)
   return node.nodes
 end
 

lua/nvim-tree/explorer/reload.lua

@@ -41,7 +41,7 @@ function M.reload(node, git_status, unloaded_bufnr)
     return
   end
 
-  local ps = log.profile_start("reload %s", node.absolute_path)
+  local profile = log.profile_start("reload %s", node.absolute_path)
 
   local filter_status = filters.prepare(git_status, unloaded_bufnr)
 
@@ -130,13 +130,13 @@ function M.reload(node, git_status, unloaded_bufnr)
     node.group_next = child_folder_only
     local ns = M.reload(child_folder_only, git_status)
     node.nodes = ns or {}
-    log.profile_end(ps, "reload %s", node.absolute_path)
+    log.profile_end(profile)
     return ns
   end
 
   sorters.merge_sort(node.nodes, sorters.node_comparator)
   live_filter.apply_filter(node)
-  log.profile_end(ps, "reload %s", node.absolute_path)
+  log.profile_end(profile)
   return node.nodes
 end
 
@@ -164,8 +164,7 @@ function M.refresh_nodes_for_path(path)
     return
   end
 
-  local pn = string.format("refresh_nodes_for_path %s", path)
-  local ps = log.profile_start(pn)
+  local profile = log.profile_start("refresh_nodes_for_path %s", path)
 
   NodeIterator.builder({ explorer })
     :hidden()
@@ -186,7 +185,7 @@ function M.refresh_nodes_for_path(path)
     end)
     :iterate()
 
-  log.profile_end(ps, pn)
+  log.profile_end(profile)
 end
 
 function M.setup(opts)

lua/nvim-tree/git/runner.lua

@@ -140,7 +140,7 @@ end
 
 -- This module runs a git process, which will be killed if it takes more than timeout which defaults to 400ms
 function Runner.run(opts)
-  local ps = log.profile_start("git job %s %s", opts.project_root, opts.path)
+  local profile = log.profile_start("git job %s %s", opts.project_root, opts.path)
 
   local self = setmetatable({
     project_root = opts.project_root,
@@ -155,7 +155,7 @@ function Runner.run(opts)
   self:_run_git_job()
   self:_wait()
 
-  log.profile_end(ps, "git job %s %s", opts.project_root, opts.path)
+  log.profile_end(profile)
 
   if self.rc == -1 then
     log.line("git", "job timed out  %s %s", opts.project_root, opts.path)

lua/nvim-tree/git/utils.lua

@@ -4,7 +4,7 @@ local log = require "nvim-tree.log"
 local has_cygpath = vim.fn.executable "cygpath" == 1
 
 function M.get_toplevel(cwd)
-  local ps = log.profile_start("git toplevel %s", cwd)
+  local profile = log.profile_start("git toplevel %s", cwd)
 
   local cmd = { "git", "-C", cwd, "rev-parse", "--show-toplevel" }
   log.line("git", "%s", vim.inspect(cmd))
@@ -12,7 +12,7 @@ function M.get_toplevel(cwd)
   local toplevel = vim.fn.system(cmd)
 
   log.raw("git", toplevel)
-  log.profile_end(ps, "git toplevel %s", cwd)
+  log.profile_end(profile)
 
   if vim.v.shell_error ~= 0 or not toplevel or #toplevel == 0 or toplevel:match "fatal" then
     return nil
@@ -41,7 +41,7 @@ function M.should_show_untracked(cwd)
     return untracked[cwd]
   end
 
-  local ps = log.profile_start("git untracked %s", cwd)
+  local profile = log.profile_start("git untracked %s", cwd)
 
   local cmd = { "git", "-C", cwd, "config", "status.showUntrackedFiles" }
   log.line("git", vim.inspect(cmd))
@@ -49,7 +49,7 @@ function M.should_show_untracked(cwd)
   local has_untracked = vim.fn.system(cmd)
 
   log.raw("git", has_untracked)
-  log.profile_end(ps, "git untracked %s", cwd)
+  log.profile_end(profile)
 
   untracked[cwd] = vim.trim(has_untracked) ~= "no"
   return untracked[cwd]

lua/nvim-tree/log.lua

@@ -21,29 +21,32 @@ function M.raw(typ, fmt, ...)
   end
 end
 
+---@class Profile
+---@field start number nanos
+---@field tag string
+
 --- Write profile start to log file
 --- START is prefixed
 --- @param fmt string for string.format
 --- @vararg any arguments for string.format
---- @return number nanos to pass to profile_end
+--- @return Profile to pass to profile_end
 function M.profile_start(fmt, ...)
+  local profile = {}
   if M.enabled "profile" then
-    M.line("profile", "START " .. (fmt or "???"), ...)
-    return vim.loop.hrtime()
-  else
-    return 0
+    profile.start = vim.loop.hrtime()
+    profile.tag = string.format((fmt or "???"), ...)
+    M.line("profile", "START %s", profile.tag)
   end
+  return profile
 end
 
 --- Write profile end to log file
 --- END is prefixed and duration in seconds is suffixed
---- @param start number nanos returned from profile_start
---- @param fmt string for string.format
---- @vararg any arguments for string.format
-function M.profile_end(start, fmt, ...)
-  if M.enabled "profile" then
-    local millis = start and math.modf((vim.loop.hrtime() - start) / 1000000) or -1
-    M.line("profile", "END   " .. (fmt or "???") .. "  " .. millis .. "ms", ...)
+--- @param profile Profile returned from profile_start
+function M.profile_end(profile)
+  if M.enabled "profile" and type(profile) == "table" then
+    local millis = profile.start and math.modf((vim.loop.hrtime() - profile.start) / 1000000) or -1
+    M.line("profile", "END   %s %dms", profile.tag or "", millis)
   end
 end
 
@@ -54,7 +57,7 @@ end
 --- @vararg any arguments for string.format
 function M.line(typ, fmt, ...)
   if M.enabled(typ) then
-    M.raw(typ, string.format("[%s] [%s] %s\n", os.date "%Y-%m-%d %H:%M:%S", typ, fmt), ...)
+    M.raw(typ, string.format("[%s] [%s] %s\n", os.date "%Y-%m-%d %H:%M:%S", typ, (fmt or "???")), ...)
   end
 end
 

lua/nvim-tree/renderer/init.lua

@@ -55,7 +55,7 @@ function M.draw(unloaded_bufnr)
     return
   end
 
-  local ps = log.profile_start "draw"
+  local profile = log.profile_start "draw"
 
   local cursor = vim.api.nvim_win_get_cursor(view.get_winnr())
   icon_component.reset_config()
@@ -100,7 +100,7 @@ function M.draw(unloaded_bufnr)
 
   view.grow_from_content()
 
-  log.profile_end(ps, "draw")
+  log.profile_end(profile)
 end
 
 function M.setup(opts)

lua/nvim-tree/view.lua

@@ -238,8 +238,7 @@ function M.open(options)
     return
   end
 
-  local pn = string.format "view open"
-  local ps = log.profile_start(pn)
+  local profile = log.profile_start "view open"
 
   create_buffer()
   open_window()
@@ -251,7 +250,7 @@ function M.open(options)
   end
   events._dispatch_on_tree_open()
 
-  log.profile_end(ps, pn)
+  log.profile_end(profile)
 end
 
 local function grow()