#791 add profiling for some operations (#1108)

Author: alex-courtis

README.md

@@ -206,7 +206,9 @@ require'nvim-tree'.setup { -- BEGIN_DEFAULT_OPTS
     types = {
       all = false,
       config = false,
+      copy_paste = false,
       git = false,
+      profile = false,
     },
   },
 } -- END_DEFAULT_OPTS

doc/nvim-tree-lua.txt

@@ -173,7 +173,9 @@ function.
         types = {
           all = false,
           config = false,
+          copy_paste = false,
           git = false,
+          profile = false,
         },
       },
     } -- END_DEFAULT_OPTS
@@ -492,6 +494,10 @@ Here is a list of the options available in the setup call:
         type: `boolean`
         default: `false`
 
+    - |log.types.profile|: timing of some operations
+        type: `boolean`
+        default: `false`
+
     - |log.types.config|: options and mappings, at startup
         type: `boolean`
         default: `false`

lua/nvim-tree.lua

@@ -424,7 +424,9 @@ local DEFAULT_OPTS = { -- BEGIN_DEFAULT_OPTS
     types = {
       all = false,
       config = false,
+      copy_paste = false,
       git = false,
+      profile = false,
     },
   },
 } -- END_DEFAULT_OPTS

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

@@ -1,5 +1,6 @@
 local a = vim.api
 
+local log = require "nvim-tree.log"
 local utils = require "nvim-tree.utils"
 local core = require "nvim-tree.core"
 
@@ -28,6 +29,8 @@ function M.fn(name, with_open)
 end
 
 function M.force_dirchange(foldername, with_open)
+  local ps = log.profile_start("change dir %s", foldername)
+
   if M.options.change_cwd and vim.tbl_isempty(vim.v.event) then
     if M.options.global then
       vim.cmd("cd " .. vim.fn.fnameescape(foldername))
@@ -41,6 +44,8 @@ function M.force_dirchange(foldername, with_open)
   else
     require("nvim-tree.renderer").draw()
   end
+
+  log.profile_end(ps, "change dir %s", foldername)
 end
 
 function M.setup(options)

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

@@ -1,3 +1,4 @@
+local log = require "nvim-tree.log"
 local uv = vim.loop
 local view = require "nvim-tree.view"
 local utils = require "nvim-tree.utils"
@@ -16,6 +17,7 @@ function M.fn(fname)
   end
   running[fname] = true
 
+  local ps = log.profile_start("find file %s", fname)
   -- always match against the real path
   local fname_real = uv.fs_realpath(fname)
   if not fname_real then
@@ -68,6 +70,8 @@ function M.fn(fname)
     view.set_cursor { index, 0 }
   end
   running[fname] = false
+
+  log.profile_end(ps, "find file %s", fname)
 end
 
 return M

lua/nvim-tree/git/runner.lua

@@ -128,6 +128,8 @@ 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", opts.project_root)
+
   local self = setmetatable({
     project_root = opts.project_root,
     list_untracked = opts.list_untracked,
@@ -140,6 +142,8 @@ function Runner.run(opts)
   self:_run_git_job()
   self:_wait()
 
+  log.profile_end(ps, "git job %s", opts.project_root)
+
   if self.rc == -1 then
     log.line("git", "job timed out")
   elseif self.rc ~= 0 then

lua/nvim-tree/log.lua

@@ -19,14 +19,26 @@ function M.raw(typ, fmt, ...)
   io.close(file)
 end
 
+--- Write to log file via M.line
+--- START is prefixed
+--- @return reltime to pass to profile_end
+function M.profile_start(fmt, ...)
+  M.line("profile", "START " .. (fmt or "???"), ...)
+  return vim.fn.reltime()
+end
+
+--- Write to log file via M.line
+--- END is prefixed and duration in seconds is suffixed
+--- @param start reltime returned from profile_start
+function M.profile_end(start, fmt, ...)
+  local dur = vim.fn.reltimestr(vim.fn.reltime(start, vim.fn.reltime()))
+  M.line("profile", "END   " .. (fmt or "???") .. "  " .. dur .. "s", ...)
+end
+
 -- Write to log file via M.raw
 -- time and typ are prefixed and a trailing newline is added
 function M.line(typ, fmt, ...)
-  if not M.path or not M.config.types[typ] and not M.config.types.all then
-    return
-  end
-
-  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), ...)
 end
 
 function M.setup(opts)

lua/nvim-tree/renderer/init.lua

@@ -1,3 +1,4 @@
+local log = require "nvim-tree.log"
 local utils = require "nvim-tree.utils"
 local view = require "nvim-tree.view"
 local _padding = require "nvim-tree.renderer.padding"
@@ -238,6 +239,9 @@ function M.draw()
   if not core.get_explorer() or not bufnr or not api.nvim_buf_is_loaded(bufnr) then
     return
   end
+
+  local ps = log.profile_start "draw"
+
   local cursor
   if view.is_visible() then
     cursor = api.nvim_win_get_cursor(view.get_winnr())
@@ -266,6 +270,8 @@ function M.draw()
   if cursor and #lines >= cursor[1] then
     api.nvim_win_set_cursor(view.get_winnr(), cursor)
   end
+
+  log.profile_end(ps, "draw")
 end
 
 function M.render_hl(bufnr)